Jump to content

Cyclic USB power off since one of the latest updates

dl9sec

By dl9sec
in Beginners

 Share

Recommended Posts

dl9sec

dl9sec

Posted
Posted

Hi,

 

I am using Armbian 5.90 on an BananaPi as a RTL-TCP server for an RTL-SDR stick which plugs in the USB port.

Everything work fine since more than a year.

Now since one of the latest updates, the RTL-TCP server doesn't work anymore 24/7.  After a while, I can not connect to the server anymore.

I studied the logs and it seems, that kernel/udev/upowerd powers off the USB-port where the RTL-SDR stick is plugged. The stick reinitializes, but the binding of the stick to the running server gets lost.

 

There seems to be something new to the kernel/system which cyclically drops the USB connection to my stick.

 

Any ideas, how to avoid this "feature"?

 

Thank you in advance.

 

Regards, Thorsten

Link to comment
Share on other sites

Armbian & Khadas are rewarding contributors

Igor

Igor

Posted
Posted
6 minutes ago, dl9sec said:

I studied the logs and it seems

 

Without sharing your logs, nobody is able to study them and give any hints. That's why we ask for at least this: 

armbianmonitor -u

 

8 minutes ago, dl9sec said:

I studied the logs and it seems, that kernel/udev/upowerd


Strange. Is your Bananapi M1 powered with microUSB?

Link to comment
Share on other sites
dl9sec

dl9sec

Posted
  • Author
Posted

Hi Igor,

 

thanks for the quick response.

 

Mean that? http://ix.io/24ZS

 

The relevant syslog part is that: 

:
Dec 20 21:15:47 localhost kernel: [278637.049120] usb 1-1: USB disconnect, device number 10
Dec 20 21:15:47 localhost upowerd[1660]: unhandled action 'unbind' on /sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1/1-1:1.0
Dec 20 21:15:47 localhost upowerd[1660]: unhandled action 'unbind' on /sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1
Dec 20 21:15:47 localhost kernel: [278637.358808] usb 1-1: new high-speed USB device number 11 using ehci-platform
Dec 20 21:15:47 localhost kernel: [278637.526995] usb 1-1: New USB device found, idVendor=0bda, idProduct=2838, bcdDevice= 1.00
Dec 20 21:15:47 localhost kernel: [278637.527010] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Dec 20 21:15:47 localhost kernel: [278637.527016] usb 1-1: Product: RTL2838UHIDIR
Dec 20 21:15:47 localhost kernel: [278637.527022] usb 1-1: Manufacturer: Realtek
Dec 20 21:15:47 localhost kernel: [278637.527028] usb 1-1: SerialNumber: 00000001
:

I don't know, why the kernel disconnects the USB spontaneously.

As already mentioned, the server runs for about one year and there was never a USB disconnect...

 

Regards, Thorsten

Link to comment
Share on other sites
Igor

Igor

Posted
Posted
40 minutes ago, dl9sec said:

As already mentioned, the server runs for about one year and there was never a USB disconnect

 

I noticed that part. mUSB powering at once means we are dealing with a corner case. Even a small change in a power scheme, changed governor or something triggering bigger power consumption caused by u-boot/kernel change can lead to this behavior. I have seen it. First do exclude this problem (powered USB hub).

Link to comment
Share on other sites
dl9sec

dl9sec

Posted
  • Author
Posted

Here again a current syslog since starting the server.

At 12:38 the kernel disconnected USB and then the rtl_tcp server breaks...

  

