watchdog caused traceback due to USB hang

[andersthomson]

Hi,

I've pi2 used as a headless tvheadend server with two tuners (so lots of USB traffic). Every so often (after a day or two) I get hard hangs of all USB traffic which has prompted me to manually reboot the thing.

I've now enabled the watchdog, configured reboot on panic and gotten myself a serial cable and I now start to see results.

Attached is a large log of where the USB goes south and eventually I get a kernel backtrace triggered by a watchdog codepath somehow.

Any ideas how to fix this?
(grep for 'cut here' for the kernel bits)

crashreport.txt

[popcornmix]

How did you enable the watchdog?
This look suspicious

Sep 22 18:06:13 rpi2 systemd-shutdow[1]: Failed to set timeout to 600s: Invalid argument

The hardware watchdog is limited to around 30 seconds I believe due the number of bits in the hardware countdown timer. Ten minutes is very long for a watchdog timeout. 10 seconds would be a more common value.

[lategoodbye]

@andersthomson
Please provide a lsusb -t output of the affected setup.
Are you able to narrow down the affected setup to a minimum setup of connected USB devices?

[andersthomson]

watchdog is enabled as with the systemd unit, which exec's /usr/sbin/watchdog

 cat /etc/watchdog.conf 
#ping                   = 172.31.14.1
#ping                   = 192.168.1.1
#ping                   = 172.26.1.255
#interface              = eth0
#file                   = /var/log/messages
#change                 = 1407

# Uncomment to enable test. Setting one of these values to '0' disables it.
# These values will hopefully never reboot your machine during normal use
# (if your machine is really hung, the loadavg will go much higher than 25)
max-load-1              = 24
#max-load-5             = 18
#max-load-15            = 12

# Note that this is the number of pages!
# To get the real size, check how large the pagesize is on your machine.
min-memory              = 1
allocatable-memory      = 1

#repair-binary          = /usr/sbin/repair
#repair-timeout         = 
#test-binary            = 
#test-timeout           = 

watchdog-device = /dev/watchdog
watchdog-timeout = 15

# Defaults compiled into the binary
#temperature-device     =
temperature-device = /sys/class/thermal/thermal_zone0/temp
#max-temperature        = 120
max-temperature = 51000

# Defaults compiled into the binary
admin                   = root
interval                = 1
logtick                = 1
log-dir         = /var/log/watchdog

# This greatly decreases the chance that watchdog won't be scheduled before
# your machine is really loaded
realtime                = yes
priority                = 1

# Check if rsyslogd is still running by enabling the following line
#pidfile                = /var/run/rsyslogd.pid   

[andersthomson]

lsusb -t
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
|__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/5p, 480M
|__ Port 1: Dev 3, If 0, Class=Vendor Specific Class, Driver=smsc95xx, 480M
|__ Port 2: Dev 4, If 0, Class=Hub, Driver=hub/7p, 480M
|__ Port 2: Dev 6, If 0, Class=Vendor Specific Class, Driver=em28xx, 480M
|__ Port 3: Dev 5, If 0, Class=Hub, Driver=hub/4p, 480M
|__ Port 1: Dev 7, If 0, Class=Hub, Driver=hub/4p, 480M
|__ Port 1: Dev 9, If 0, Class=Vendor Specific Class, Driver=em28xx, 480M
|__ Port 2: Dev 11, If 0, Class=Vendor Specific Class, Driver=usbfs, 12M
|__ Port 4: Dev 8, If 0, Class=Hub, Driver=hub/4p, 480M
|__ Port 1: Dev 10, If 0, Class=Vendor Specific Class, Driver=ftdi_sio, 12M
|__ Port 4: Dev 12, If 0, Class=Mass Storage, Driver=usb-storage, 480M

[andersthomson]

My "is things in a stable state?" script detected this in dmesg yesterday, which also points to the watchdog.

