Linux: USB-modem + USB-webcam on RPi3 causes kernel oops
I have ten Raspberry Pi 3's (Model B Rev 1.2) with a USB 4G-modem and a USB webcam plugged in. And I managed to get a log which is similar to what @l-spitz describes at #1272 (but I have not been able to reproduce the issue with the dwc_otg buspower toggle) - see down below.
It should also be mentioned that we have ten additional Raspberry Pi 3's with an identical setup and hardware, except that these ten have no USB webcam, but instead use the RPi camera module. These ten work fine, stable for at least months.
When the webcam is used every 5 minutes using crontab, the problem occurs every 24~48 hours. A kernel oops shows up, and after half an hour of no 4G connection the system is rebooted by an external watchdog that checks if the RPi is still functional (without this, presumably the RPi would stay 'frozen' or off). There is definitively no power supply issue, especially since we've recently tested using an externally powered USB-hub which still does not solve the problem.
Interestingly, the problem only occurs when both the webcam and modem are plugged in (and used). I have another ten RPi's that have been up and running for about a year now 24/7, using the exact same modem and power supply etc, but without the webcam, and those RPi's have never had any problems.
Unfortunately I haven't been able to reproduce the problem, it seems to have the properties of a race condition of some sorts. Using the webcam every 5 minutes instead of every hour gives a higher probability of the problem showing up. However, any script where I have tried to force the problem with a shorter interval did not increase the frequency of the problem. I have also tried stressing the RPi with high CPU and other things, but to no avail. Additionally, when the webcam is plugged in but it is not used, the problem does not occur.
Since at first I thought the problem was only related to the webcam, I have tried several uvcvideo modprobe options such as quirks mode and nodrop and several other combinations. These did not have an effect on the problem.
Some more information on the RPi's (Raspbian GNU/Linux 8):
> uname -a
Linux rpi 4.9.35-v7+ #1014 SMP Fri Jun 30 14:47:43 BST 2017 armv7l GNU/Linux
> lsusb
Bus 001 Device 111: ID 05a3:9422 ARC International
Bus 001 Device 110: ID 12d1:14dc Huawei Technologies Co., Ltd.
Bus 001 Device 109: ID 1a40:0101 Terminus Technology Inc. 4-Port HUB
Bus 001 Device 108: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 107: ID 0424:9514 Standard Microsystems Corp.
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Additionally, in february I have fully updated/upgraded the system, but the problem persisted. Therefore, it does not seem to be related to a bug that occurs in only a specific kernel version. This problem spans about a year of updates.
Here are the kernel logs I managed to extract from one of the RPi's (I don't have too many logs, since I have been using tmpfs on /var/log to reduce SD-card corruption):
[568461.998997] uvcvideo: Non-zero status (-5) in status completion handler.
[569970.962252] uvcvideo: Non-zero status (-5) in status completion handler.
[571877.689924] uvcvideo: Failed to resubmit video URB (-1).
[573977.726977] uvcvideo: Failed to resubmit video URB (-1).
[574877.998712] uvcvideo: Failed to resubmit video URB (-1).
[575778.459269] uvcvideo: Failed to resubmit video URB (-1).
[576082.931273] uvcvideo: Failed to resubmit video URB (-1).
[576082.935186] uvcvideo: Failed to resubmit video URB (-1).
[578671.852022] uvcvideo: Non-zero status (-5) in status completion handler.
[579716.748041] uvcvideo: Failed to resubmit video URB (-1).
[584777.153730] uvcvideo: Failed to resubmit video URB (-1).
[586578.011536] uvcvideo: Failed to resubmit video URB (-1).
[595277.433798] Unable to handle kernel NULL pointer dereference at virtual address 00000104
[595277.440310] pgd = b4c50000
[595277.444031] [00000104] *pgd=00000000
[595277.447739] Internal error: Oops: 805 [#1] SMP ARM
[595277.451799] Modules linked in: cdc_ether sr_mod cdrom hci_uart btbcm bluetooth brcmfmac brcmutil cfg80211 rfkill sg evdev snd_bcm2835 bcm2835_gpiomem i2c_bcm2835 uvcvideo snd_usb_audio snd_hwdep snd_usbmidi_lib videobuf2_vmalloc snd_rawmidi videobuf2_memops snd_seq_device videobuf2_v4l2 snd_pcm videobuf2_core snd_timer videodev snd media uio_pdrv_genirq fixed uio i2c_dev fuse ipv6
[595277.471881] CPU: 0 PID: 147 Comm: systemd-journal Not tainted 4.9.24-v7+ #993
[595277.480474] Hardware name: BCM2835
[595277.484650] task: b4d53b00 task.stack: b4d32000
[595277.488994] PC is at uvc_queue_next_buffer+0x7c/0xf0 [uvcvideo]
[595277.493456] LR is at 0x100
[595277.498072] pc : [<7f1e33dc>] lr : [<00000100>] psr: 60000193
[595277.498072] sp : b4d33aa8 ip : 00000100 fp : b4d33ac4
[595277.506335] r10: ad446400 r9 : b4f48398 r8 : 00000010
[595277.508553] r7 : b6956400 r6 : b4f484e8 r5 : b4f48398 r4 : b30c2600
[595277.510877] r3 : b4f48398 r2 : 00000200 r1 : 00000000 r0 : 60000193
[595277.513259] Flags: nZCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment user
[595277.517812] Control: 10c5383d Table: 34c5006a DAC: 00000055
[595277.520057] Process systemd-journal (pid: 147, stack limit = 0xb4d32210)
[595277.522425] Stack: (0xb4d33aa8 to 0xb4d34000)
[595277.524678] 3aa0: 00000001 b30c2600 b4f48000 ad446500 b4d33afc b4d33ac8
[595277.529189] 3ac0: 7f1e6ab4 7f1e336c 7f1f06c0 b30c2600 00000000 b30c2600 ad446400 b4f48000
[595277.533654] 3ae0: b4f484e8 80b79340 00000000 00000001 b4d33b1c b4d33b00 7f1e56b8 7f1e69a8
[595277.538091] 3b00: ad446400 60000113 00000000 00000000 b4d33b3c b4d33b20 80556fe8 7f1e5640
[595277.543118] 3b20: 97af5d80 ad446400 ad446400 00000000 b4d33b5c b4d33b40 80557114 80556f74
[595277.548000] 3b40: b638ea74 97af5d80 b59d0400 ad446400 b4d33b84 b4d33b60 80581084 805570d4
[595277.552983] 3b60: b4d33ba4 20000113 804eb324 b59a4ac0 b59a4ac4 00000000 b4d33b94 b4d33b88
[595277.557836] 3b80: 8058fe40 80581024 b4d33bbc b4d33b98 80123070 8058fe2c 80122ffc 80c02080
[595277.562546] 3ba0: 00000000 b4d32000 00000100 b5805180 b4d33c24 b4d33bc0 8010169c 80123008
[595277.567385] 3bc0: 8017400c 80177754 00000001 00400100 80c02d00 038bdb6b 0000000a 80c7a980
[595277.572177] 3be0: 80c71e38 80c0312c 80b793b8 80c02080 b4d33bc0 00000001 80172ecc 80b7cec0
[595277.577441] 3c00: 00000000 00000000 00000001 b5805180 b4d32000 024200ca b4d33c34 b4d33c28
[595277.582579] 3c20: 80122c04 8010151c b4d33c5c b4d33c38 80173510 80122b04 b4d33c78 80c04670
[595277.587644] 3c40: a0000113 ffffffff b4d33cac 80c043a8 b4d33c74 b4d33c60 8010150c 801734ac
[595277.592777] 3c60: 80c040a4 80213a28 b4d33d5c b4d33c78 8071893c 80101470 024200ca 00000000
[595277.598093] 3c80: 00000081 b4d33dd8 80c6f440 00400000 00000000 00000081 80c043a8 00000000
[595277.603457] 3ca0: 024200ca b4d33d5c b4d33d60 b4d33cc8 80214cec 80213a28 a0000113 ffffffff
[595277.608896] 3cc0: 80214048 7f000000 804eb324 80452f2c b583ef00 80c1ed4a 00000001 ffffffff
[595277.614229] 3ce0: 00000058 80c0312c 00000001 00000001 024200ca 00000000 b5ffca4c 3547b000
[595277.619511] 3d00: 80b81a3c b5ffca3c 80c6f040 00000001 00000000 20000113 b5ffca50 00000000
[595277.625045] 3d20: ffffffe1 00000081 b4d33dd8 80c6f440 b583ef00 80c6f440 00400000 00000000
[595277.630557] 3d40: 00000081 80c043a8 00000000 024200ca b4d33e3c b4d33d60 80214cec 80213a1c
[595277.635747] 3d60: b5ff7bc8 00000000 0000000e 8056d00c b4d33d9c b59a2480 60000193 b4e55300
[595277.640989] 3d80: b59d0400 b59a48c0 60000193 8056d7a8 b4d33dd4 b4d33da0 8056d7a8 8058fdac
[595277.646494] 3da0: 00000001 000000c0 b4d33dcc b59a2480 00000000 80269d6c 80c5c8e8 b79e0410
[595277.652020] 3dc0: b4e55328 80269e54 16d08a0d 024200ca b5882000 b634ef58 80c6f440 00000000
[595277.657192] 3de0: 80c6f440 00000001 00000001 00000000 80269e58 801e30cc b5882000 b4d33e58
[595277.662104] 3e00: 00000040 8024aff4 b4d33e3c b4d33e18 8024aff4 9eb6f738 00000000 9eb6f738
[595277.667006] 3e20: 00000040 00000000 76084000 00000055 b4d33ea4 b4d33e40 802420cc 80214c08
[595277.671907] 3e40: 00000000 8058fdfc 80585d44 abd4d20c b583ef00 0000003e b5882000 9eb6f738
[595277.676809] 3e60: 76084000 00000055 b4c51d80 00000000 00000000 00000000 b4d33ea4 b4d33fb0
[595277.681711] 3e80: b4d53b00 00000817 76084000 b53da700 b53da738 00000055 b4d33efc b4d33ea8
[595277.686612] 3ea0: 807193f4 80241580 b583ef00 80173fa0 00000000 00000001 b583ef00 00000000
[595277.691513] 3ec0: 00000001 00000000 00000800 00000000 b4d33efc 80c093f4 00000817 807190b8
[595277.696414] 3ee0: 76084000 b4d33fb0 7ee04c68 ffffffff b4d33fac b4d33f00 801011e8 807190c4
[595277.701313] 3f00: 80b793b8 b583ef00 b583ef00 b583ef10 b4d33f34 b4d33f20 80177754 8047db30
[595277.706212] 3f20: 80c04640 00000000 b4d33f44 b4d33f38 80172ecc 8047d9ec b4d33f5c b4d33f48
[595277.711110] 3f40: 8047d9ec 80122ba0 80b7cec0 00000000 b4d33f6c b4d33f60 80122ba0 801800ec
[595277.716010] 3f60: b4d33f94 b4d33f70 80173510 80122b04 b4d33fb0 80c04670 20000010 ffffffff
[595277.720911] 3f80: 10c5383d 76f910dc 20000010 76f910dc 20000010 ffffffff 10c5383d 10c5387d
[595277.725814] 3fa0: 00000000 b4d33fb0 80718c24 801011ac 76084000 00000000 0006fff8 00000000
[595277.730718] 3fc0: 56768598 7ee04da0 00000000 76e1188c 7ee04c68 7ee04c68 ffffffff 7ee04da0
[595277.735620] 3fe0: 00000000 7ee04c00 00000000 76f910dc 20000010 ffffffff 367fa861 367fac61
[595277.740580] [<7f1e33dc>] (uvc_queue_next_buffer [uvcvideo]) from [<7f1e6ab4>] (uvc_video_decode_isoc+0x118/0x198 [uvcvideo])
[595277.745560] [<7f1e6ab4>] (uvc_video_decode_isoc [uvcvideo]) from [<7f1e56b8>] (uvc_video_complete+0x84/0xec [uvcvideo])
[595277.750533] [<7f1e56b8>] (uvc_video_complete [uvcvideo]) from [<80556fe8>] (__usb_hcd_giveback_urb+0x80/0x160)
[595277.755485] [<80556fe8>] (__usb_hcd_giveback_urb) from [<80557114>] (usb_hcd_giveback_urb+0x4c/0xfc)
[595277.760431] [<80557114>] (usb_hcd_giveback_urb) from [<80581084>] (completion_tasklet_func+0x6c/0x98)
[595277.765386] [<80581084>] (completion_tasklet_func) from [<8058fe40>] (tasklet_callback+0x20/0x24)
[595277.770346] [<8058fe40>] (tasklet_callback) from [<80123070>] (tasklet_hi_action+0x74/0x10c)
[595277.775307] [<80123070>] (tasklet_hi_action) from [<8010169c>] (__do_softirq+0x18c/0x3cc)
[595277.780271] [<8010169c>] (__do_softirq) from [<80122c04>] (irq_exit+0x10c/0x168)
[595277.785232] [<80122c04>] (irq_exit) from [<80173510>] (__handle_domain_irq+0x70/0xc4)
[595277.790206] [<80173510>] (__handle_domain_irq) from [<8010150c>] (bcm2836_arm_irqchip_handle_irq+0xa8/0xac)
[595277.795210] [<8010150c>] (bcm2836_arm_irqchip_handle_irq) from [<8071893c>] (__irq_svc+0x5c/0x7c)
[595277.800203] Exception stack(0xb4d33c78 to 0xb4d33cc0)
[595277.802690] 3c60: 024200ca 00000000
[595277.807526] 3c80: 00000081 b4d33dd8 80c6f440 00400000 00000000 00000081 80c043a8 00000000
[595277.812308] 3ca0: 024200ca b4d33d5c b4d33d60 b4d33cc8 80214cec 80213a28 a0000113 ffffffff
[595277.817090] [<8071893c>] (__irq_svc) from [<80213a28>] (get_page_from_freelist+0x18/0xb0c)
[595277.821870] [<80213a28>] (get_page_from_freelist) from [<80214cec>] (__alloc_pages_nodemask+0xf0/0xdd0)
[595277.826664] [<80214cec>] (__alloc_pages_nodemask) from [<802420cc>] (handle_mm_fault+0xb58/0xde4)
[595277.831448] [<802420cc>] (handle_mm_fault) from [<807193f4>] (do_page_fault+0x33c/0x3b0)
[595277.836222] [<807193f4>] (do_page_fault) from [<801011e8>] (do_DataAbort+0x48/0xc4)
[595277.840989] [<801011e8>] (do_DataAbort) from [<80718c24>] (__dabt_usr+0x44/0x60)
[595277.845748] Exception stack(0xb4d33fb0 to 0xb4d33ff8)
[595277.848126] 3fa0: 76084000 00000000 0006fff8 00000000
[595277.852790] 3fc0: 56768598 7ee04da0 00000000 76e1188c 7ee04c68 7ee04c68 ffffffff 7ee04da0
[595277.857412] 3fe0: 00000000 7ee04c00 00000000 76f910dc 20000010 ffffffff
[595277.859753] Code: e594215c e594c158 e1a03005 e3a0ec01 (e58c2004)
[595298.444164] INFO: rcu_sched detected stalls on CPUs/tasks:
[595298.446141] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=1028
[595298.450017] (detected by 0, t=2102 jiffies, g=24633640, c=24633639, q=2669)
[595298.452050] Task dump for CPU 3:
[595298.454014] avconv R running task 0 7121 1 0x00000003
[595298.456036] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
[595361.493307] INFO: rcu_sched detected stalls on CPUs/tasks:
[595361.495339] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=4177
[595361.499401] (detected by 0, t=8407 jiffies, g=24633640, c=24633639, q=4904)
[595361.501486] Task dump for CPU 3:
[595361.503505] avconv R running task 0 7121 1 0x00000003
[595361.505644] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
[595424.542469] INFO: rcu_sched detected stalls on CPUs/tasks:
[595424.544614] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=7326
[595424.548907] (detected by 0, t=14712 jiffies, g=24633640, c=24633639, q=7114)
[595424.553205] Task dump for CPU 3:
[595424.555364] avconv R running task 0 7121 1 0x00000003
[595424.557604] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
[595478.601843] INFO: task systemd-journal:147 blocked for more than 120 seconds.
[595478.606190] Not tainted 4.9.24-v7+ #993
[595478.608334] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[595478.612668] systemd-journal D 0 147 1 0x00000001
[595478.614853] [<80713980>] (__schedule) from [<80713ea4>] (schedule+0x50/0xa8)
[595478.617050] [<80713ea4>] (schedule) from [<80714298>] (schedule_preempt_disabled+0x18/0x1c)
[595478.621370] [<80714298>] (schedule_preempt_disabled) from [<807159b4>] (__mutex_lock_slowpath+0xac/0x164)
[595478.625729] [<807159b4>] (__mutex_lock_slowpath) from [<80715acc>] (mutex_lock+0x60/0x64)
[595478.630111] [<80715acc>] (mutex_lock) from [<805d9138>] (rpi_firmware_transaction+0x44/0xac)
[595478.634549] [<805d9138>] (rpi_firmware_transaction) from [<805d9298>] (rpi_firmware_property_list+0xf8/0x220)
[595478.639028] [<805d9298>] (rpi_firmware_property_list) from [<805d9424>] (rpi_firmware_property+0x64/0x84)
[595478.643559] [<805d9424>] (rpi_firmware_property) from [<804a2110>] (bcm2708_fb_blank+0x50/0x9c)
[595478.648156] [<804a2110>] (bcm2708_fb_blank) from [<80498650>] (fb_blank+0x64/0xb8)
[595478.652762] [<80498650>] (fb_blank) from [<8049207c>] (fbcon_blank+0x1ec/0x2b8)
[595478.657403] [<8049207c>] (fbcon_blank) from [<804d53f0>] (do_unblank_screen+0xbc/0x1c4)
[595478.662167] [<804d53f0>] (do_unblank_screen) from [<804d5514>] (unblank_screen+0x1c/0x20)
[595478.666940] [<804d5514>] (unblank_screen) from [<80462ffc>] (bust_spinlocks+0x30/0x58)
[595478.671725] [<80462ffc>] (bust_spinlocks) from [<8010c18c>] (die+0x130/0x440)
[595478.676601] [<8010c18c>] (die) from [<80118e74>] (__do_kernel_fault.part.0+0x74/0x1f4)
[595478.681517] [<80118e74>] (__do_kernel_fault.part.0) from [<80719300>] (do_page_fault+0x248/0x3b0)
[595478.686521] [<80719300>] (do_page_fault) from [<80719524>] (do_translation_fault+0xbc/0xc0)
[595478.691532] [<80719524>] (do_translation_fault) from [<801011e8>] (do_DataAbort+0x48/0xc4)
[595478.696549] [<801011e8>] (do_DataAbort) from [<807188b4>] (__dabt_svc+0x54/0x80)
[595478.701543] Exception stack(0xb4d33a58 to 0xb4d33aa0)
[595478.704045] 3a40: 60000193 00000000
[595478.708887] 3a60: 00000200 b4f48398 b30c2600 b4f48398 b4f484e8 b6956400 00000010 b4f48398
[595478.713671] 3a80: ad446400 b4d33ac4 00000100 b4d33aa8 00000100 7f1e33dc 60000193 ffffffff
[595478.718465] [<807188b4>] (__dabt_svc) from [<7f1e33dc>] (uvc_queue_next_buffer+0x7c/0xf0 [uvcvideo])
[595478.723285] [<7f1e33dc>] (uvc_queue_next_buffer [uvcvideo]) from [<7f1e6ab4>] (uvc_video_decode_isoc+0x118/0x198 [uvcvideo])
[595478.728122] [<7f1e6ab4>] (uvc_video_decode_isoc [uvcvideo]) from [<7f1e56b8>] (uvc_video_complete+0x84/0xec [uvcvideo])
[595478.732962] [<7f1e56b8>] (uvc_video_complete [uvcvideo]) from [<80556fe8>] (__usb_hcd_giveback_urb+0x80/0x160)
[595478.737759] [<80556fe8>] (__usb_hcd_giveback_urb) from [<80557114>] (usb_hcd_giveback_urb+0x4c/0xfc)
[595478.742551] [<80557114>] (usb_hcd_giveback_urb) from [<80581084>] (completion_tasklet_func+0x6c/0x98)
[595478.747338] [<80581084>] (completion_tasklet_func) from [<8058fe40>] (tasklet_callback+0x20/0x24)
[595478.752129] [<8058fe40>] (tasklet_callback) from [<80123070>] (tasklet_hi_action+0x74/0x10c)
[595478.756907] [<80123070>] (tasklet_hi_action) from [<8010169c>] (__do_softirq+0x18c/0x3cc)
[595478.761680] [<8010169c>] (__do_softirq) from [<80122c04>] (irq_exit+0x10c/0x168)
[595478.766452] [<80122c04>] (irq_exit) from [<80173510>] (__handle_domain_irq+0x70/0xc4)
[595478.771224] [<80173510>] (__handle_domain_irq) from [<8010150c>] (bcm2836_arm_irqchip_handle_irq+0xa8/0xac)
[595478.776102] [<8010150c>] (bcm2836_arm_irqchip_handle_irq) from [<8071893c>] (__irq_svc+0x5c/0x7c)
[595478.781100] Exception stack(0xb4d33c78 to 0xb4d33cc0)
[595478.783599] 3c60: 024200ca 00000000
[595478.788443] 3c80: 00000081 b4d33dd8 80c6f440 00400000 00000000 00000081 80c043a8 00000000
[595478.793236] 3ca0: 024200ca b4d33d5c b4d33d60 b4d33cc8 80214cec 80213a28 a0000113 ffffffff
[595478.798022] [<8071893c>] (__irq_svc) from [<80213a28>] (get_page_from_freelist+0x18/0xb0c)
[595478.802814] [<80213a28>] (get_page_from_freelist) from [<80214cec>] (__alloc_pages_nodemask+0xf0/0xdd0)
[595478.807609] [<80214cec>] (__alloc_pages_nodemask) from [<802420cc>] (handle_mm_fault+0xb58/0xde4)
[595478.812402] [<802420cc>] (handle_mm_fault) from [<807193f4>] (do_page_fault+0x33c/0x3b0)
[595478.817178] [<807193f4>] (do_page_fault) from [<801011e8>] (do_DataAbort+0x48/0xc4)
[595478.821953] [<801011e8>] (do_DataAbort) from [<80718c24>] (__dabt_usr+0x44/0x60)
[595478.826715] Exception stack(0xb4d33fb0 to 0xb4d33ff8)
[595478.829094] 3fa0: 76084000 00000000 0006fff8 00000000
[595478.833767] 3fc0: 56768598 7ee04da0 00000000 76e1188c 7ee04c68 7ee04c68 ffffffff 7ee04da0
[595478.838389] 3fe0: 00000000 7ee04c00 00000000 76f910dc 20000010 ffffffff
[595487.591650] INFO: rcu_sched detected stalls on CPUs/tasks:
[595487.594004] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=10474
[595487.598573] (detected by 0, t=21017 jiffies, g=24633640, c=24633639, q=9691)
[595487.603146] Task dump for CPU 3:
[595487.605424] avconv R running task 0 7121 1 0x00000003
[595487.607815] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
[595550.640848] INFO: rcu_sched detected stalls on CPUs/tasks:
[595550.643158] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=13622
[595550.647634] (detected by 0, t=27322 jiffies, g=24633640, c=24633639, q=11994)
[595550.652088] Task dump for CPU 3:
[595550.654264] avconv R running task 0 7121 1 0x00000003
[595550.656499] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
[595601.480296] INFO: task systemd-journal:147 blocked for more than 120 seconds.
[595601.484693] Not tainted 4.9.24-v7+ #993
[595601.486858] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[595601.491209] systemd-journal D 0 147 1 0x00000001
[595601.493404] [<80713980>] (__schedule) from [<80713ea4>] (schedule+0x50/0xa8)
[595601.495582] [<80713ea4>] (schedule) from [<80714298>] (schedule_preempt_disabled+0x18/0x1c)
[595601.499858] [<80714298>] (schedule_preempt_disabled) from [<807159b4>] (__mutex_lock_slowpath+0xac/0x164)
[595601.504264] [<807159b4>] (__mutex_lock_slowpath) from [<80715acc>] (mutex_lock+0x60/0x64)
[595601.508664] [<80715acc>] (mutex_lock) from [<805d9138>] (rpi_firmware_transaction+0x44/0xac)
[595601.513097] [<805d9138>] (rpi_firmware_transaction) from [<805d9298>] (rpi_firmware_property_list+0xf8/0x220)
[595601.517601] [<805d9298>] (rpi_firmware_property_list) from [<805d9424>] (rpi_firmware_property+0x64/0x84)
[595601.522161] [<805d9424>] (rpi_firmware_property) from [<804a2110>] (bcm2708_fb_blank+0x50/0x9c)
[595601.526721] [<804a2110>] (bcm2708_fb_blank) from [<80498650>] (fb_blank+0x64/0xb8)
[595601.531321] [<80498650>] (fb_blank) from [<8049207c>] (fbcon_blank+0x1ec/0x2b8)
[595601.536022] [<8049207c>] (fbcon_blank) from [<804d53f0>] (do_unblank_screen+0xbc/0x1c4)
[595601.540747] [<804d53f0>] (do_unblank_screen) from [<804d5514>] (unblank_screen+0x1c/0x20)
[595601.545492] [<804d5514>] (unblank_screen) from [<80462ffc>] (bust_spinlocks+0x30/0x58)
[595601.550281] [<80462ffc>] (bust_spinlocks) from [<8010c18c>] (die+0x130/0x440)
[595601.555142] [<8010c18c>] (die) from [<80118e74>] (__do_kernel_fault.part.0+0x74/0x1f4)
[595601.560052] [<80118e74>] (__do_kernel_fault.part.0) from [<80719300>] (do_page_fault+0x248/0x3b0)
[595601.565051] [<80719300>] (do_page_fault) from [<80719524>] (do_translation_fault+0xbc/0xc0)
[595601.570056] [<80719524>] (do_translation_fault) from [<801011e8>] (do_DataAbort+0x48/0xc4)
[595601.575064] [<801011e8>] (do_DataAbort) from [<807188b4>] (__dabt_svc+0x54/0x80)
[595601.580050] Exception stack(0xb4d33a58 to 0xb4d33aa0)
[595601.582548] 3a40: 60000193 00000000
[595601.587385] 3a60: 00000200 b4f48398 b30c2600 b4f48398 b4f484e8 b6956400 00000010 b4f48398
[595601.592164] 3a80: ad446400 b4d33ac4 00000100 b4d33aa8 00000100 7f1e33dc 60000193 ffffffff
[595601.596954] [<807188b4>] (__dabt_svc) from [<7f1e33dc>] (uvc_queue_next_buffer+0x7c/0xf0 [uvcvideo])
[595601.601768] [<7f1e33dc>] (uvc_queue_next_buffer [uvcvideo]) from [<7f1e6ab4>] (uvc_video_decode_isoc+0x118/0x198 [uvcvideo])
[595601.606599] [<7f1e6ab4>] (uvc_video_decode_isoc [uvcvideo]) from [<7f1e56b8>] (uvc_video_complete+0x84/0xec [uvcvideo])
[595601.611436] [<7f1e56b8>] (uvc_video_complete [uvcvideo]) from [<80556fe8>] (__usb_hcd_giveback_urb+0x80/0x160)
[595601.616230] [<80556fe8>] (__usb_hcd_giveback_urb) from [<80557114>] (usb_hcd_giveback_urb+0x4c/0xfc)
[595601.621019] [<80557114>] (usb_hcd_giveback_urb) from [<80581084>] (completion_tasklet_func+0x6c/0x98)
[595601.625805] [<80581084>] (completion_tasklet_func) from [<8058fe40>] (tasklet_callback+0x20/0x24)
[595601.630595] [<8058fe40>] (tasklet_callback) from [<80123070>] (tasklet_hi_action+0x74/0x10c)
[595601.635373] [<80123070>] (tasklet_hi_action) from [<8010169c>] (__do_softirq+0x18c/0x3cc)
[595601.640145] [<8010169c>] (__do_softirq) from [<80122c04>] (irq_exit+0x10c/0x168)
[595601.644919] [<80122c04>] (irq_exit) from [<80173510>] (__handle_domain_irq+0x70/0xc4)
[595601.649689] [<80173510>] (__handle_domain_irq) from [<8010150c>] (bcm2836_arm_irqchip_handle_irq+0xa8/0xac)
[595601.654566] [<8010150c>] (bcm2836_arm_irqchip_handle_irq) from [<8071893c>] (__irq_svc+0x5c/0x7c)
[595601.659562] Exception stack(0xb4d33c78 to 0xb4d33cc0)
[595601.662060] 3c60: 024200ca 00000000
[595601.666903] 3c80: 00000081 b4d33dd8 80c6f440 00400000 00000000 00000081 80c043a8 00000000
[595601.671693] 3ca0: 024200ca b4d33d5c b4d33d60 b4d33cc8 80214cec 80213a28 a0000113 ffffffff
[595601.676472] [<8071893c>] (__irq_svc) from [<80213a28>] (get_page_from_freelist+0x18/0xb0c)
[595601.681257] [<80213a28>] (get_page_from_freelist) from [<80214cec>] (__alloc_pages_nodemask+0xf0/0xdd0)
[595601.686047] [<80214cec>] (__alloc_pages_nodemask) from [<802420cc>] (handle_mm_fault+0xb58/0xde4)
[595601.690836] [<802420cc>] (handle_mm_fault) from [<807193f4>] (do_page_fault+0x33c/0x3b0)
[595601.695607] [<807193f4>] (do_page_fault) from [<801011e8>] (do_DataAbort+0x48/0xc4)
[595601.700378] [<801011e8>] (do_DataAbort) from [<80718c24>] (__dabt_usr+0x44/0x60)
[595601.705135] Exception stack(0xb4d33fb0 to 0xb4d33ff8)
[595601.707512] 3fa0: 76084000 00000000 0006fff8 00000000
[595601.712182] 3fc0: 56768598 7ee04da0 00000000 76e1188c 7ee04c68 7ee04c68 ffffffff 7ee04da0
[595601.716801] 3fe0: 00000000 7ee04c00 00000000 76f910dc 20000010 ffffffff
[595613.690064] INFO: rcu_sched detected stalls on CPUs/tasks:
[595613.692416] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=16770
[595613.696982] (detected by 0, t=33627 jiffies, g=24633640, c=24633639, q=14188)
[595613.701553] Task dump for CPU 3:
[595613.703829] avconv R running task 0 7121 1 0x00000003
[595613.706219] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
[595676.739299] INFO: rcu_sched detected stalls on CPUs/tasks:
[595676.741616] 3-...: (1 GPs behind) idle=6bb/140000000000000/0 softirq=25589465/25589472 fqs=19920
[595676.746111] (detected by 0, t=39932 jiffies, g=24633640, c=24633639, q=16746)
[595676.750647] Task dump for CPU 3:
[595676.752908] avconv R running task 0 7121 1 0x00000003
[595676.755229] [<80713980>] (__schedule) from [<8025ea44>] (__slab_free+0x1f8/0x3a4)
jetibest
All 38 comments
I would recommend trying a newer kernel - we are currently shipping Raspbian based on 4.14.34. Amongst a slew of improvements is a back-port of a patch that fixes a memory corruption bug caused by the USB driver - see https://github.com/raspberrypi/linux/commit/8960ba68b681a62a523cc593773d5d03a413a075 .
You can either grab the current image, update the relevant Raspbian packages (sudo apt-get install --reinstall raspberrypi-bootloader raspberrypi-kernel) or use rpi-update to fetch the very latest firmware (sudo rpi-update).
pelwell
on 8 Jun 2018
@pelwell We are currently testing the latest update for which we used rpi-update. However, does this fix mean that it should be reproducable using the following code repeatedly?
echo 0 > /sys/bus/platform/drivers/dwc_otg/20980000.usb/buspower
sleep 5
echo 1 > /sys/bus/platform/drivers/dwc_otg/20980000.usb/buspower
See also: #1272
jetibest
on 8 Jun 2018
Perhaps - it's worth a try.
pelwell
on 8 Jun 2018
@pelwell As I suspected - unfortunately, the latest update did not fix the problem. The kernel oops still occurs, even after latest rpi-update.
> uname -a
Linux rpi 4.14.48-v7+ #1118 SMP Thu Jun 7 16:40:27 BST 2018 armv7l GNU/Linux
Here are the dmesg -k logs after booting the system from the kernel oops frozen state:
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.14.48-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1118 SMP Thu Jun 7 16:40:27 BST 2018
[ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 8 MiB at 0x36800000
[ 0.000000] On node 0 totalpages: 225280
[ 0.000000] free_area_init_node: node 0, pgdat 80c84fc0, node_mem_map b603a000
[ 0.000000] Normal zone: 1980 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 225280 pages, LIFO batch:31
[ 0.000000] percpu: Embedded 17 pages/cpu @b5fe3000 s38720 r8192 d22720 u69632
[ 0.000000] pcpu-alloc: s38720 r8192 d22720 u69632 alloc=17*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 223300
[ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000 dwc_otg.lpm_enable=0 console=tty1 root=/dev/mmcblk0p7 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait noswap
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 871216K/901120K available (7168K kernel code, 575K rwdata, 2072K rodata, 1024K init, 706K bss, 21712K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xb7800000 - 0xff800000 (1152 MB)
lowmem : 0x80000000 - 0xb7000000 ( 880 MB)
modules : 0x7f000000 - 0x80000000 ( 16 MB)
.text : 0x80008000 - 0x80800000 (8160 kB)
.init : 0x80b00000 - 0x80c00000 (1024 kB)
.data : 0x80c00000 - 0x80c8feb4 ( 576 kB)
.bss : 0x80c96f40 - 0x80d478b4 ( 707 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 25253 entries in 75 pages
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000023] Switching to timer-based delay loop, resolution 52ns
[ 0.000272] Console: colour dummy device 80x30
[ 0.000804] console [tty1] enabled
[ 0.000844] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000884] pid_max: default: 32768 minimum: 301
[ 0.001214] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001247] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.002192] Disabling memory control group subsystem
[ 0.002290] CPU: Testing write buffer coherency: ok
[ 0.002701] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.003100] Setting up static identity map for 0x100000 - 0x10003c
[ 0.003233] Hierarchical SRCU implementation.
[ 0.003884] smp: Bringing up secondary CPUs ...
[ 0.004591] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.005343] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.006078] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.006182] smp: Brought up 1 node, 4 CPUs
[ 0.006252] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.006274] CPU: All CPU(s) started in HYP mode.
[ 0.006292] CPU: Virtualization extensions available.
[ 0.007150] devtmpfs: initialized
[ 0.016884] random: get_random_u32 called from bucket_table_alloc+0xfc/0x24c with crng_init=0
[ 0.017547] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.017789] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.017833] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.018407] pinctrl core: initialized pinctrl subsystem
[ 0.019168] NET: Registered protocol family 16
[ 0.021766] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.026531] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.026564] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.026784] Serial: AMBA PL011 UART driver
[ 0.028427] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.028902] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[ 0.060569] bcm2835-dma 3f007000.dma: DMA legacy API manager at b7813000, dmachans=0x1
[ 0.062013] SCSI subsystem initialized
[ 0.062253] usbcore: registered new interface driver usbfs
[ 0.062323] usbcore: registered new interface driver hub
[ 0.062424] usbcore: registered new device driver usb
[ 0.070083] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-06-07 15:37
[ 0.071398] clocksource: Switched to clocksource arch_sys_counter
[ 0.148492] VFS: Disk quotas dquot_6.6.0
[ 0.148603] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.148808] FS-Cache: Loaded
[ 0.149017] CacheFiles: Loaded
[ 0.157846] NET: Registered protocol family 2
[ 0.158577] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.158708] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.158910] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.159056] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.159118] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.159364] NET: Registered protocol family 1
[ 0.159824] RPC: Registered named UNIX socket transport module.
[ 0.159848] RPC: Registered udp transport module.
[ 0.159867] RPC: Registered tcp transport module.
[ 0.159886] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.161327] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 0.164149] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 0.172097] FS-Cache: Netfs 'nfs' registered for caching
[ 0.172706] NFS: Registering the id_resolver key type
[ 0.172759] Key type id_resolver registered
[ 0.172779] Key type id_legacy registered
[ 0.172807] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[ 0.174647] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.174791] io scheduler noop registered
[ 0.174813] io scheduler deadline registered (default)
[ 0.175103] io scheduler cfq registered
[ 0.175124] io scheduler mq-deadline registered
[ 0.175144] io scheduler kyber registered
[ 0.177847] BCM2708FB: allocated DMA memory f6910000
[ 0.177891] BCM2708FB: allocated DMA channel 0 @ b7813000
[ 0.187328] Console: switching to colour frame buffer device 80x30
[ 0.195700] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[ 0.199683] bcm2835-rng 3f104000.rng: hwrng registered
[ 0.202448] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
[ 0.208250] vc-sm: Videocore shared memory driver
[ 0.211347] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 0.226600] brd: module loaded
[ 0.237950] loop: module loaded
[ 0.240671] Loading iSCSI transport class v2.0-870.
[ 0.244018] libphy: Fixed MDIO Bus: probed
[ 0.246767] usbcore: registered new interface driver lan78xx
[ 0.249541] usbcore: registered new interface driver smsc95xx
[ 0.252280] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.483054] Core Release: 2.80a
[ 0.485659] Setting default values for core params
[ 0.488246] Finished setting default values for core params
[ 0.691097] Using Buffer DMA mode
[ 0.693705] Periodic Transfer Interrupt Enhancement - disabled
[ 0.696401] Multiprocessor Interrupt Enhancement - disabled
[ 0.699150] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.701942] Dedicated Tx FIFOs mode
[ 0.705017] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xb6904000 dma = 0xf6904000 len=9024
[ 0.710799] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 0.724473] dwc_otg: Microframe scheduler enabled
[ 0.724560] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805e7c5c
[ 0.727219] WARN::hcd_init_fiq:460: FIQ ASM at 0x805e7fc4 length 36
[ 0.729789] WARN::hcd_init_fiq:486: MPHI regs_base at 0xb787e000
[ 0.732406] dwc_otg 3f980000.usb: DWC OTG Controller
[ 0.735046] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 0.740280] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 0.743053] Init: Port Power? op_state=1
[ 0.745796] Init: Power Port (0)
[ 0.748657] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.751459] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.756906] usb usb1: Product: DWC OTG Controller
[ 0.759677] usb usb1: Manufacturer: Linux 4.14.48-v7+ dwc_otg_hcd
[ 0.762487] usb usb1: SerialNumber: 3f980000.usb
[ 0.765822] hub 1-0:1.0: USB hub found
[ 0.768557] hub 1-0:1.0: 1 port detected
[ 0.771755] dwc_otg: FIQ enabled
[ 0.771761] dwc_otg: NAK holdoff enabled
[ 0.771765] dwc_otg: FIQ split-transaction FSM enabled
[ 0.771776] Module dwc_common_port init
[ 0.772016] usbcore: registered new interface driver usb-storage
[ 0.774872] mousedev: PS/2 mouse device common for all mice
[ 0.777564] IR NEC protocol handler initialized
[ 0.780172] IR RC5(x/sz) protocol handler initialized
[ 0.782832] IR RC6 protocol handler initialized
[ 0.785477] IR JVC protocol handler initialized
[ 0.788074] IR Sony protocol handler initialized
[ 0.790650] IR SANYO protocol handler initialized
[ 0.793209] IR Sharp protocol handler initialized
[ 0.795705] IR MCE Keyboard/mouse protocol handler initialized
[ 0.798255] IR XMP protocol handler initialized
[ 0.801456] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 0.804331] bcm2835-cpufreq: min=600000 max=1200000
[ 0.807216] sdhci: Secure Digital Host Controller Interface driver
[ 0.809776] sdhci: Copyright(c) Pierre Ossman
[ 0.812647] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.815606] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[ 0.818357] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.822424] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.825240] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.828025] usbcore: registered new interface driver usbhid
[ 0.830675] usbhid: USB HID core driver
[ 0.833897] vchiq: vchiq_init_state: slot_zero = b6980000, is_master = 0
[ 0.838383] [vc_sm_connected_init]: start
[ 0.847205] [vc_sm_connected_init]: end - returning 0
[ 0.850503] Initializing XFRM netlink socket
[ 0.853218] NET: Registered protocol family 17
[ 0.855954] Key type dns_resolver registered
[ 0.858988] Registering SWP/SWPB emulation handler
[ 0.862245] registered taskstats version 1
[ 0.870585] uart-pl011 3f201000.serial: cts_event_workaround enabled
[ 0.873580] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 0.880866] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 166, base_baud = 31250000) is a 16550
[ 0.887861] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 0.890944] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 0.952031] sdhost: log_buf @ b6907000 (f6907000)
[ 0.991500] Indeed it is in host mode hprt0 = 00021501
[ 1.055490] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 1.060050] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 1.064497] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 1.070060] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 1.081426] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 1.085057] of_cfs_init
[ 1.087718] of_cfs_init: OK
[ 1.090691] Waiting for root device /dev/mmcblk0p7...
[ 1.104785] random: fast init done
[ 1.158836] mmc0: host does not support reading read-only switch, assuming write-enable
[ 1.166724] mmc0: new high speed SDHC card at address 0007
[ 1.169982] mmcblk0: mmc0:0007 SD16G 14.5 GiB
[ 1.176682] mmcblk0: p1 p2 < p5 p6 p7 >
[ 1.201437] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 1.204383] Indeed it is in host mode hprt0 = 00001101
[ 1.211650] EXT4-fs (mmcblk0p7): INFO: recovery required on readonly filesystem
[ 1.216977] EXT4-fs (mmcblk0p7): write access will be enabled during recovery
[ 1.274162] mmc1: new high speed SDIO card at address 0001
[ 1.441708] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[ 1.444496] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.447902] hub 1-1:1.0: USB hub found
[ 1.450736] hub 1-1:1.0: 5 ports detected
[ 1.771431] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 1.901779] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[ 1.904685] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 1.913208] smsc95xx v1.0.6
[ 2.004706] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:27:d2:7d
[ 2.301423] usb 1-1.2: new high-speed USB device number 4 using dwc_otg
[ 2.419627] EXT4-fs (mmcblk0p7): recovery complete
[ 2.429276] EXT4-fs (mmcblk0p7): mounted filesystem with ordered data mode. Opts: (null)
[ 2.432339] usb 1-1.2: New USB device found, idVendor=0781, idProduct=5571
[ 2.432349] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 2.432356] usb 1-1.2: Product: Cruzer Fit
[ 2.432362] usb 1-1.2: Manufacturer: SanDisk
[ 2.432369] usb 1-1.2: SerialNumber: 4C530001020323105465
[ 2.433105] usb-storage 1-1.2:1.0: USB Mass Storage device detected
[ 2.457947] VFS: Mounted root (ext4 filesystem) readonly on device 179:7.
[ 2.458050] scsi host0: usb-storage 1-1.2:1.0
[ 2.473826] devtmpfs: mounted
[ 2.479724] Freeing unused kernel memory: 1024K
[ 2.551438] usb 1-1.4: new high-speed USB device number 5 using dwc_otg
[ 2.715506] usb 1-1.4: New USB device found, idVendor=05a3, idProduct=9422
[ 2.718614] usb 1-1.4: New USB device strings: Mfr=2, Product=1, SerialNumber=3
[ 2.724655] usb 1-1.4: Product: H264 USB Camera
[ 2.727724] usb 1-1.4: Manufacturer: Sonix Technology Co., Ltd.
[ 2.730738] usb 1-1.4: SerialNumber: SN0001
[ 2.818157] random: systemd: uninitialized urandom read (16 bytes read)
[ 3.028376] NET: Registered protocol family 10
[ 3.032759] Segment Routing with IPv6
[ 3.196215] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read)
[ 3.334354] random: systemd: uninitialized urandom read (16 bytes read)
[ 3.512511] scsi 0:0:0:0: Direct-Access SanDisk Cruzer Fit 1.00 PQ: 0 ANSI: 6
[ 3.520392] sd 0:0:0:0: [sda] 31260672 512-byte logical blocks: (16.0 GB/14.9 GiB)
[ 3.528659] sd 0:0:0:0: [sda] Write Protect is off
[ 3.532336] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[ 3.532898] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 3.547714] sda: sda1
[ 3.553370] sd 0:0:0:0: [sda] Attached SCSI removable disk
[ 3.974326] fuse init (API version 7.26)
[ 4.015334] i2c /dev entries driver
[ 6.270680] EXT4-fs (mmcblk0p7): re-mounted. Opts: (null)
[ 6.758171] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[ 6.761002] bcm2835_alsa bcm2835_alsa: card created with 8 channels
[ 6.839976] sd 0:0:0:0: Attached scsi generic sg0 type 0
[ 6.889445] media: Linux media interface: v0.10
[ 6.945117] Linux video capture interface: v2.00
[ 7.079517] usb 1-1.4: 4:1: cannot get freq at ep 0x84
[ 7.142114] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[ 7.150183] usbcore: registered new interface driver snd-usb-audio
[ 7.159442] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
[ 7.159689] usbcore: registered new interface driver brcmfmac
[ 7.162793] uvcvideo: Found UVC 1.00 device H264 USB Camera (05a3:9422)
[ 7.179450] uvcvideo: Unable to create debugfs 1-5 directory.
[ 7.179774] uvcvideo 1-1.4:1.0: Entity type for entity Extension 4 was not initialized!
[ 7.179788] uvcvideo 1-1.4:1.0: Entity type for entity Extension 3 was not initialized!
[ 7.179801] uvcvideo 1-1.4:1.0: Entity type for entity Processing 2 was not initialized!
[ 7.179812] uvcvideo 1-1.4:1.0: Entity type for entity Camera 1 was not initialized!
[ 7.180210] input: H264 USB Camera: USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4:1.0/input/input0
[ 7.180466] usbcore: registered new interface driver uvcvideo
[ 7.180548] USB Video Class driver (1.1.1)
[ 7.370586] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Aug 7 2017 00:46:29 version 7.45.41.46 (r666254 CY) FWID 01-f8a78378
[ 7.371475] brcmfmac: brcmf_c_preinit_dcmds: CLM version = API: 12.2 Data: 7.11.15 Compiler: 1.24.2 ClmImport: 1.24.1 Creation: 2014-05-26 10:53:55 Inc Data: 9.10.41 Inc Compiler: 1.29.4 Inc ClmImport: 1.36.3 Creation: 2017-08-07 00:37:47
[ 8.484932] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 8.484951] brcmfmac: power management disabled
[ 8.802462] uart-pl011 3f201000.serial: no DMA platform data
[ 9.554614] random: crng init done
[ 9.554625] random: 7 urandom warning(s) missed due to ratelimiting
[ 10.422033] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 10.422292] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 12.461452] usb 1-1.3: new high-speed USB device number 6 using dwc_otg
[ 12.592395] usb 1-1.3: New USB device found, idVendor=12d1, idProduct=1f01
[ 12.592407] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 12.592415] usb 1-1.3: Product: HUAWEI_MOBILE
[ 12.592423] usb 1-1.3: Manufacturer: HUAWEI_MOBILE
[ 12.592432] usb 1-1.3: SerialNumber: 0123456789ABCDEF
[ 12.650911] usb-storage 1-1.3:1.0: USB Mass Storage device detected
[ 12.651449] scsi host1: usb-storage 1-1.3:1.0
[ 13.282409] Bluetooth: Core ver 2.22
[ 13.282612] NET: Registered protocol family 31
[ 13.282628] Bluetooth: HCI device and connection manager initialized
[ 13.282665] Bluetooth: HCI socket layer initialized
[ 13.282680] Bluetooth: L2CAP socket layer initialized
[ 13.282746] Bluetooth: SCO socket layer initialized
[ 13.305871] Bluetooth: HCI UART driver ver 2.3
[ 13.305894] Bluetooth: HCI UART protocol H4 registered
[ 13.305901] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 13.306396] Bluetooth: HCI UART protocol Broadcom registered
[ 13.676861] scsi 1:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
[ 13.677326] scsi 1:0:0:0: Attached scsi generic sg1 type 5
[ 13.677892] scsi 1:0:0:1: Direct-Access HUAWEI TF CARD Storage 2.31 PQ: 0 ANSI: 2
[ 13.679240] sd 1:0:0:1: Attached scsi generic sg2 type 0
[ 13.685002] sd 1:0:0:1: [sdb] Attached SCSI removable disk
[ 13.689390] sr 1:0:0:0: [sr0] scsi-1 drive
[ 13.689400] cdrom: Uniform CD-ROM driver Revision: 3.20
[ 13.690298] sr 1:0:0:0: Attached scsi CD-ROM sr0
[ 15.807703] sr 1:0:0:0: [sr0] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x08
[ 15.807713] sr 1:0:0:0: [sr0] tag#0 Sense Key : 0x3 [current]
[ 15.807719] sr 1:0:0:0: [sr0] tag#0 ASC=0x11 ASCQ=0x0
[ 15.807727] sr 1:0:0:0: [sr0] tag#0 CDB: opcode=0x28 28 00 00 00 0f fe 00 00 02 00
[ 15.807734] print_req_error: critical medium error, dev sr0, sector 16376
[ 15.807760] attempt to access beyond end of device
[ 15.807765] sr0: rw=0, want=16384, limit=16376
[ 15.807771] Buffer I/O error on dev sr0, logical block 2047, async page read
[ 17.801724] usb 1-1.3: USB disconnect, device number 6
[ 18.861504] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
[ 18.992679] usb 1-1.3: New USB device found, idVendor=12d1, idProduct=14dc
[ 18.992692] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 18.992696] usb 1-1.3: Product: HUAWEI_MOBILE
[ 18.992700] usb 1-1.3: Manufacturer: HUAWEI_MOBILE
[ 19.142449] usb-storage 1-1.3:1.2: USB Mass Storage device detected
[ 19.144379] scsi host1: usb-storage 1-1.3:1.2
[ 19.208612] cdc_ether 1-1.3:1.0 eth1: register 'cdc_ether' at usb-3f980000.usb-1.3, CDC Ethernet Device, 0c:5b:8f:27:9a:64
[ 19.208854] usbcore: registered new interface driver cdc_ether
[ 20.167064] scsi 1:0:0:0: Direct-Access HUAWEI TF CARD Storage 2.31 PQ: 0 ANSI: 2
[ 20.168114] sd 1:0:0:0: Attached scsi generic sg1 type 0
[ 20.176203] sd 1:0:0:0: [sdb] Attached SCSI removable disk
[ 26.102627] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 26.102662] brcmfmac: power management disabled
[ 42.685677] uvcvideo: Failed to resubmit video URB (-1).
[ 1803.057432] uvcvideo: Failed to resubmit video URB (-1).
[ 2702.913553] uvcvideo: Failed to resubmit video URB (-1).
@pelwell We installed a fresh Arch Linux for the RPi 3B, which still led to the problem (I figure the kernel is just the same). Note that it is unlikely due to a bug in the USB-devices themselves, since the problem only occurs when a combination of both is used. Power supply is definitively not an issue either, as stated before.
It applies to all ten RPi 3B devices, so it is not a coincidental manufacturing error either. We are wasting a lot of time on this issue, if you have any idea to what might cause this issue or help to prevent it, please let us know.
I also see that in RPi 3B+ model some changes were made to the USB architecture, including an additional USB controller. Why was this changed? Could this have anything to do with this issue?
jetibest
on 17 Jun 2018
@jetibest The USB connection on the SOC itself is the same. The new ethernet chip (to give us gig ethernet) now has two hubs internally, one hanging off the other, to give enough ports. Not sure why it was done like that, but that's how it is. We just use the chip!
JamesH65
on 17 Jun 2018
@JamesH65 Thank you. We are now testing with a RPi 3B+, to see if the issue still occurs, just to make sure we tried everything before we start looking for alternatives to the RPi. If there is something else we could or should try, I am open to suggestions.
Will this issue be investigated? How do you typically deal with issues like these?
jetibest
on 17 Jun 2018
The problem here is that you are using two external devices. We are currently working full time on ensuring the on board devices work as expected, so there is little time for trying combinations of third party stuff.
As for how we deal, generally, the bugs that affect a lot of people get investigated first. And of course, we always have new products to develop as well, and as we don't have a dedicated bug fixing team, there is a certain amount of flitting around between new product and bug fixing.
We also like to have easy ways of replicating issues, on Raspbian. Easily replicated bugs get fixed faster. Bugs reported on other distro's, because we cannot be sure they also go wrong on our distro, tend to be lower on the priority list.
JamesH65
on 18 Jun 2018
@JamesH65 Thank you for your swift reply. I understand, fair enough.
As far as reproducibility goes, when you have the time, you can do the following which has been very consistent for us:
- RPi 3 Model B with NOOBS Raspbian installation
- usb webcam (any uvcvideo)
- usbmodem (e.g. Huawei E3372)
Set a crontab for every 5 minutes running the following script:
avconv -f video4linux2 -input_format mjpeg -i /dev/video0 -codec:v copy "/tmp/frame.%d.jpg" &
pid=$!
sleep 5
kill -INT $pid
wait $pid
rm -f /tmp/frame.*.jpg
Make sure to connect to the internet through the usbmodem, and keep an ssh-connection open (e.g. use ServerAliveInterval 60 in /etc/ssh/sshd.conf). It will take by average ~3 days (of 24 hours) for the kernel oops to occur. Unfortunately we have been unable to reproduce this problem on a shorter notice.
Of course, for many people, an occasional kernel oops may only be a slight annoyance, and it is hard to track down the problem. Many times it may be indistinguishable from a bad power supply. I wouldn't be surprised if this is not reported too often, if at all. But I found these that might be similar:
ajohn370 commented on Dec 14, 2017 "Having a similar issue with an rpi 3 b. System runs smoothly but it freezes hangs and I loose ssh and VNC access." - https://github.com/raspberrypi/firmware/issues/247
l-spitz commented on Sep 26, 2017 "I'm getting a lot of issues similar to what you describe, when running webcams over the usb, namely sporadically get dmesg messages, and eventually get following, which requires a power cycle to recover from." - https://github.com/raspberrypi/linux/issues/1272
zerwes commented on Mar 29 "same issue here" - https://github.com/raspberrypi/linux/issues/2481
jetibest
on 18 Jun 2018
Actually I could reproduce it in usually less than an hour, typically 20 mins (rarely a day long), by running two webcams, taking stills as fast as they could. Using a python script (calling linux using os.system), but suspect bash script would do the same . Each webcam was in its own process.
Each time it was same thing (kernel NULL pointer dereference at virtual address 0...)
I tried fswebcam and uvccapture both did the same.
There seemed a loose correlation between file size and crashes (eg. a low-res web-cam vs. high res).
This was on the Rpi 3, not tried it since the B+ came out.
I came to the conclusion that trying to do more than one large file transfer over the usb at the same time was the trigger. I re-arranged my application to avoid this situation.
l-spitz
on 18 Jun 2018
Thanks, both useful data points that will help when we get the time. @P33M Any thoughts?
JamesH65
on 18 Jun 2018
I can now confirm that the problem is only reproducable when the webcam is repeatedly turned on and off again to take pictures (using avconv). When the webcam is permanently streaming (avconv mjpeg), there is no issue. It seems like turning the webcam on or off is the cause (however, only in combination with another usb-device).
@l-spitz do you still have your python script, or know what it consisted of? I would like to test your script on our system.
jetibest
on 29 Jun 2018
Sure, my script is constantly turning two usb webcams on and off (as an accelerated test) so fits with what you found. Hope it helps
`
import sys, os
import time
import multiprocessing
import subprocess
class OCamera():
def __init__(self,name,filename,video):
print(name)
self.filename = filename
if video == 1:
self.device = '/dev/video1'
elif video == 0:
self.device = '/dev/video0'
else:
raise ValueError("device not supported")
self.cmd_string = "fswebcam -d " + self.device + " -q -r 800x600 --no-banner -S 5 "
#self.cmd_string = "uvccapture -d" + self.device + " -q81 -x640 -y480 -m -S45 -C30 -G80 -B-96 -o"
print("command string",self.cmd_string)
self.killme = multiprocessing.Event()
self.killme.set()
self.name = name
self.process = multiprocessing.Process(target=self.Process, args=(), name=name)
def killProcess(self):
self.killme.clear()
def start(self):
self.process.start()
def Process(self):
while self.killme.is_set():
print(self.name)
os.system(self.cmd_string + self.filename)
time.sleep(0.1)
if __name__ == "__main__":
procs = list()
try:
procs.append(OCamera("Camera One",'/home/pi/Temp/cam1_test.jpg',1))
procs.append(OCamera("Camera Two",'/home/pi/Temp/cam2_test.jpg',0))
print("starting cameras")
for wc in procs:
wc.start()
except:
for wc in procs:
wc.killProcess()
for wc in procs:
wc.process.join()
`
l-spitz
on 30 Jun 2018
@l-spitz Thank you for the script. Ran it for an hour or so, and later again for 5 hours straight. Unfortunately could not reproduce any problem within a short period of time (even while the usb-modem was also still plugged in). I used two ELP camera modules with USB connectors, on the RPi 3 Model B.
After that I ran the same script for 3 hours, but now with a sleep of 3 seconds (to ensure the webcams are suspended momentarily, which I verified with cat /sys/bus/usb/devices/1-1.4/power/*), and I still could not reproduce it on short notice.
So the current status is that it is still not reproducable within hours, but only within days. It's very peculiar that the problem does not occur sooner for a higher frequency of accessing the USB webcams.
jetibest
on 6 Jul 2018
What resolution was the camera, I was using a genius HD webcam F100, and also tried with others in the 5MP range (all on RPi 3 Model B). I re-tried the script before posting, and had three crashes in a 6 hr period. I had a hunch larger MP caused more crashes.
l-spitz
on 7 Jul 2018
I think I am having a similar issue. I am using ELP 5MP webcams ELP-USB500W05G, currently on Rpi 3B but hopefully soon on 3B+ models. We are using thousands of Pi's so this is a big deal for us.
Here is the initial trace from kernel.... As you can see, there is some sort of USB bus crash, followed by a USB restart.
Aug 21 09:00:45 raspberrypi kernel: [12920.270759] usb usb1-port1: disabled by hub (EMI?), re-enabling...
Aug 21 09:00:45 raspberrypi kernel: [12920.270777] usb 1-1: USB disconnect, device number 6
Aug 21 09:00:45 raspberrypi kernel: [12920.270783] usb 1-1.1: USB disconnect, device number 7
Aug 21 09:00:45 raspberrypi kernel: [12920.271116] smsc95xx 1-1.1:1.0 eth0: unregister 'smsc95xx' usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet
Aug 21 09:00:45 raspberrypi kernel: [12920.271175] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 09:00:45 raspberrypi kernel: [12920.331236] usb 1-1.3: USB disconnect, device number 8
Aug 21 09:00:45 raspberrypi kernel: [12920.331372] cdc_acm 1-1.3:1.0: failed to set dtr/rts
Aug 21 09:00:45 raspberrypi kernel: [12920.332048] usb 1-1.5: USB disconnect, device number 9
Aug 21 09:00:45 raspberrypi kernel: [12920.530924] Indeed it is in host mode hprt0 = 00001501
Aug 21 09:00:46 raspberrypi kernel: [12920.740744] usb 1-1: new high-speed USB device number 10 using dwc_otg
Aug 21 09:00:46 raspberrypi kernel: [12920.740844] Indeed it is in host mode hprt0 = 00001101
Aug 21 09:00:46 raspberrypi kernel: [12920.980837] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Aug 21 09:00:46 raspberrypi kernel: [12920.980844] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 09:00:46 raspberrypi kernel: [12920.981246] hub 1-1:1.0: USB hub found
Aug 21 09:00:46 raspberrypi kernel: [12920.981295] hub 1-1:1.0: 5 ports detected
Aug 21 09:00:46 raspberrypi kernel: [12921.300789] usb 1-1.1: new high-speed USB device number 11 using dwc_otg
Aug 21 09:00:46 raspberrypi kernel: [12921.450965] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Aug 21 09:00:46 raspberrypi kernel: [12921.450981] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 09:00:46 raspberrypi kernel: [12921.453840] smsc95xx v1.0.6
Aug 21 09:00:46 raspberrypi kernel: [12921.544026] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f8:2f:76
Aug 21 09:00:47 raspberrypi kernel: [12921.640774] usb 1-1.3: new full-speed USB device number 12 using dwc_otg
Aug 21 09:00:47 raspberrypi kernel: [12921.732710] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 09:00:47 raspberrypi kernel: [12921.732934] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 21 09:00:47 raspberrypi kernel: [12921.782278] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=f058
Aug 21 09:00:47 raspberrypi kernel: [12921.782294] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 21 09:00:47 raspberrypi kernel: [12921.782302] usb 1-1.3: Product: Sensor S7 V1.0
Aug 21 09:00:47 raspberrypi kernel: [12921.782311] usb 1-1.3: Manufacturer: Agnetix Inc.
Aug 21 09:00:47 raspberrypi kernel: [12921.782320] usb 1-1.3: SerialNumber: EA2622F2D54C5490704C0403E12F2958
Aug 21 09:00:47 raspberrypi kernel: [12921.785171] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
Aug 21 09:00:47 raspberrypi kernel: [12922.080722] usb 1-1.5: new high-speed USB device number 13 using dwc_otg
Aug 21 09:00:47 raspberrypi kernel: [12922.216313] usb 1-1.5: New USB device found, idVendor=05a3, idProduct=9520
Aug 21 09:00:47 raspberrypi kernel: [12922.216327] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Aug 21 09:00:47 raspberrypi kernel: [12922.216336] usb 1-1.5: Product: HD USB Camera
Aug 21 09:00:47 raspberrypi kernel: [12922.216344] usb 1-1.5: Manufacturer: HD Camera Manufacturer
Aug 21 09:00:47 raspberrypi kernel: [12922.217250] uvcvideo: Found UVC 1.00 device HD USB Camera (05a3:9520)
Aug 21 09:00:47 raspberrypi kernel: [12922.348073] uvcvideo 1-1.5:1.0: Entity type for entity Extension 2 was not initialized!
Aug 21 09:00:47 raspberrypi kernel: [12922.348089] uvcvideo 1-1.5:1.0: Entity type for entity Processing 3 was not initialized!
Aug 21 09:00:47 raspberrypi kernel: [12922.348102] uvcvideo 1-1.5:1.0: Entity type for entity Camera 1 was not initialized!
Aug 21 09:00:47 raspberrypi kernel: [12922.348480] input: HD USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/1-1.5:1.0/input/input2
Aug 21 09:00:48 raspberrypi kernel: [12923.151520] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 21 09:00:48 raspberrypi kernel: [12923.153739] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
Aug 21 11:51:27 raspberrypi kernel: [23162.284857] usb usb1-port1: disabled by hub (EMI?), re-enabling...
Aug 21 11:51:27 raspberrypi kernel: [23162.284875] usb 1-1: USB disconnect, device number 10
Aug 21 11:51:27 raspberrypi kernel: [23162.284881] usb 1-1.1: USB disconnect, device number 11
Aug 21 11:51:27 raspberrypi kernel: [23162.285232] smsc95xx 1-1.1:1.0 eth0: unregister 'smsc95xx' usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet
Aug 21 11:51:27 raspberrypi kernel: [23162.285291] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 11:51:27 raspberrypi kernel: [23162.346627] usb 1-1.3: USB disconnect, device number 12
Aug 21 11:51:27 raspberrypi kernel: [23162.346829] cdc_acm 1-1.3:1.0: failed to set dtr/rts
Aug 21 11:51:27 raspberrypi kernel: [23162.347867] usb 1-1.5: USB disconnect, device number 13
Aug 21 11:51:27 raspberrypi kernel: [23162.544881] Indeed it is in host mode hprt0 = 00001501
Aug 21 11:51:28 raspberrypi kernel: [23162.754792] usb 1-1: new high-speed USB device number 14 using dwc_otg
Aug 21 11:51:28 raspberrypi kernel: [23162.754897] Indeed it is in host mode hprt0 = 00001101
Aug 21 11:51:28 raspberrypi kernel: [23162.994891] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Aug 21 11:51:28 raspberrypi kernel: [23162.994898] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 11:51:28 raspberrypi kernel: [23162.996998] hub 1-1:1.0: USB hub found
Aug 21 11:51:28 raspberrypi kernel: [23162.997088] hub 1-1:1.0: 5 ports detected
Aug 21 11:51:28 raspberrypi kernel: [23163.314741] usb 1-1.1: new high-speed USB device number 15 using dwc_otg
Aug 21 11:51:28 raspberrypi kernel: [23163.445002] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Aug 21 11:51:28 raspberrypi kernel: [23163.445015] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 11:51:28 raspberrypi kernel: [23163.447878] smsc95xx v1.0.6
Aug 21 11:51:28 raspberrypi kernel: [23163.539226] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f8:2f:76
Aug 21 11:51:29 raspberrypi kernel: [23163.634834] usb 1-1.3: new full-speed USB device number 16 using dwc_otg
Aug 21 11:51:29 raspberrypi kernel: [23163.746914] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 11:51:29 raspberrypi kernel: [23163.747122] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 21 11:51:29 raspberrypi kernel: [23163.773778] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=f058
Aug 21 11:51:29 raspberrypi kernel: [23163.773794] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 21 11:51:29 raspberrypi kernel: [23163.773803] usb 1-1.3: Product: Sensor S7 V1.0
Aug 21 11:51:29 raspberrypi kernel: [23163.773812] usb 1-1.3: Manufacturer: Agnetix Inc.
Aug 21 11:51:29 raspberrypi kernel: [23163.773820] usb 1-1.3: SerialNumber: EA2622F2D54C5490704C0403E12F2958
Aug 21 11:51:29 raspberrypi kernel: [23163.774821] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
Aug 21 11:51:29 raspberrypi kernel: [23164.074774] usb 1-1.5: new high-speed USB device number 17 using dwc_otg
Aug 21 11:51:29 raspberrypi kernel: [23164.210329] usb 1-1.5: New USB device found, idVendor=05a3, idProduct=9520
Aug 21 11:51:29 raspberrypi kernel: [23164.210341] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Aug 21 11:51:29 raspberrypi kernel: [23164.210350] usb 1-1.5: Product: HD USB Camera
Aug 21 11:51:29 raspberrypi kernel: [23164.210358] usb 1-1.5: Manufacturer: HD Camera Manufacturer
Aug 21 11:51:29 raspberrypi kernel: [23164.211276] uvcvideo: Found UVC 1.00 device HD USB Camera (05a3:9520)
Aug 21 11:51:29 raspberrypi kernel: [23164.342076] uvcvideo 1-1.5:1.0: Entity type for entity Extension 2 was not initialized!
Aug 21 11:51:29 raspberrypi kernel: [23164.342091] uvcvideo 1-1.5:1.0: Entity type for entity Processing 3 was not initialized!
Aug 21 11:51:29 raspberrypi kernel: [23164.342104] uvcvideo 1-1.5:1.0: Entity type for entity Camera 1 was not initialized!
Aug 21 11:51:29 raspberrypi kernel: [23164.342483] input: HD USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/1-1.5:1.0/input/input3
Aug 21 11:51:30 raspberrypi kernel: [23165.237881] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
Aug 21 11:51:30 raspberrypi kernel: [23165.238579] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 21 12:47:23 raspberrypi kernel: [26518.042924] usb usb1-port1: disabled by hub (EMI?), re-enabling...
Aug 21 12:47:23 raspberrypi kernel: [26518.042945] usb 1-1: USB disconnect, device number 14
Aug 21 12:47:23 raspberrypi kernel: [26518.042951] usb 1-1.1: USB disconnect, device number 15
Aug 21 12:47:23 raspberrypi kernel: [26518.043318] smsc95xx 1-1.1:1.0 eth0: unregister 'smsc95xx' usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet
Aug 21 12:47:23 raspberrypi kernel: [26518.043396] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 12:47:23 raspberrypi kernel: [26518.097158] usb 1-1.3: USB disconnect, device number 16
Aug 21 12:47:23 raspberrypi kernel: [26518.097360] cdc_acm 1-1.3:1.0: failed to set dtr/rts
Aug 21 12:47:23 raspberrypi kernel: [26518.099565] usb 1-1.5: USB disconnect, device number 17
Aug 21 12:47:23 raspberrypi kernel: [26518.302949] Indeed it is in host mode hprt0 = 00001501
Aug 21 12:47:23 raspberrypi kernel: [26518.512856] usb 1-1: new high-speed USB device number 18 using dwc_otg
Aug 21 12:47:23 raspberrypi kernel: [26518.512964] Indeed it is in host mode hprt0 = 00001101
Aug 21 12:47:24 raspberrypi kernel: [26518.762968] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Aug 21 12:47:24 raspberrypi kernel: [26518.762974] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 12:47:24 raspberrypi kernel: [26518.763372] hub 1-1:1.0: USB hub found
Aug 21 12:47:24 raspberrypi kernel: [26518.763419] hub 1-1:1.0: 5 ports detected
Aug 21 12:47:24 raspberrypi kernel: [26519.082841] usb 1-1.1: new high-speed USB device number 19 using dwc_otg
Aug 21 12:47:24 raspberrypi kernel: [26519.213072] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Aug 21 12:47:24 raspberrypi kernel: [26519.213085] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 12:47:24 raspberrypi kernel: [26519.215909] smsc95xx v1.0.6
Aug 21 12:47:24 raspberrypi kernel: [26519.306343] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f8:2f:76
Aug 21 12:47:24 raspberrypi kernel: [26519.402918] usb 1-1.3: new full-speed USB device number 20 using dwc_otg
Aug 21 12:47:24 raspberrypi kernel: [26519.494766] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 12:47:24 raspberrypi kernel: [26519.494975] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 21 12:47:24 raspberrypi kernel: [26519.541847] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=f058
Aug 21 12:47:24 raspberrypi kernel: [26519.541863] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 21 12:47:24 raspberrypi kernel: [26519.541872] usb 1-1.3: Product: Sensor S7 V1.0
Aug 21 12:47:24 raspberrypi kernel: [26519.541880] usb 1-1.3: Manufacturer: Agnetix Inc.
Aug 21 12:47:24 raspberrypi kernel: [26519.541889] usb 1-1.3: SerialNumber: EA2622F2D54C5490704C0403E12F2958
Aug 21 12:47:24 raspberrypi kernel: [26519.542904] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
Aug 21 12:47:25 raspberrypi kernel: [26519.842837] usb 1-1.5: new high-speed USB device number 21 using dwc_otg
Aug 21 12:47:25 raspberrypi kernel: [26519.978440] usb 1-1.5: New USB device found, idVendor=05a3, idProduct=9520
Aug 21 12:47:25 raspberrypi kernel: [26519.978452] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Aug 21 12:47:25 raspberrypi kernel: [26519.978462] usb 1-1.5: Product: HD USB Camera
Aug 21 12:47:25 raspberrypi kernel: [26519.978470] usb 1-1.5: Manufacturer: HD Camera Manufacturer
Aug 21 12:47:25 raspberrypi kernel: [26519.979367] uvcvideo: Found UVC 1.00 device HD USB Camera (05a3:9520)
Aug 21 12:47:25 raspberrypi kernel: [26520.110199] uvcvideo 1-1.5:1.0: Entity type for entity Extension 2 was not initialized!
Aug 21 12:47:25 raspberrypi kernel: [26520.110216] uvcvideo 1-1.5:1.0: Entity type for entity Processing 3 was not initialized!
Aug 21 12:47:25 raspberrypi kernel: [26520.110227] uvcvideo 1-1.5:1.0: Entity type for entity Camera 1 was not initialized!
Aug 21 12:47:25 raspberrypi kernel: [26520.110610] input: HD USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/1-1.5:1.0/input/input4
Aug 21 12:47:26 raspberrypi kernel: [26520.913119] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 21 12:47:26 raspberrypi kernel: [26520.913627] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
Aug 21 13:56:24 raspberrypi kernel: [30659.299377] usb usb1-port1: disabled by hub (EMI?), re-enabling...
Aug 21 13:56:24 raspberrypi kernel: [30659.299391] usb 1-1: USB disconnect, device number 18
Aug 21 13:56:24 raspberrypi kernel: [30659.299397] usb 1-1.1: USB disconnect, device number 19
Aug 21 13:56:24 raspberrypi kernel: [30659.299724] smsc95xx 1-1.1:1.0 eth0: unregister 'smsc95xx' usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet
Aug 21 13:56:24 raspberrypi kernel: [30659.299781] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 13:56:24 raspberrypi kernel: [30659.360239] usb 1-1.3: USB disconnect, device number 20
Aug 21 13:56:24 raspberrypi kernel: [30659.360385] cdc_acm 1-1.3:1.0: failed to set dtr/rts
Aug 21 13:56:24 raspberrypi kernel: [30659.361269] usb 1-1.5: USB disconnect, device number 21
Aug 21 13:56:24 raspberrypi kernel: [30659.559806] Indeed it is in host mode hprt0 = 00001501
Aug 21 13:56:25 raspberrypi kernel: [30659.769416] usb 1-1: new high-speed USB device number 22 using dwc_otg
Aug 21 13:56:25 raspberrypi kernel: [30659.769513] Indeed it is in host mode hprt0 = 00001101
Aug 21 13:56:25 raspberrypi kernel: [30660.009503] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Aug 21 13:56:25 raspberrypi kernel: [30660.009511] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 13:56:25 raspberrypi kernel: [30660.011332] hub 1-1:1.0: USB hub found
Aug 21 13:56:25 raspberrypi kernel: [30660.011392] hub 1-1:1.0: 5 ports detected
Aug 21 13:56:25 raspberrypi kernel: [30660.329331] usb 1-1.1: new high-speed USB device number 23 using dwc_otg
Aug 21 13:56:25 raspberrypi kernel: [30660.459471] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Aug 21 13:56:25 raspberrypi kernel: [30660.459480] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 13:56:25 raspberrypi kernel: [30660.466009] smsc95xx v1.0.6
Aug 21 13:56:25 raspberrypi kernel: [30660.551427] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f8:2f:76
Aug 21 13:56:26 raspberrypi kernel: [30660.649386] usb 1-1.3: new full-speed USB device number 24 using dwc_otg
Aug 21 13:56:26 raspberrypi kernel: [30660.711479] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 13:56:26 raspberrypi kernel: [30660.711809] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 21 13:56:26 raspberrypi kernel: [30660.787153] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=f058
Aug 21 13:56:26 raspberrypi kernel: [30660.787169] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 21 13:56:26 raspberrypi kernel: [30660.787178] usb 1-1.3: Product: Sensor S7 V1.0
Aug 21 13:56:26 raspberrypi kernel: [30660.787186] usb 1-1.3: Manufacturer: Agnetix Inc.
Aug 21 13:56:26 raspberrypi kernel: [30660.787195] usb 1-1.3: SerialNumber: EA2622F2D54C5490704C0403E12F2958
Aug 21 13:56:26 raspberrypi kernel: [30660.790140] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
Aug 21 13:56:26 raspberrypi kernel: [30661.099363] usb 1-1.5: new high-speed USB device number 25 using dwc_otg
Aug 21 13:56:26 raspberrypi kernel: [30661.234947] usb 1-1.5: New USB device found, idVendor=05a3, idProduct=9520
Aug 21 13:56:26 raspberrypi kernel: [30661.234960] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Aug 21 13:56:26 raspberrypi kernel: [30661.234969] usb 1-1.5: Product: HD USB Camera
Aug 21 13:56:26 raspberrypi kernel: [30661.234979] usb 1-1.5: Manufacturer: HD Camera Manufacturer
Aug 21 13:56:26 raspberrypi kernel: [30661.235879] uvcvideo: Found UVC 1.00 device HD USB Camera (05a3:9520)
Aug 21 13:56:26 raspberrypi kernel: [30661.366685] uvcvideo 1-1.5:1.0: Entity type for entity Extension 2 was not initialized!
Aug 21 13:56:26 raspberrypi kernel: [30661.366700] uvcvideo 1-1.5:1.0: Entity type for entity Processing 3 was not initialized!
Aug 21 13:56:26 raspberrypi kernel: [30661.366711] uvcvideo 1-1.5:1.0: Entity type for entity Camera 1 was not initialized!
Aug 21 13:56:26 raspberrypi kernel: [30661.367093] input: HD USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/1-1.5:1.0/input/input5
Aug 21 13:56:27 raspberrypi kernel: [30662.170555] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
Aug 21 13:56:27 raspberrypi kernel: [30662.172491] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 21 16:08:58 raspberrypi kernel: [38613.560486] usb usb1-port1: disabled by hub (EMI?), re-enabling...
Aug 21 16:08:58 raspberrypi kernel: [38613.560505] usb 1-1: USB disconnect, device number 22
Aug 21 16:08:58 raspberrypi kernel: [38613.560511] usb 1-1.1: USB disconnect, device number 23
Aug 21 16:08:58 raspberrypi kernel: [38613.560869] smsc95xx 1-1.1:1.0 eth0: unregister 'smsc95xx' usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet
Aug 21 16:08:58 raspberrypi kernel: [38613.560945] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 16:08:58 raspberrypi kernel: [38613.602262] usb 1-1.3: USB disconnect, device number 24
Aug 21 16:08:58 raspberrypi kernel: [38613.602433] cdc_acm 1-1.3:1.0: failed to set dtr/rts
Aug 21 16:08:58 raspberrypi kernel: [38613.603845] usb 1-1.5: USB disconnect, device number 25
Aug 21 16:08:59 raspberrypi kernel: [38613.810545] Indeed it is in host mode hprt0 = 00001501
Aug 21 16:08:59 raspberrypi kernel: [38614.030496] usb 1-1: new high-speed USB device number 26 using dwc_otg
Aug 21 16:08:59 raspberrypi kernel: [38614.030737] Indeed it is in host mode hprt0 = 00001101
Aug 21 16:08:59 raspberrypi kernel: [38614.270582] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
Aug 21 16:08:59 raspberrypi kernel: [38614.270589] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 16:08:59 raspberrypi kernel: [38614.272708] hub 1-1:1.0: USB hub found
Aug 21 16:08:59 raspberrypi kernel: [38614.272801] hub 1-1:1.0: 5 ports detected
Aug 21 16:08:59 raspberrypi kernel: [38614.590431] usb 1-1.1: new high-speed USB device number 27 using dwc_otg
Aug 21 16:09:00 raspberrypi kernel: [38614.720624] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Aug 21 16:09:00 raspberrypi kernel: [38614.720632] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Aug 21 16:09:00 raspberrypi kernel: [38614.727510] smsc95xx v1.0.6
Aug 21 16:09:00 raspberrypi kernel: [38614.822546] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f8:2f:76
Aug 21 16:09:00 raspberrypi kernel: [38614.920451] usb 1-1.3: new full-speed USB device number 28 using dwc_otg
Aug 21 16:09:00 raspberrypi kernel: [38614.961586] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Aug 21 16:09:00 raspberrypi kernel: [38614.961724] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 21 16:09:00 raspberrypi kernel: [38615.059355] usb 1-1.3: New USB device found, idVendor=04d8, idProduct=f058
Aug 21 16:09:00 raspberrypi kernel: [38615.059365] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 21 16:09:00 raspberrypi kernel: [38615.059370] usb 1-1.3: Product: Sensor S7 V1.0
Aug 21 16:09:00 raspberrypi kernel: [38615.059377] usb 1-1.3: Manufacturer: Agnetix Inc.
Aug 21 16:09:00 raspberrypi kernel: [38615.059382] usb 1-1.3: SerialNumber: EA2622F2D54C5490704C0403E12F2958
Aug 21 16:09:00 raspberrypi kernel: [38615.064312] cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device
Aug 21 16:09:00 raspberrypi kernel: [38615.370440] usb 1-1.5: new high-speed USB device number 29 using dwc_otg
Aug 21 16:09:00 raspberrypi kernel: [38615.505856] usb 1-1.5: New USB device found, idVendor=05a3, idProduct=9520
Aug 21 16:09:00 raspberrypi kernel: [38615.505866] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Aug 21 16:09:00 raspberrypi kernel: [38615.505871] usb 1-1.5: Product: HD USB Camera
Aug 21 16:09:00 raspberrypi kernel: [38615.505875] usb 1-1.5: Manufacturer: HD Camera Manufacturer
Aug 21 16:09:00 raspberrypi kernel: [38615.507622] uvcvideo: Found UVC 1.00 device HD USB Camera (05a3:9520)
Aug 21 16:09:01 raspberrypi kernel: [38615.638163] uvcvideo 1-1.5:1.0: Entity type for entity Extension 2 was not initialized!
Aug 21 16:09:01 raspberrypi kernel: [38615.638173] uvcvideo 1-1.5:1.0: Entity type for entity Processing 3 was not initialized!
Aug 21 16:09:01 raspberrypi kernel: [38615.638179] uvcvideo 1-1.5:1.0: Entity type for entity Camera 1 was not initialized!
Aug 21 16:09:01 raspberrypi kernel: [38615.638764] input: HD USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/1-1.5:1.0/input/input6
Aug 21 16:09:01 raspberrypi kernel: [38616.508753] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
Aug 21 16:09:01 raspberrypi kernel: [38616.513102] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 21 16:09:09 raspberrypi kernel: [38624.030448] usb 1-1.5: reset high-speed USB device number 29 using dwc_otg
Aug 21 16:09:09 raspberrypi kernel: [38624.165270] uvcvideo: Found UVC 1.00 device HD USB Camera (05a3:9520)
Aug 21 16:09:09 raspberrypi kernel: [38624.166532] uvcvideo 1-1.5:1.0: Entity type for entity Extension 2 was not initialized!
Aug 21 16:09:09 raspberrypi kernel: [38624.166539] uvcvideo 1-1.5:1.0: Entity type for entity Processing 3 was not initialized!
Aug 21 16:09:09 raspberrypi kernel: [38624.166544] uvcvideo 1-1.5:1.0: Entity type for entity Camera 1 was not initialized!
Aug 21 16:09:09 raspberrypi kernel: [38624.166737] input: HD USB Camera as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/1-1.5:1.0/input/input7
We have been able to see this with variable frequency on pretty much all Pi's.
We KNOW that the voltage is sufficient because we make the PSU, and set it to 5.25V and have lots of capacitance there too.
Kernel is 4.14.34-v7+ #1110
In the past we were able to trigger the disconnect 100% of the time by closing the camera port. We switched from doing that to leaving it open to mitigate the problem.
We have several issues at this point.
1) as you can see it appears the kernel input system resources do not seem to be freed...
2) the camera moves between video0 and video1, we chase it in our python script.
3) the network gets taken down at the same time causing a whole host of other issues.
we have tried it both stock and with dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xf. No difference.
If you would like our exercise script, please let me know, and I will send it.
noafterglow
on 21 Aug 2018
@noafterglow Thank you for your contribution to this issue! We worked around the problem exactly the same way. Since we need to grab frames, and stream video with different settings etc. I wrote a service that keeps the camera always running on MJPEG stream mode. Then another program can pipe these frames as input, using ffmpeg to generate either individual JPEG files, or e.g. a live H264 in TS stream - even at the same time. Using this modular approach, the webcam never needs to be disabled (and v4l2-ctl can change the settings in realtime), and actually gave the advantage of being able to take pictures at the same time as videostream etc etc.
Even though this workaround is stable, we would really prefer to keep power consumption down as we are using solar panels to power the system.
On the longer term, I also found that sometimes there are suddenly /dev/video0 and /dev/video1. But I think this is unrelated to this specific issue, since the camera is permanently enabled now. Additionally this did not interfere with our application.
Could you provide your exercise script? Not sure if your issue is actually related though, seeing your kernel logs. We did not find USB disconnects in our logs. I would lilke to try your script.
We are using ELP-USBFHD06H-L28 Sony IMX322 (lsusb: 05a3:9422 ARC International).
jetibest
on 21 Aug 2018
basically the camera was operated from cv2, with the following sequence (It was spread out over two files...:
self._capture = cv2.VideoCapture(port)
self.default_width = self._capture.get(CAP_PROP_FRAME_WIDTH)
self.default_height = self._capture.get(CAP_PROP_FRAME_HEIGHT)
self.default_fps = self._capture.get(CAP_PROP_FPS)
self._capture.set(CAP_PROP_FRAME_WIDTH, width)
self._capture.set(CAP_PROP_FRAME_HEIGHT, height)
self.width = self._capture.get(CAP_PROP_FRAME_WIDTH)
self.height = self._capture.get(CAP_PROP_FRAME_HEIGHT)
self.fps = self._capture.get(CAP_PROP_FPS)
for i in xrange(10):
self.grab()
_, image = self._capture.retrieve()
self._capture.release()
noafterglow
on 23 Aug 2018
The disconnect happens at release().
noafterglow
on 23 Aug 2018
@noafterglow this is a separate issue to the crash described above.
Aug 21 09:00:45 raspberrypi kernel: [12920.270759] usb usb1-port1: disabled by hub (EMI?), re-enabling...
External influence has caused a disconnect event on the root port of the USB controller. Poor quality power supplies, RF interference or electrostatic discharge events can all create conditions that result in a spurious disconnect.
Note that turning a webcam on/off will cause a significant change in power draw. A PSU with a badly tuned feedback arrangement may overshoot/undershoot a considerable amount. It would be worth monitoring the 5V and 3v3 pins on the GPIO header with an oscilloscope to rule out a gross PSU issue.
The null pointer dereference is more likely to be a genuine bug in uvcvideo and friends.
P33M
on 5 Oct 2018
The power supply is a 3A 5.25V supply with with a great feedback arrangement, and class B EMI components. I know because I designed it, and the test labs tested it, which is what I do all the time. This is NOT and EMI issue either, unless the Pi board itself is poorly designed. There is no way for the Pi to see any change in voltage as a result of the webcam being turned on and off. There is way too much capacitance there for the webcam's measly 100mA draw to make any difference. The camera is out of range of people touching it, so ESD is not it either. This is a bug.
I don't know what the Pi can do to make the root hub disconnect, but its doing it internally. The issue happens at different rates on different Pi's, some have a couple of times a day, some every few minutes, some go days between events. Mostly is a couple of times per day. It seems to follow the Pi, and not the location.
noafterglow
on 6 Nov 2018
In another attempt to fix this problem, I am going to modify the USB-driver configuration - apparently there are many options to try. More specifically, I will be changing the dwc_otg module (using modprobe or in /boot/cmdline.txt) parameters a.k.a. "DesignWare USB 2.0 OTG Controller (DWC_otg)".
References:
Parameter reference
Parameter reference specifically for BCM2708
"dwc_otg.fiq_fsm_enable=0 has fixed the crash, but the audio quality is still very poor with this device." - Issue 588: Kernel Oops when trying to record from USB Audio Mic
Obviously, messing with these parameters will require thorough testing, and many modifications may not work at all. Will report back in a few months.
@noafterglow this information may also be interesting to you.
jetibest
on 28 Nov 2018
Did the USB driver modifications work for resolving the issue?
ysirotin
on 23 Mar 2019
I have not investigated the issue in the last 6 months. We have just
loaded the latest kernel and will go looking at the logs again to see if
the problem persists.
Stay tuned.
Ihor Lys
617-470-2740
On Sat, Mar 23, 2019 at 7:42 AM ysirotin notifications@github.com wrote:
Did the USB driver modifications work for resolving the issue?
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/raspberrypi/linux/issues/2551#issuecomment-475875348,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AE1wwyvHY03JsJ-ejm9Dp_3QMPdaAaGsks5vZj1MgaJpZM4T8TOh
.
noafterglow
on 24 Mar 2019
We have narrowed a similar issue down specifically to the USB port used. When plugging the webcam into the 1-1.3 port on the 3B, we consistently get errors/resets like those documented above. However, when plugging a webcam into 1-1.4 port, we do not see the errors (or the errors are much more infrequent). I am honestly not sure what the difference is between these ports.
ysirotin
on 29 Mar 2019
Is it the specific ports or the relative position of the webcam compared to the other devices? With 2 devices and 4 ports you have 12 possible combinations.
pelwell
on 29 Mar 2019
We only have one thing (Logitech C920) plugged into the USB port of the Pi (no keyboard/mouse). We did not exhaustively test each port yet.
ysirotin
on 29 Mar 2019
I suspect that this is actually driven by an issue in the hub itself. This
may be why the Pi foundation dumped that part on the latest pi. The only
real way to know is to hook up a USB analyzer to both the internal port
which hooks to the hub as well as the port used for the webcam and look at
what happens during the event.
Now that that Pi is EOL, its over, and we only have the next version to
deal with.
On Fri, Mar 29, 2019, 05:56 ysirotin notifications@github.com wrote:
We only have one thing (Logitech C920) plugged into the USB port of the Pi
(no keyboard/mouse). We did not exhaustively test each port yet.—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/raspberrypi/linux/issues/2551#issuecomment-477987703,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AE1ww0zKzy1Wwij5l8mHsl_CCF2U32Yzks5vbg2RgaJpZM4T8TOh
.
noafterglow
on 29 Mar 2019
We didn't dump the part - still used on the Pi1, 2, and 3 which are still in production, not EOL. Yes, you can still get Pi 1 if you really want! For the Pi3B+ we simply moved to a part that supported gig ethernet.
JamesH65
on 29 Mar 2019
Ok. Then perhaps setting up a test system is worth it. As i
mentioned earlier, i have a 100% method for causing this problem, using
the shutoff of a webcam from user mode. I dont know if its the same
problem here, but it definitely has the same symptom. I dont have the
proper equipment to snoop the intermediate buses to see what actually
happens, but id bet that a day of work on that would probably be
very useful. Otherwise i fear that this is really nothing more than
guessing as to parameters i certainly dont understand.
I will set up my system and run it and let you know if the latest kernel
solves the problem. However, we are upgrading to to latest pi on our next
build, as well as moving the camera to the csi connector, so we wont see
this exact issue again.
On Fri, Mar 29, 2019, 08:38 James Hughes notifications@github.com wrote:
We didn't dump the part - still used on the Pi1, 2, and 3 which are still
in production, not EOL. Yes, you can still get Pi 1 if you really want! For
the Pi3B+ we simply moved to a part that supported gig ethernet.—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/raspberrypi/linux/issues/2551#issuecomment-478044155,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AE1wwyjT1sELQ3rks2jBGd0TWekFF8gjks5vbjNrgaJpZM4T8TOh
.
noafterglow
on 29 Mar 2019
In case it can be useful, I am having something very similar with an old Hauppage WinTV-USB (analog TV tuner, works as v4l2 device) that works flawlessly connected to any PC, but suffers the disabled by hub (EMI?), re-enabling... when used for streaming on either a Raspberri Pi 3A+ or a Raspberry Pi 3B+
I tried pretty much everything:
- Changing cables
- Changing power adapters
- Adding ferrite cores
- Buying a new MultiTT hub from UUGear.
- Changing to a Raspberry Pi 3B+ and connecting the device to one of the ports, without using any hub
- Playing with
cmdline.txtanddwc_otg
All of it on different combinations, including everthing at the same time.
My only conclusion is that, being a USB 1.0 (according to lsusb, that also shows it consumes max 200mA) is causing some kind of problems. Maybe what's described at https://www.raspberrypi.org/documentation/hardware/raspberrypi/usb/README.md#knownissues 2. USB 1.1 webcams (even if in my case the analog tuner provides only 320x240 video)
I'd rule any kind of real EMI problem as if I place the USB cable following the same path, but connected to a PC instead of connected to a Raspberry, things work fine, with or without ferrite beads.
The exact same setup using a Terratec Cinergy Hybrid T USB XS (USB 2.0, includes an analog TV tuner supported as v4l2 device, and consumes max 500mA) works just fine.
Not complaining! But if you need any more info, and you think it can be useful for this issue, just ping :-)
I wonder, is any one of the persons reporting problems using any USB 1.X device?
juliogonzalez
on 18 Aug 2020
Hi I know this is old but same issue here for months (Fedora Linux x86, not just Rpi). Happens randomly between boots, so I think it must be some kind of race condition. That and the C920 webcam isn't officially supported by Linux. Still nothing should ever cause a null dereference in the kernel.
Linux 5.8.18-200.fc32.x86_64 #1 SMP Mon Nov 2 19:49:11 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
jboero
on 12 Nov 2020
@jetibest I just found it. Who needs to check pointers before dereference right? Submitting a fix. The webcam might error (still not supported in Linux) but it won't Oops the kernel.
jboero
on 12 Nov 2020
That's in unmodified upstream code - have you passed it on to the correct upstream Linux mailing list?
JamesH65
on 12 Nov 2020
I figured it was. Still trying to hunt it down upstream. Hold on the PR for now thanks!
jboero
on 12 Nov 2020
get_maintainer.pl is your friend.
:~/linux$ ./scripts/get_maintainer.pl drivers/usb/core/usb.c
Greg Kroah-Hartman <[email protected]> (supporter:USB SUBSYSTEM,commit_signer:2/1=100%,authored:1/1=100%,added_lines:2/2=100%,removed_lines:3/3=100%)
Felipe Balbi <[email protected]> (commit_signer:1/1=100%)
[email protected] (open list:USB SUBSYSTEM)
[email protected] (open list)
[email protected] is the mailing list of last resort, so go for Greg KH and linux-usb initially.
6by9
on 12 Nov 2020
Yep thanks I've submitted and sent the email to the usb list.
https://github.com/torvalds/linux/commit/a40519014549f60969c8e67a2fd91426db05fe04
jboero
on 12 Nov 2020
Related issues
KevinStartup
·
6Comments
ensarkarabudak
·
7Comments
XECDesign
·
6Comments
mi-hol
·
8Comments
incyi
·
9Comments
Most helpful comment
Yep thanks I've submitted and sent the email to the usb list.
https://github.com/torvalds/linux/commit/a40519014549f60969c8e67a2fd91426db05fe04