Dec 21 11:43:38 localhost systemd[1]: Starting RTL-SDR Remote Server...
Dec 21 11:43:53 localhost systemd[1]: Started RTL-SDR Remote Server.
Dec 21 11:43:53 localhost rtl_tcp[17943]: Found 1 device(s):
Dec 21 11:43:53 localhost rtl_tcp[17943]:   0:  Realtek, RTL2838UHIDIR, SN: 00000001
Dec 21 11:43:53 localhost rtl_tcp[17943]: Using device 0: Generic RTL2832U OEM
Dec 21 11:43:53 localhost upowerd[1660]: unhandled action 'bind' on /sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1/1-1:1.0
Dec 21 11:43:54 localhost rtl_tcp[17943]: Found Rafael Micro R820T tuner
Dec 21 11:43:54 localhost rtl_tcp[17943]: [R82XX] PLL not locked!
Dec 21 11:43:54 localhost rtl_tcp[17943]: Tuned to 100000000 Hz.
Dec 21 11:45:01 localhost CRON[17953]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 11:45:01 localhost CRON[17959]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 11:55:01 localhost CRON[18420]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 12:00:01 localhost CRON[18423]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 12:05:01 localhost CRON[18433]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 12:15:01 localhost CRON[18446]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 12:15:01 localhost CRON[18448]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 12:17:01 localhost CRON[18457]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 21 12:23:44 localhost systemd[1339]: Starting Timed resync...
Dec 21 12:23:45 localhost profile-sync-daemon[18469]: #033[01mchromium resync successful#033[00m
Dec 21 12:23:45 localhost systemd[1339]: Started Timed resync.
Dec 21 12:25:01 localhost CRON[18512]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 12:30:01 localhost CRON[18517]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 12:35:01 localhost CRON[18527]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 12:38:51 localhost kernel: [334025.667430] usb 1-1: USB disconnect, device number 11
Dec 21 12:38:51 localhost rtl_tcp[17943]: cb transfer status: 5, canceling...
Dec 21 12:38:51 localhost rtl_tcp[17943]: message repeated 14 times: [ cb transfer status: 5, canceling...]
Dec 21 12:38:51 localhost upowerd[1660]: unhandled action 'unbind' on /sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1/1-1:1.0
Dec 21 12:38:51 localhost upowerd[1660]: unhandled action 'unbind' on /sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1
Dec 21 12:38:56 localhost rtl_tcp[17943]: Signal caught, exiting!
Dec 21 12:38:57 localhost rtl_tcp[17943]: Signal caught, exiting!
Dec 21 12:45:01 localhost CRON[18544]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 12:45:01 localhost CRON[18545]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 12:47:07 localhost kernel: [334521.748478] usb 1-1: new high-speed USB device number 12 using ehci-platform
Dec 21 12:47:07 localhost kernel: [334521.918542] usb 1-1: New USB device found, idVendor=0bda, idProduct=2838, bcdDevice= 1.00
Dec 21 12:47:07 localhost kernel: [334521.918610] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Dec 21 12:47:07 localhost kernel: [334521.918651] usb 1-1: Product: RTL2838UHIDIR
Dec 21 12:47:07 localhost kernel: [334521.918692] usb 1-1: Manufacturer: Realtek
Dec 21 12:47:07 localhost kernel: [334521.918729] usb 1-1: SerialNumber: 00000001
Dec 21 12:47:07 localhost mtp-probe: checking bus 1, device 12: "/sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1"
Dec 21 12:47:07 localhost mtp-probe: bus: 1, device: 12 was not an MTP device
Dec 21 12:47:08 localhost upowerd[1660]: unhandled action 'bind' on /sys/devices/platform/soc@1c00000/1c14000.usb/usb1/1-1

 

Link to comment
Share on other sites
dl9sec

dl9sec

Posted
  • Author
Posted
24 minutes ago, Igor said:

Also recommended: 

 

Thanks for that hint.

 

Gave it a try but got a warning message:


  

Test install failed. Can't change firmware

Check /tmpswitch_kernel.log

which says:

  

linux-image-current-sunxi=19.11.3 linux-dtb-current-sunxi=19.11.3 linux-u-boot-bananapi-current

Will a reboot brick my installation?

Link to comment
Share on other sites
dl9sec

dl9sec

Posted
  • Author
Posted

Unfortunately after 3 hours the kernel disonnected the USB again: 