[ 0.000000] Booting Linux on physical CPU 0xf00
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 4.4.15-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #897 SMP Tue Jul 12 18:42:55 BST 2016
[ 0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] Machine model: Raspberry Pi 2 Model B Rev 1.1
[ 0.000000] cma: Reserved 8 MiB at 0x3a800000
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] On node 0 totalpages: 241664
[ 0.000000] free_area_init_node: node 0, pgdat 808c0e00, node_mem_map b9fa6000
[ 0.000000] Normal zone: 2124 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 241664 pages, LIFO batch:31
[ 0.000000] [bcm2709_smp_init_cpus] enter (9520->f3003010)
[ 0.000000] [bcm2709_smp_init_cpus] ncores=4
[ 0.000000] PERCPU: Embedded 13 pages/cpu @b9f63000 s22592 r8192 d22464 u53248
[ 0.000000] pcpu-alloc: s22592 r8192 d22464 u53248 alloc=13*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 239540
[ 0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2709.boardrev=0xa01041 bcm2709.serial=0x9aa48012 smsc95xx.macaddr=B8:27:EB:A4:80:12 bcm2708_fb.fbswap=1 bcm2709.uart_clock=3000000 bcm2709.disk_led_gpio=47 bcm2709.disk_led_active_low=0 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000 root=/dev/mmcblk0p4 smsc95xx.turbo_mode=N rootdelay=2 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 init=/usr/lib/systemd/systemd ro
[ 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: 939088K/966656K available (6344K kernel code, 432K rwdata, 1712K rodata, 476K init, 764K bss, 19376K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xbb800000 - 0xff800000 (1088 MB)
lowmem : 0x80000000 - 0xbb000000 ( 944 MB)
modules : 0x7f000000 - 0x80000000 ( 16 MB)
.text : 0x80008000 - 0x807e6470 (8058 kB)
.init : 0x807e7000 - 0x8085e000 ( 476 kB)
.data : 0x8085e000 - 0x808ca108 ( 433 kB)
.bss : 0x808cd000 - 0x8098c1ac ( 765 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] Build-time adjustment of leaf fanout to 32.
[ 0.000000] NR_IRQS:16 nr_irqs:16 16
[ 0.000000] Architected 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.000011] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000031] Switching to timer-based delay loop, resolution 52ns
[ 0.000349] Console: colour dummy device 80x30
[ 0.000386] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[ 0.000412] pid_max: default: 32768 minimum: 301
[ 0.000802] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000824] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.002003] Disabling cpuset control group subsystem
[ 0.002049] Initializing cgroup subsys io
[ 0.002085] Initializing cgroup subsys memory
[ 0.002140] Initializing cgroup subsys devices
[ 0.002166] Initializing cgroup subsys freezer
[ 0.002192] Initializing cgroup subsys net_cls
[ 0.002262] CPU: Testing write buffer coherency: ok
[ 0.002348] ftrace: allocating 21209 entries in 63 pages
[ 0.054644] CPU0: update cpu_capacity 1024
[ 0.054683] CPU0: thread -1, cpu 0, socket 15, mpidr 80000f00
[ 0.054699] [bcm2709_smp_prepare_cpus] enter
[ 0.054835] Setting up static identity map for 0x8240 - 0x8274
[ 0.057213] [bcm2709_boot_secondary] cpu:1 started (0) 17
[ 0.057643] [bcm2709_secondary_init] enter cpu:1
[ 0.057702] CPU1: update cpu_capacity 1024
[ 0.057710] CPU1: thread -1, cpu 1, socket 15, mpidr 80000f01
[ 0.058283] [bcm2709_boot_secondary] cpu:2 started (0) 17
[ 0.058636] [bcm2709_secondary_init] enter cpu:2
[ 0.058668] CPU2: update cpu_capacity 1024
[ 0.058676] CPU2: thread -1, cpu 2, socket 15, mpidr 80000f02
[ 0.059217] [bcm2709_boot_secondary] cpu:3 started (0) 18
[ 0.059471] [bcm2709_secondary_init] enter cpu:3
[ 0.059499] CPU3: update cpu_capacity 1024
[ 0.059507] CPU3: thread -1, cpu 3, socket 15, mpidr 80000f03
[ 0.059596] Brought up 4 CPUs
[ 0.059626] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.059636] CPU: All CPU(s) started in HYP mode.
[ 0.059645] CPU: Virtualization extensions available.
[ 0.060557] devtmpfs: initialized
[ 0.073059] VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
[ 0.073517] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.074563] pinctrl core: initialized pinctrl subsystem
[ 0.075348] NET: Registered protocol family 16
[ 0.081083] DMA: preallocated 4096 KiB pool for atomic coherent allocations
[ 0.089191] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.089211] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.089415] Serial: AMBA PL011 UART driver
[ 0.089743] 3f201000.uart: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 0.588754] console [ttyAMA0] enabled
[ 0.593041] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.672384] bcm2835-dma 3f007000.dma: DMA legacy API manager at f3007000, dmachans=0x1
[ 0.681064] SCSI subsystem initialized
[ 0.685036] usbcore: registered new interface driver usbfs
[ 0.690657] usbcore: registered new interface driver hub
[ 0.696111] usbcore: registered new device driver usb
[ 0.711255] raspberrypi-firmware soc:firmware: Attached to firmware from 2016-07-15 17:50
[ 0.746937] clocksource: Switched to clocksource arch_sys_counter
[ 0.806132] FS-Cache: Loaded
[ 0.809457] CacheFiles: Loaded
[ 0.828931] NET: Registered protocol family 2
[ 0.834524] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.841738] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.848382] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.854875] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.860873] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.867571] NET: Registered protocol family 1
[ 0.872430] RPC: Registered named UNIX socket transport module.
[ 0.878384] RPC: Registered udp transport module.
[ 0.883081] RPC: Registered tcp transport module.
[ 0.887802] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.895413] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available
[ 0.905294] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.927779] VFS: Disk quotas dquot_6.6.0
[ 0.932099] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.941892] FS-Cache: Netfs 'nfs' registered for caching
[ 0.948391] NFS: Registering the id_resolver key type
[ 0.953496] Key type id_resolver registered
[ 0.957710] Key type id_legacy registered
[ 0.964992] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[ 0.972624] io scheduler noop registered
[ 0.976555] io scheduler deadline registered
[ 0.980926] io scheduler cfq registered (default)
[ 0.988618] BCM2708FB: allocated DMA memory fac00000
[ 0.993612] BCM2708FB: allocated DMA channel 0 @ f3007000
[ 1.004940] Console: switching to colour frame buffer device 82x26
[ 1.015325] KGDB: Registered I/O driver kgdboc
[ 2.090000] bcm2835-rng 3f104000.rng: hwrng registered
[ 2.095298] vc-cma: Videocore CMA driver
[ 2.099256] vc-cma: vc_cma_base = 0x00000000
[ 2.103954] vc-cma: vc_cma_size = 0x00000000 (0 MiB)
[ 2.109370] vc-cma: vc_cma_initial = 0x00000000 (0 MiB)
[ 2.115074] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
[ 2.143978] brd: module loaded
[ 2.158356] loop: module loaded
[ 2.162591] vchiq: vchiq_init_state: slot_zero = 0xbac80000, is_master = 0
[ 2.171231] Loading iSCSI transport class v2.0-870.
[ 2.177056] usbcore: registered new interface driver smsc95xx
[ 2.182873] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 2.389062] Core Release: 2.80a
[ 2.392216] Setting default values for core params
[ 2.397057] Finished setting default values for core params
[ 2.603034] Using Buffer DMA mode
[ 2.606346] Periodic Transfer Interrupt Enhancement - disabled
[ 2.612190] Multiprocessor Interrupt Enhancement - disabled
[ 2.617775] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 2.622130] Dedicated Tx FIFOs mode
[ 2.626065] WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xbac14000 dma = 0xfac14000 len=9024
[ 2.635939] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 2.658285] dwc_otg: Microframe scheduler enabled
[ 2.658358] WARN::hcd_init_fiq:413: FIQ on core 1 at 0x80446aa0
[ 2.664276] WARN::hcd_init_fiq:414: FIQ ASM at 0x80446e10 length 36
[ 2.670538] WARN::hcd_init_fiq:439: MPHI regs_base at 0xbb87e000
[ 2.676612] dwc_otg 3f980000.usb: DWC OTG Controller
[ 2.681636] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 2.688999] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 2.694608] Init: Port Power? op_state=1
[ 2.698549] Init: Power Port (0)
[ 2.702068] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 2.708882] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 2.716097] usb usb1: Product: DWC OTG Controller
[ 2.720820] usb usb1: Manufacturer: Linux 4.4.15-v7+ dwc_otg_hcd
[ 2.726821] usb usb1: SerialNumber: 3f980000.usb
[ 2.732509] hub 1-0:1.0: USB hub found
[ 2.736311] hub 1-0:1.0: 1 port detected
[ 2.741046] dwc_otg: FIQ enabled
[ 2.741060] dwc_otg: NAK holdoff enabled
[ 2.741070] dwc_otg: FIQ split-transaction FSM enabled
[ 2.741112] Module dwc_common_port init
[ 2.741537] usbcore: registered new interface driver usb-storage
[ 2.747937] mousedev: PS/2 mouse device common for all mice
[ 2.754337] bcm2835-cpufreq: min=600000 max=900000
[ 2.759489] sdhci: Secure Digital Host Controller Interface driver
[ 2.765660] sdhci: Copyright(c) Pierre Ossman
[ 2.770424] sdhost: log_buf @ bac13000 (fac13000)
[ 2.846979] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 2.872981] sdhci-pltfm: SDHCI platform and OF driver helper
[ 2.879372] ledtrig-cpu: registered to indicate activity on CPUs
[ 2.885604] hidraw: raw HID events driver (C) Jiri Kosina
[ 2.891290] usbcore: registered new interface driver usbhid
[ 2.896854] usbhid: USB HID core driver
[ 2.901377] Initializing XFRM netlink socket
[ 2.905694] NET: Registered protocol family 17
[ 2.910328] Key type dns_resolver registered
[ 2.915113] Registering SWP/SWPB emulation handler
[ 2.921100] registered taskstats version 1
[ 2.925454] vc-sm: Videocore shared memory driver
[ 2.930216] [vc_sm_connected_init]: start
[ 2.934911] [vc_sm_connected_init]: end - returning 0
[ 2.940167] Indeed it is in host mode hprt0 = 00021501
[ 2.947405] of_cfs_init
[ 2.950004] of_cfs_init: OK
[ 2.953763] uart-pl011 3f201000.uart: no DMA platform data
[ 2.954482] mmc0: host does not support reading read-only switch, assuming write-enable
[ 2.956610] mmc0: new high speed SDHC card at address 59b4
[ 2.957708] mmcblk0: mmc0:59b4 USD 7.51 GiB
[ 2.967080] mmcblk0: p1 p2 p3 p4
[ 2.980606] Waiting 2 sec before mounting root device...
[ 3.126988] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 3.133594] Indeed it is in host mode hprt0 = 00001101
[ 3.337283] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[ 3.343997] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 3.352178] hub 1-1:1.0: USB hub found
[ 3.356021] hub 1-1:1.0: 5 ports detected
[ 3.636974] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 3.757235] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[ 3.764107] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 3.774349] smsc95xx v1.0.4
[ 3.840843] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:a4:80:12
[ 3.946974] usb 1-1.2: new high-speed USB device number 4 using dwc_otg
[ 4.067445] usb 1-1.2: New USB device found, idVendor=1a40, idProduct=0201
[ 4.074335] usb 1-1.2: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 4.081685] usb 1-1.2: Product: USB 2.0 Hub [MTT]
[ 4.087335] hub 1-1.2:1.0: USB hub found
[ 4.091372] hub 1-1.2:1.0: 7 ports detected
[ 4.176973] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
[ 4.297299] usb 1-1.3: New USB device found, idVendor=0409, idProduct=005a
[ 4.304171] usb 1-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 4.312632] hub 1-1.3:1.0: USB hub found
[ 4.316650] hub 1-1.3:1.0: 4 ports detected
[ 4.386975] usb 1-1.2.2: new high-speed USB device number 6 using dwc_otg
[ 4.507750] usb 1-1.2.2: New USB device found, idVendor=2013, idProduct=025f
[ 4.514795] usb 1-1.2.2: New USB device strings: Mfr=3, Product=1, SerialNumber=2
[ 4.522303] usb 1-1.2.2: Product: PCTV 292e
[ 4.526484] usb 1-1.2.2: Manufacturer: PCTV
[ 4.530688] usb 1-1.2.2: SerialNumber: 0011412129
[ 4.626973] usb 1-1.3.1: new high-speed USB device number 7 using dwc_otg
[ 4.747285] usb 1-1.3.1: New USB device found, idVendor=0409, idProduct=005a
[ 4.754331] usb 1-1.3.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 4.762660] hub 1-1.3.1:1.0: USB hub found
[ 4.766883] hub 1-1.3.1:1.0: 4 ports detected
[ 4.866974] usb 1-1.3.4: new high-speed USB device number 8 using dwc_otg
[ 4.987478] usb 1-1.3.4: New USB device found, idVendor=0409, idProduct=005a
[ 4.994580] usb 1-1.3.4: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 4.994650] EXT4-fs (mmcblk0p4): couldn't mount as ext3 due to feature incompatibilities
[ 5.002187] EXT4-fs (mmcblk0p4): couldn't mount as ext2 due to feature incompatibilities
[ 5.019602] hub 1-1.3.4:1.0: USB hub found
[ 5.023871] hub 1-1.3.4:1.0: 4 ports detected
[ 5.023902] EXT4-fs (mmcblk0p4): INFO: recovery required on readonly filesystem
[ 5.023909] EXT4-fs (mmcblk0p4): write access will be enabled during recovery
[ 5.076993] usb 1-1.3.1.1: new high-speed USB device number 9 using dwc_otg
[ 5.197939] usb 1-1.3.1.1: New USB device found, idVendor=2013, idProduct=024f
[ 5.205221] usb 1-1.3.1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 5.212949] usb 1-1.3.1.1: Product: PCTV 290e
[ 5.217372] usb 1-1.3.1.1: Manufacturer: PCTV Systems
[ 5.222472] usb 1-1.3.1.1: SerialNumber: 00000010VKB7
[ 5.307111] usb 1-1.3.1.2: new full-speed USB device number 10 using dwc_otg
[ 5.425728] EXT4-fs (mmcblk0p4): orphan cleanup on readonly fs
[ 5.431799] EXT4-fs (mmcblk0p4): 1 orphan inode deleted
[ 5.437060] EXT4-fs (mmcblk0p4): recovery complete
[ 5.454677] usb 1-1.3.1.2: New USB device found, idVendor=1781, idProduct=0c31
[ 5.461955] usb 1-1.3.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 5.469644] usb 1-1.3.1.2: Product: TellStick Duo
[ 5.474346] usb 1-1.3.1.2: Manufacturer: Telldus
[ 5.479002] usb 1-1.3.1.2: SerialNumber: A703AJYN
[ 5.499814] EXT4-fs (mmcblk0p4): mounted filesystem with ordered data mode. Opts: (null)
[ 5.507996] VFS: Mounted root (ext4 filesystem) readonly on device 179:4.
[ 5.515650] devtmpfs: mounted
[ 5.519459] Freeing unused kernel memory: 476K (807e7000 - 8085e000)
[ 5.537031] usb 1-1.3.4.1: new full-speed USB device number 11 using dwc_otg
[ 5.661338] usb 1-1.3.4.1: New USB device found, idVendor=0403, idProduct=6001
[ 5.668681] usb 1-1.3.4.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 5.676381] usb 1-1.3.4.1: Product: Smartreader2 plus
[ 5.681532] usb 1-1.3.4.1: Manufacturer: Argolis BV
[ 5.686461] usb 1-1.3.4.1: SerialNumber:
[ 5.787012] usb 1-1.3.4.4: new high-speed USB device number 12 using dwc_otg
[ 5.908279] usb 1-1.3.4.4: New USB device found, idVendor=04e8, idProduct=61b5
[ 5.915570] usb 1-1.3.4.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 5.923320] usb 1-1.3.4.4: Product: Samsung M3 Portable
[ 5.928570] usb 1-1.3.4.4: Manufacturer: Samsung M3 Portable
[ 5.934299] usb 1-1.3.4.4: SerialNumber: 0A247DF106000060
[ 5.941455] usb-storage 1-1.3.4.4:1.0: USB Mass Storage device detected
[ 5.949132] scsi host0: usb-storage 1-1.3.4.4:1.0
[ 5.971529] NET: Registered protocol family 10
[ 5.979343] systemd[1]: Failed to insert module 'kdbus': Function not implemented
[ 6.001018] random: systemd urandom read with 79 bits of entropy available
[ 6.034445] systemd[1]: systemd 228 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT +GNUTLS -ACL -XZ +LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN)
[ 6.053412] systemd[1]: Detected architecture arm.
[ 6.078043] systemd[1]: Set hostname to <rpi2.lan>.
[ 6.930358] systemd[1]: rpc-gssd.service: Cannot add dependency job, ignoring: Unit rpc-gssd.service failed to load: No such file or directory.
[ 6.943355] systemd[1]: rpc-svcgssd.service: Cannot add dependency job, ignoring: Unit rpc-svcgssd.service failed to load: No such file or directory.
[ 6.948255] scsi 0:0:0:0: Direct-Access Samsung M3 Portable 1404 PQ: 0 ANSI: 6
[ 6.949764] sd 0:0:0:0: [sda] 3907029168 512-byte logical blocks: (2.00 TB/1.82 TiB)
[ 6.950187] sd 0:0:0:0: [sda] Write Protect is off
[ 6.950204] sd 0:0:0:0: [sda] Mode Sense: 33 00 00 08
[ 6.950603] sd 0:0:0:0: [sda] No Caching mode page found
[ 6.950614] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 6.989027] systemd[1]: gssproxy.service: Cannot add dependency job, ignoring: Unit gssproxy.service failed to load: No such file or directory.
[ 7.002786] systemd[1]: display-manager.service: Cannot add dependency job, ignoring: Unit display-manager.service failed to load: No such file or directory.
[ 7.023824] systemd[1]: Listening on Network Service Netlink Socket.
[ 7.047277] systemd[1]: Reached target Host and Network Name Lookups.
[ 7.079965] systemd[1]: Created slice User and Session Slice.
[ 7.124696] systemd[1]: Listening on udev Kernel Socket.
[ 7.147580] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 7.177501] systemd[1]: Listening on Journal Socket (/dev/log).
[ 7.205919] sda: sda1 sda2 sda3 sda4 < sda5 sda6 >
[ 7.215137] sd 0:0:0:0: [sda] Attached SCSI disk
[ 7.227289] systemd[1]: Reached target Remote File Systems.
[ 7.247459] systemd[1]: Listening on udev Control Socket.
[ 7.268273] systemd[1]: Created slice System Slice.
[ 7.288333] systemd[1]: Created slice system-serial\x2dgetty.slice.
[ 7.317214] systemd[1]: Reached target Slices.
[ 7.338154] systemd[1]: Created slice system-getty.slice.
[ 7.367523] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[ 7.397176] systemd[1]: Reached target Paths.
[ 7.418183] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 7.447502] systemd[1]: Listening on Journal Socket.
[ 7.497909] systemd[1]: Starting Setup Virtual Console...
[ 7.522007] systemd[1]: Starting Journal Service...
[ 7.551979] systemd[1]: Starting File System Check on Root Device...
[ 7.582506] systemd[1]: Mounting Debug File System...
[ 7.612034] systemd[1]: Mounting POSIX Message Queue File System...
[ 7.633571] systemd[1]: Mounting Temporary Directory...
[ 7.645986] systemd[1]: Mounting NFSD configuration filesystem...
[ 7.670642] systemd[1]: Starting Apply Kernel Variables...
[ 7.684887] systemd[1]: Mounting Configuration File System...
[ 7.696051] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 7.708823] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[ 7.723138] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[ 7.750780] systemd[1]: Set up automount var-lib-media.automount.
[ 7.765152] systemd[1]: Set up automount var-lib-timeshift.automount.
[ 7.772393] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[ 7.877779] systemd[1]: Mounting RPC Pipe File System...
[ 7.912045] systemd[1]: Mounted RPC Pipe File System.
[ 7.937424] systemd[1]: Mounted NFSD configuration filesystem.
[ 7.967379] systemd[1]: Mounted Debug File System.
[ 7.987289] systemd[1]: Mounted Configuration File System.
[ 8.007289] systemd[1]: Mounted POSIX Message Queue File System.
[ 8.037262] systemd[1]: Mounted Temporary Directory.
[ 8.057808] systemd[1]: Started Journal Service.
[ 8.775275] EXT4-fs (mmcblk0p4): re-mounted. Opts: user_xattr
[ 9.331359] systemd-journald[111]: Received request to flush runtime journal from PID 1
[ 9.364266] systemd-journald[111]: File /var/log/journal/18e841ae3401834bac9a7b7f552c54e2/system.journal corrupted or uncleanly shut down, renaming and replacing.
[ 10.089576] random: nonblocking pool is initialized
[ 10.199628] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 10.245672] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 10.385946] usbcore: registered new interface driver usbserial
[ 10.399084] usbcore: registered new interface driver usbserial_generic
[ 10.409668] usbserial: USB Serial support registered for generic
[ 10.443192] usbcore: registered new interface driver ftdi_sio
[ 10.451120] usbserial: USB Serial support registered for FTDI USB Serial Device
[ 10.461017] ftdi_sio 1-1.3.4.1:1.0: FTDI USB Serial Device converter detected
[ 10.469049] usb 1-1.3.4.1: Detected FT232BM
[ 10.475270] usb 1-1.3.4.1: FTDI USB Serial Device converter now attached to ttyUSB0
[ 10.509596] media: Linux media interface: v0.10
[ 10.576063] Linux video capture interface: v2.00
[ 10.663423] em28xx: New device PCTV PCTV 292e @ 480 Mbps (2013:025f, interface 0, class 0)
[ 10.671845] em28xx: DVB interface 0 found: isoc
[ 10.697060] em28xx: chip ID is em28178
[ 10.945462] Adding 538620k swap on /dev/mmcblk0p2. Priority:-1 extents:1 across:538620k SSFS
[ 11.164544] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: user_xattr
[ 11.511128] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com
[ 12.708036] em28178 #0: EEPROM ID = 26 00 01 00, EEPROM hash = 0x1f10fa04
[ 12.714859] em28178 #0: EEPROM info:
[ 12.718543] em28178 #0: microcode start address = 0x0004, boot configuration = 0x01
[ 12.733950] em28178 #0: AC97 audio (5 sample rates)
[ 12.738994] em28178 #0: 500mA max power
[ 12.742955] em28178 #0: Table at offset 0x27, strings=0x146a, 0x1888, 0x0a7e
[ 12.750483] em28178 #0: Identified as PCTV tripleStick (292e) (card=94)
[ 12.757174] em28178 #0: dvb set to isoc mode.
[ 12.761965] em28xx: New device PCTV Systems PCTV 290e @ 480 Mbps (2013:024f, interface 0, class 0)
[ 12.771032] em28xx: DVB interface 0 found: isoc
[ 12.775889] em28xx: chip ID is em28174
[ 13.138732] em28174 #1: EEPROM ID = 26 00 01 00, EEPROM hash = 0x11372abd
[ 13.145939] em28174 #1: EEPROM info:
[ 13.149770] em28174 #1: microcode start address = 0x0004, boot configuration = 0x01
[ 13.185087] em28174 #1: No audio on board.
[ 13.189408] em28174 #1: 500mA max power
[ 13.193368] em28174 #1: Table at offset 0x39, strings=0x1aa0, 0x14ba, 0x1ace
[ 13.200966] em28174 #1: Identified as PCTV nanoStick T2 290e (card=78)
[ 13.207571] em28174 #1: dvb set to isoc mode.
[ 13.209233] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
[ 13.225072] usbcore: registered new interface driver em28xx
[ 13.239341] em28178 #0: Binding DVB extension
[ 13.279789] i2c i2c-4: Added multiplexed i2c bus 7
[ 13.284810] si2168 4-0064: Silicon Labs Si2168 successfully attached
[ 13.296621] IPv6: ADDRCONF(NETDEV_UP): br0: link is not ready
[ 13.309287] IPv6: ADDRCONF(NETDEV_UP): veth-osc: link is not ready
[ 13.314888] si2157 7-0060: Silicon Labs Si2147/2148/2157/2158 successfully attached
[ 13.314936] DVB: registering new adapter (em28178 #0)
[ 13.314964] usb 1-1.2.2: DVB: registering adapter 0 frontend 0 (Silicon Labs Si2168)...
[ 13.319928] em28178 #0: DVB extension successfully initialized
[ 13.319941] em28174 #1: Binding DVB extension
[ 13.354112] device veth-osc-br entered promiscuous mode
[ 13.369347] IPv6: ADDRCONF(NETDEV_UP): veth-tvh: link is not ready
[ 13.382592] device veth-tvh-br entered promiscuous mode
[ 13.383822] tda18271 6-0060: creating new instance
[ 13.398462] TDA18271HD/C2 detected @ 6-0060
[ 13.402456] device eth0 entered promiscuous mode
[ 13.415371] br0: port 1(veth-osc-br) entered forwarding state
[ 13.421331] br0: port 1(veth-osc-br) entered forwarding state
[ 13.427860] IPv6: ADDRCONF(NETDEV_CHANGE): veth-osc: link becomes ready
[ 13.434718] IPv6: ADDRCONF(NETDEV_CHANGE): br0: link becomes ready
[ 13.449935] br0: port 2(veth-tvh-br) entered forwarding state
[ 13.455749] br0: port 2(veth-tvh-br) entered forwarding state
[ 13.461972] IPv6: ADDRCONF(NETDEV_CHANGE): veth-tvh: link becomes ready
[ 13.531358] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[ 13.539423] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 13.789257] DVB: registering new adapter (em28174 #1)
[ 13.794634] usb 1-1.3.1.1: DVB: registering adapter 1 frontend 0 (Sony CXD2820R)...
[ 13.819980] em28174 #1: DVB extension successfully initialized
[ 13.827220] em28xx: Registered (Em28xx dvb Extension) extension
[ 13.881668] em28178 #0: Registering input extension
[ 13.927050] Registered IR keymap rc-pinnacle-pctv-hd
[ 13.933911] input: em28xx IR (em28178 #0) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.2/rc/rc0/input0
[ 13.947773] rc0: em28xx IR (em28178 #0) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.2/rc/rc0
[ 13.958470] em28178 #0: Input extension successfully initalized
[ 13.964469] em28174 #1: Registering input extension
[ 13.972785] Registered IR keymap rc-pinnacle-pctv-hd
[ 13.979297] input: em28xx IR (em28174 #1) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.1/1-1.3.1.1/rc/rc1/input1
[ 13.991473] rc1: em28xx IR (em28174 #1) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.1/1-1.3.1.1/rc/rc1
[ 14.003139] em28174 #1: Input extension successfully initalized
[ 14.009251] em28xx: Registered (Em28xx Input Extension) extension
[ 15.084857] smsc95xx 1-1.1:1.0 eth0: kevent 4 may have been dropped
[ 15.098531] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 15.105435] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
[ 15.116285] br0: port 3(eth0) entered forwarding state
[ 15.121636] br0: port 3(eth0) entered forwarding state
[ 15.522500] EXT4-fs (dm-6): mounted filesystem with ordered data mode. Opts: (null)
[ 15.562494] EXT4-fs (dm-7): mounted filesystem with ordered data mode. Opts: (null)
[ 16.134522] EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null)
[ 16.480937] EXT4-fs (dm-4): mounted filesystem with ordered data mode. Opts: (null)
[ 16.966283] EXT4-fs (dm-5): mounted filesystem with ordered data mode. Opts: (null)
[ 17.704661] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[ 17.842910] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
[ 17.851836] NFSD: starting 90-second grace period (net 808b7000)
[ 21.259298] tda18271: performing RF tracking filter calibration
[ 23.920664] tda18271: RF tracking filter calibration complete
[ 23.927927] usb 1-1.3.1.1: DVB: adapter 1 frontend 0 frequency 0 out of range (45000000..864000000)
[ 23.951655] si2168 4-0064: found a 'Silicon Labs Si2168-B40'
[ 23.961790] si2168 4-0064: downloading firmware from file 'dvb-demod-si2168-b40-01.fw'
[ 24.315230] si2168 4-0064: firmware version: 4.0.11
[ 24.324965] si2157 7-0060: found a 'Silicon Labs Si2157-A30'
[ 24.379157] si2157 7-0060: firmware version: 3.0.5
[ 24.384040] usb 1-1.2.2: DVB: adapter 0 frontend 0 frequency 0 out of range (55000000..862000000)
[ 28.447010] br0: port 1(veth-osc-br) entered forwarding state
[ 28.486952] br0: port 2(veth-tvh-br) entered forwarding state
[ 28.579625] TCP: request_sock_TCP: Possible SYN flooding on port 80. Sending cookies. Check SNMP counters.
[ 30.126947] br0: port 3(eth0) entered forwarding state
[60700.408873] ------------[ cut here ]------------
[60700.413587] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:306 dev_watchdog+0x2a4/0x2b0()
[60700.422173] NETDEV WATCHDOG: eth0 (smsc95xx): transmit queue 0 timed out
[60700.428976] Modules linked in: evdev rc_pinnacle_pctv_hd em28xx_rc rc_core tda18271 cxd2820r si2157 si2168 i2c_mux em28xx_dvb bridge stp llc veth dvb_core dm_mod em28xx tveeprom v4l2_common videodev media ftdi_sio usbserial bcm2835_wdt bcm2835_gpiomem uio_pdrv_genirq uio sch_fq_codel nfsd ipv6
[60700.429154] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.4.15-v7+ #897
[60700.429158] Hardware name: BCM2709
[60700.429204] <80018724> from <80014058>
[60700.429227] <80014058> from <80320764>
[60700.429250] <80320764> from <80025300>
[60700.429270] <80025300> from <80025370>
[60700.429288] <80025370> from <804f87c8>
[60700.429306] <804f87c8> from <80081be4>
[60700.429322] <80081be4> from <80081f04>
[60700.429338] <80081f04> from <80029050>
[60700.429353] <80029050> from <80029630>
[60700.429371] <80029630> from <800710a8>
[60700.429391] <800710a8> from <80010a74>
[60700.429408] <80010a74> from <8000951c>
[60700.429430] <8000951c> from <805b9684>
[60700.429437] Exception stack(0x8085ff08 to 0x8085ff50)
[60700.429449] ff00: 00000000 b9f633c8 00000000 00000000 8085e000 808605dc
[60700.429463] ff20: 80860500 80860580 805bde5c 808c4798 ba7ff740 8085ff64 808614f8 8085ff58
[60700.429471] ff40: 80010b34 80010b38 60010013 ffffffff
[60700.429491] <805b9684> from <80010b38>
[60700.429511] <80010b38> from <80063dd4>
[60700.429529] <80063dd4> from <80063ffc>
[60700.429546] <80063ffc> from <805b3fb0>
[60700.429565] <805b3fb0> from <807e7d34>
[60700.429574] ---[ end trace 42b53d8fc72d9818 ]---
[64470.701611] em28178 #0: writing to i2c device at 0xc8 failed (error=-5)
[64470.901599] em28178 #0: writing to i2c device at 0xc8 failed (error=-5)
[64471.111555] em28174 #1: writing to i2c device at 0xd8 failed (error=-5)
[64471.118206] i2c i2c-6: cxd2820r: i2c rd failed=-5 reg=10 len=1
[64471.501568] em28178 #0: writing to i2c device at 0xc8 failed (error=-5)
[64472.101881] em28178 #0: writing to i2c device at 0xc8 failed (error=-5)
[64472.121581] em28174 #1: writing to i2c device at 0xd8 failed (error=-5)
[64472.128889] i2c i2c-6: cxd2820r: i2c rd failed=-5 reg=10 len=1
[64472.214369] em28178 #0: write to i2c device at 0xc8 failed with unknown error (status=3)
[64473.167852] em28174 #1: write to i2c device at 0xd8 failed with unknown error (status=1)
[64473.176946] i2c i2c-6: cxd2820r: i2c rd failed=-5 reg=10 len=1

[P33M]

You appear to have 4 (?!) USB hubs of various sizes plugged into the Pi. Can you post the output of lsusb -t please?

Can you also say whether these hubs are self-powered or bus-powered?

[andersthomson]

lsusb.txt

Two self powered hubs off the pi2, one of them is a 10 port with carries three 4way splitters internally.

I got the hubs in an attempt to rule out power issues as I have to (supposedly power hungry) TV tuner sticks in there.

[P33M]

Can you try again after running rpi-update? There have been some bug fixes that may affect your use case.

[andersthomson]

I'm compiling my own stuff. Can you indicate git commit and config to use? Thanks! /Anders

…

On May 4, 2017 5:28:26 PM GMT+02:00, P33M ***@***.***> wrote: Can you try again after running rpi-update? There have been some bug fixes that may affect your use case. -- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: #1649 (comment)

-- Sent from my Android device with K-9 Mail. Please excuse my brevity.

[popcornmix]

He'll be referring to top of rpi-4.9.y tree (currently 9a5f215) and using the bcm2709_defconfig.
See: https://www.raspberrypi.org/documentation/linux/kernel/building.md

But it is more useful for us if you test with a default kernel.
Reporting a bug with a custom built kernel adds another level of unknown when we try to diagnose.

[andersthomson]

Building that commit against that config right now. As it happens, I'm on rpi-4.9.17 right now, and cannot recall seeing the Watchdog in the oops for quite some time. I do still get regular oopes from the usb otg driver though (and an attempt at vanilla-4.11 with dwc2 consistently fails to get the tuners operational)

…

On Sun, May 14, 2017 at 5:06 PM, popcornmix ***@***.***> wrote: He'll be referring to top of rpi-4.9.y tree (currently raspberrypi/linux@ 9a5f215 <9a5f215>) and using the bcm2709_defconfig. See: https://www.raspberrypi.org/documentation/linux/kernel/building.md But it is more useful for us if you test with a default kernel. Reporting a bug with a custom built kernel adds another level of unknown when we try to diagnose. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1649 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGC9C9ieaTXmR-baqFoyHzo4_B8eN9Wnks5r5xhagaJpZM4KES2I> .

[lategoodbye]

@andersthomson Could you please explain what goes wrong on dwc2?