Dec 21 13:37:01 localhost blueman-mechanism: loading Ppp
Dec 21 13:37:01 localhost blueman-mechanism: loading Rfcomm
Dec 21 13:37:01 localhost blueman-mechanism: loading RfKill
Dec 21 13:37:02 localhost dbus-daemon[1379]: [session uid=1000 pid=1379] Activating via systemd: service name='org.gnome.Terminal' unit='gnome-terminal-server.service' requested by ':1.41' (uid=1000 pid=1959 comm="/usr/bin/gnome-terminal.real ")
Dec 21 13:37:02 localhost systemd[1344]: Starting GNOME Terminal Server...
Dec 21 13:37:04 localhost dbus-daemon[1379]: [session uid=1000 pid=1379] Successfully activated service 'org.gnome.Terminal'
Dec 21 13:37:04 localhost systemd[1344]: Started GNOME Terminal Server.
Dec 21 13:37:31 localhost blueman-mechanism: Exiting
Dec 21 13:45:01 localhost CRON[1989]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 13:45:01 localhost CRON[1990]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 13:50:57 localhost systemd[1]: Starting Cleanup of Temporary Directories...
Dec 21 13:50:57 localhost systemd[1]: Started Cleanup of Temporary Directories.
Dec 21 13:55:01 localhost CRON[2007]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 14:00:01 localhost CRON[2013]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 14:05:01 localhost CRON[2022]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 14:15:01 localhost CRON[2030]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 14:15:01 localhost CRON[2031]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 14:17:01 localhost CRON[2040]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 21 14:25:01 localhost CRON[2051]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 14:30:01 localhost CRON[2057]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 14:35:01 localhost CRON[2066]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 14:36:57 localhost systemd[1344]: Starting Timed resync...
Dec 21 14:36:58 localhost profile-sync-daemon[2069]: #033[01mchromium resync successful#033[00m
Dec 21 14:36:59 localhost systemd[1344]: Started Timed resync.
Dec 21 14:45:01 localhost CRON[2119]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 14:45:01 localhost CRON[2120]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 14:55:01 localhost CRON[2134]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 15:00:01 localhost CRON[2139]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 15:05:01 localhost CRON[2148]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 15:15:01 localhost CRON[2156]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 15:15:01 localhost CRON[2157]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 15:17:01 localhost CRON[2167]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 21 15:25:01 localhost CRON[2177]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 15:30:01 localhost CRON[2182]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 15:35:01 localhost CRON[2191]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 15:37:57 localhost systemd[1344]: Starting Timed resync...
Dec 21 15:37:57 localhost profile-sync-daemon[2195]: #033[01mchromium resync successful#033[00m
Dec 21 15:37:57 localhost systemd[1344]: Started Timed resync.
Dec 21 15:43:57 localhost systemd[1]: Starting Message of the Day...
Dec 21 15:43:57 localhost systemd[1]: Started Message of the Day.
Dec 21 15:45:01 localhost CRON[2243]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 15:45:01 localhost CRON[2244]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 15:55:01 localhost CRON[2257]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 16:00:01 localhost CRON[2262]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 16:05:01 localhost CRON[2271]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 16:15:01 localhost CRON[2279]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 16:15:01 localhost CRON[2280]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 16:17:01 localhost CRON[2290]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 21 16:21:42 localhost kernel: [ 9950.759541] usb 1-1: USB disconnect, device number 2
Dec 21 16:21:42 localhost rtl_tcp[1731]: cb transfer status: 5, canceling...
Dec 21 16:21:42 localhost rtl_tcp[1731]: message repeated 14 times: [ cb transfer status: 5, canceling...]
Dec 21 16:21:42 localhost upowerd[1677]: unhandled action 'unbind' on /sys/devices/platform/soc/1c14000.usb/usb1/1-1/1-1:1.0
Dec 21 16:21:42 localhost upowerd[1677]: unhandled action 'unbind' on /sys/devices/platform/soc/1c14000.usb/usb1/1-1
Dec 21 16:21:47 localhost rtl_tcp[1731]: Signal caught, exiting!
Dec 21 16:21:47 localhost rtl_tcp[1731]: Signal caught, exiting!
Dec 21 16:25:01 localhost CRON[2312]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 21 16:30:01 localhost CRON[2318]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 21 16:35:01 localhost CRON[2327]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)

 

Link to comment
Share on other sites
dl9sec

dl9sec

Posted
  • Author
Posted

An external powered USB hub didn't solve the problem. Same problem.

The kernel disconnects the USB spontaneously and i don't know why (if there is some EMI, the EMI was there before, so why are the newer kernel so "sensitive"?)...

  

:
Dec 28 18:06:36 localhost systemd[1]: Starting RTL-SDR Remote Server...
Dec 28 18:06:51 localhost systemd[1]: Started RTL-SDR Remote Server.
Dec 28 18:06:51 localhost rtl_tcp[18303]: Found 1 device(s):
Dec 28 18:06:51 localhost rtl_tcp[18303]:   0:  Realtek, RTL2838UHIDIR, SN: 00000001
Dec 28 18:06:51 localhost rtl_tcp[18303]: Using device 0: Generic RTL2832U OEM
Dec 28 18:06:51 localhost upowerd[1709]: unhandled action 'bind' on /sys/devices/platform/soc/1c1c000.usb/usb2/2-1/2-1.2/2-1.2:1.0
Dec 28 18:06:51 localhost rtl_tcp[18303]: Found Rafael Micro R820T tuner
Dec 28 18:06:52 localhost rtl_tcp[18303]: [R82XX] PLL not locked!
Dec 28 18:06:52 localhost rtl_tcp[18303]: Tuned to 100000000 Hz.
Dec 28 18:07:15 localhost systemd[1361]: Starting Timed resync...
Dec 28 18:07:15 localhost profile-sync-daemon[18309]: #033[01mchromium resync successful#033[00m
Dec 28 18:07:15 localhost systemd[1361]: Started Timed resync.
Dec 28 18:15:01 localhost CRON[18359]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 28 18:15:01 localhost CRON[18360]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 28 18:17:01 localhost CRON[18368]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 28 18:25:01 localhost CRON[18381]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 28 18:30:01 localhost CRON[18386]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 28 18:35:01 localhost CRON[18396]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 28 18:45:01 localhost CRON[18404]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 28 18:45:01 localhost CRON[18405]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 28 18:55:02 localhost CRON[18417]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 28 19:00:01 localhost CRON[18421]: (root) CMD (/usr/lib/armbian/armbian-truncate-logs)
Dec 28 19:04:48 localhost rtl_tcp[18303]: cb transfer status: 1, canceling...
Dec 28 19:04:48 localhost kernel: [431708.199290] usb 2-1.2: USB disconnect, device number 16
Dec 28 19:04:48 localhost upowerd[1709]: unhandled action 'unbind' on /sys/devices/platform/soc/1c1c000.usb/usb2/2-1/2-1.2/2-1.2:1.0
Dec 28 19:04:48 localhost upowerd[1709]: unhandled action 'unbind' on /sys/devices/platform/soc/1c1c000.usb/usb2/2-1/2-1.2
Dec 28 19:04:49 localhost kernel: [431708.522435] usb 2-1.2: new high-speed USB device number 17 using ehci-platform
Dec 28 19:04:49 localhost kernel: [431708.747052] usb 2-1.2: New USB device found, idVendor=0bda, idProduct=2838, bcdDevice= 1.00
Dec 28 19:04:49 localhost kernel: [431708.747069] usb 2-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Dec 28 19:04:49 localhost kernel: [431708.747076] usb 2-1.2: Product: RTL2838UHIDIR
Dec 28 19:04:49 localhost kernel: [431708.747082] usb 2-1.2: Manufacturer: Realtek
Dec 28 19:04:49 localhost kernel: [431708.747091] usb 2-1.2: SerialNumber: 00000001
Dec 28 19:04:49 localhost mtp-probe: checking bus 2, device 17: "/sys/devices/platform/soc/1c1c000.usb/usb2/2-1/2-1.2"
Dec 28 19:04:49 localhost mtp-probe: bus: 2, device: 17 was not an MTP device
Dec 28 19:04:49 localhost upowerd[1709]: unhandled action 'bind' on /sys/devices/platform/soc/1c1c000.usb/usb2/2-1/2-1.2
Dec 28 19:04:53 localhost rtl_tcp[18303]: Signal caught, exiting!
Dec 28 19:04:54 localhost rtl_tcp[18303]: Signal caught, exiting!
Dec 28 19:05:01 localhost CRON[18453]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Dec 28 19:08:14 localhost systemd[1361]: Starting Timed resync...
Dec 28 19:08:15 localhost profile-sync-daemon[18456]: #033[01mchromium resync successful#033[00m
Dec 28 19:08:15 localhost systemd[1361]: Started Timed resync.
:

 

Regards, Thorsten

Link to comment
Share on other sites
Igor

Igor

Posted
Posted
12 minutes ago, dl9sec said:

The kernel disconnects the USB spontaneously and i don't know why


Huh, from the quick look, me neither. I have some ideas where to look ... when possible.

Link to comment
Share on other sites
dl9sec

dl9sec

Posted
  • Author
Posted

The 20cm long USB plug to jack adapter i used seems to cause the problem. After replacing it with a new cable, the interruptions has gone. So no software/kernel problem it seems :-)

 

Thanks for your attention and the efforts with Armbian.

 

Regards, Thorsten

(and a Happy New Year by the way :-) )

1
Link to comment
Share on other sites
Guest
This topic is now closed to further replies.
 Share
Go to topic listing
×
×
  • Create New...

Important Information

Terms of Use - Privacy Policy - Guidelines

  I accept