raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.02k stars 4.95k forks source link

2 usb ethernet adapters: cable plug-in causes kernel-4.19.x to crash #2924

Open m1027 opened 5 years ago

m1027 commented 5 years ago

No issues with kernel-4.14.98.

Tested setup:

To trigger the kernel crash:

Immediate dmesg message after plugging the ethernet cable: [ 32.537340] ERROR::assign_and_init_hc:1394: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

Kernel crash some seconds later: [ 78.078870] ------------[ cut here ]------------ [ 78.083672] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x298/0x29c [ 78.092196] NETDEV WATCHDOG: eth_inet (ax88179_178a): transmit queue 0 timed out [ 78.099835] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.32-v7+ #37 [ 78.106456] Hardware name: BCM2835 [ 78.109977] [<80110070>] (unwind_backtrace) from [<8010c82c>] (show_stack+0x20/0x24) [ 78.117941] [<8010c82c>] (show_stack) from [<80ac87a8>] (dump_stack+0xcc/0x110) [ 78.125399] [<80ac87a8>] (dump_stack) from [<80127898>] (warn.part.3+0xc8/0xe4) [ 78.133033] [<80127898>] (warn.part.3) from [<8012791c>] (warn_slowpath_fmt+0x68/0x70) [ 78.141286] [<8012791c>] (warn_slowpath_fmt) from [<809260bc>] (dev_watchdog+0x298/0x29c) [ 78.152419] [<809260bc>] (dev_watchdog) from [<801995c0>] (call_timer_fn+0x3c/0x1a4) [ 78.166200] [<801995c0>] (call_timer_fn) from [<80199820>] (expire_timers+0xf8/0x168) [ 78.180364] [<80199820>] (expire_timers) from [<80199934>] (run_timer_softirq+0xa4/0x1c0) [ 78.194954] [<80199934>] (run_timer_softirq) from [<80102370>] (do_softirq+0x188/0x410) [ 78.209607] [<80102370>] (__do_softirq) from [<8012d3f0>] (irq_exit+0xf8/0x134) [ 78.220293] [<8012d3f0>] (irq_exit) from [<80183618>] (handle_domain_irq+0x70/0xc4) [ 78.234765] [<80183618>] (handle_domain_irq) from [<8010219c>] (bcm2836_arm_irqchip_handle_irq+0x60/0xa8) [ 78.251219] [<8010219c>] (bcm2836_arm_irqchip_handle_irq) from [<801019bc>] (irq_svc+0x5c/0x7c) [ 78.266635] Exception stack(0x81001ee8 to 0x81001f30) [ 78.274964] 1ee0: 801092a4 00000000 40000093 40000093 ffffe000 8100616c [ 78.289630] 1f00: 810061b4 00000001 00000001 8109cd8d 80cc1a74 81001f44 81000000 81001f38 [ 78.304380] 1f20: 00000000 801092a8 40000013 ffffffff [ 78.312744] [<801019bc>] (__irq_svc) from [<801092a8>] (arch_cpu_idle+0x34/0x4c) [ 78.326558] [<801092a8>] (arch_cpu_idle) from [<80ae3000>] (default_idle_call+0x40/0x48) [ 78.341068] [<80ae3000>] (default_idle_call) from [<80157144>] (do_idle+0x134/0x174) [ 78.355248] [<80157144>] (do_idle) from [<80157420>] (cpu_startup_entry+0x28/0x2c) [ 78.369266] [<80157420>] (cpu_startup_entry) from [<80adcc34>] (rest_init+0xb8/0xbc) [ 78.383454] [<80adcc34>] (rest_init) from [<80f01020>] (start_kernel+0x3b4/0x3c8) [ 78.397396] ---[ end trace 19ce283ffed865af ]--- [ 78.405259] ERROR::assign_and_init_hc:1394: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case [ 78.405259] [ 78.428274] ERROR::assign_and_init_hc:1394: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

P33M commented 5 years ago

Please post a full dmesg listing. Running out of memory in this context is likely to be fatal to other consumers, not just USB.

m1027 commented 5 years ago

Thanks for your reply.

Here the full dmesg. You'll see:

[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.19.32-v7+ (root@rpi) (gcc version 8.2.0 (Gentoo 8.2.0-r6 p1.7)) #54 SMP Thu Apr 4 10:48:40 CEST 2019 [ 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 0x3dc00000 [ 0.000000] percpu: Embedded 15 pages/cpu @(ptrval) s40204 r0 d21236 u61440 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 253242 [ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000 console=ttyAMA0,115200n8 console=tty1 root=/dev/sda3 rootwait init=/usr/lib/systemd/systemd usbcore.autosuspend=-1 rw [ 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: 987108K/1021952K available (10240K kernel code, 689K rwdata, 2464K rodata, 1024K init, 434K bss, 26652K reserved, 8192K cma-reserved) [ 0.000000] Virtual kernel memory layout: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) [ 0.000000] vmalloc : 0xbe800000 - 0xff800000 (1040 MB) [ 0.000000] lowmem : 0x80000000 - 0xbe600000 ( 998 MB) [ 0.000000] .text : 0x(ptrval) - 0x(ptrval) (11232 kB) [ 0.000000] .init : 0x(ptrval) - 0x(ptrval) (1024 kB) [ 0.000000] .data : 0x(ptrval) - 0x(ptrval) ( 690 kB) [ 0.000000] .bss : 0x(ptrval) - 0x(ptrval) ( 435 kB) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] ftrace: allocating 35411 entries in 104 pages [ 0.000000] rcu: 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.000022] Switching to timer-based delay loop, resolution 52ns [ 0.000278] Console: colour dummy device 80x30 [ 0.000860] console [tty1] enabled [ 0.000917] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000) [ 0.000964] pid_max: default: 32768 minimum: 301 [ 0.001175] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.001210] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.002306] Disabling memory control group subsystem [ 0.002392] CPU: Testing write buffer coherency: ok [ 0.002855] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.003504] Setting up static identity map for 0x100000 - 0x10003c [ 0.003670] rcu: Hierarchical SRCU implementation. [ 0.004467] smp: Bringing up secondary CPUs ... [ 0.005297] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.006194] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002 [ 0.007024] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003 [ 0.007141] smp: Brought up 1 node, 4 CPUs [ 0.007224] SMP: Total of 4 processors activated (153.60 BogoMIPS). [ 0.007248] CPU: All CPU(s) started in HYP mode. [ 0.007269] CPU: Virtualization extensions available. [ 0.008265] devtmpfs: initialized [ 0.018941] random: get_random_u32 called from bucket_table_alloc+0x94/0x1a4 with crng_init=0 [ 0.019650] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4 [ 0.019902] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.019981] futex hash table entries: 1024 (order: 4, 65536 bytes) [ 0.020585] xor: measuring software checksum speed [ 0.120026] arm4regs : 920.000 MB/sec [ 0.220112] 8regs : 685.200 MB/sec [ 0.320196] 32regs : 659.600 MB/sec [ 0.420277] neon : 1093.600 MB/sec [ 0.420300] xor: using function: neon (1093.600 MB/sec) [ 0.420330] pinctrl core: initialized pinctrl subsystem [ 0.420855] NET: Registered protocol family 16 [ 0.423239] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.428676] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. [ 0.428714] hw-breakpoint: maximum watchpoint size is 8 bytes. [ 0.428944] Serial: AMBA PL011 UART driver [ 0.431185] bcm2835-mbox 3f00b880.mailbox: mailbox enabled [ 0.467163] cryptd: max_cpu_qlen set to 1000 [ 0.631011] raid6: int32x1 gen() 112 MB/s [ 0.800870] raid6: int32x1 xor() 123 MB/s [ 0.971041] raid6: int32x2 gen() 151 MB/s [ 1.141279] raid6: int32x2 xor() 144 MB/s [ 1.311548] raid6: int32x4 gen() 174 MB/s [ 1.481636] raid6: int32x4 xor() 154 MB/s [ 1.651945] raid6: int32x8 gen() 179 MB/s [ 1.821870] raid6: int32x8 xor() 128 MB/s [ 1.992145] raid6: neonx1 gen() 358 MB/s [ 2.162201] raid6: neonx1 xor() 410 MB/s [ 2.332490] raid6: neonx2 gen() 545 MB/s [ 2.502625] raid6: neonx2 xor() 554 MB/s [ 2.672763] raid6: neonx4 gen() 655 MB/s [ 2.842985] raid6: neonx4 xor() 584 MB/s [ 3.013180] raid6: neonx8 gen() 655 MB/s [ 3.183306] raid6: neonx8 xor() 567 MB/s [ 3.183329] raid6: using algorithm neonx4 gen() 655 MB/s [ 3.183352] raid6: .... xor() 584 MB/s, rmw enabled [ 3.183374] raid6: using neon recovery algorithm [ 3.183901] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1 [ 3.185554] SCSI subsystem initialized [ 3.185769] usbcore: registered new interface driver usbfs [ 3.185832] usbcore: registered new interface driver hub [ 3.185941] usbcore: registered new device driver usb [ 3.186168] pps_core: LinuxPPS API ver. 1 registered [ 3.186194] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti giometti@linux.it [ 3.197169] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-03-27 15:46, variant start_cd [ 3.207178] raspberrypi-firmware soc:firmware: Firmware hash is 2e98b31d18547962e564bdf88e57b3df7085c29b [ 3.217985] NET: Registered protocol family 8 [ 3.218009] NET: Registered protocol family 20 [ 3.218763] clocksource: Switched to clocksource arch_sys_counter [ 3.310796] VFS: Disk quotas dquot_6.6.0 [ 3.310900] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 3.311100] FS-Cache: Loaded [ 3.311300] CacheFiles: Loaded [ 3.319875] NET: Registered protocol family 2 [ 3.320750] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes) [ 3.320813] TCP established hash table entries: 8192 (order: 3, 32768 bytes) [ 3.320943] TCP bind hash table entries: 8192 (order: 4, 65536 bytes) [ 3.321148] TCP: Hash tables configured (established 8192 bind 8192) [ 3.321301] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 3.321366] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 3.321635] NET: Registered protocol family 1 [ 3.322231] RPC: Registered named UNIX socket transport module. [ 3.322258] RPC: Registered udp transport module. [ 3.322280] RPC: Registered tcp transport module. [ 3.322302] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 3.323389] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available [ 3.326356] workingset: timestamp_bits=14 max_order=18 bucket_order=4 [ 3.335212] DLM installed [ 3.337011] NFS: Registering the id_resolver key type [ 3.337057] Key type id_resolver registered [ 3.337079] Key type id_legacy registered [ 3.337111] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 3.337138] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering... [ 3.338038] fuse init (API version 7.27) [ 3.345666] NET: Registered protocol family 38 [ 3.345773] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) [ 3.345971] io scheduler noop registered [ 3.345995] io scheduler deadline registered [ 3.346216] io scheduler cfq registered (default) [ 3.349476] BCM2708FB: allocated DMA memory 0xfdc50000 [ 3.349529] BCM2708FB: allocated DMA channel 0 [ 3.355046] Console: switching to colour frame buffer device 82x26 [ 3.358995] usbcore: registered new interface driver udlfb [ 3.361446] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled [ 3.364447] bcm2835-rng 3f104000.rng: hwrng registered [ 3.366100] vc-mem: phys_addr:0x00000000 mem_base=0x3f000000 mem_size:0x3f600000(1014 MiB) [ 3.369794] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000 [ 3.373199] usbcore: registered new interface driver udl [ 3.380266] loop: module loaded [ 3.382155] Loading iSCSI transport class v2.0-870. [ 3.384122] iscsi: registered transport (tcp) [ 3.385684] st: Version 20160209, fixed bufsize 32768, s/g segs 256 [ 3.387359] osst :I: Tape driver with OnStream support version 0.99.4 [ 3.387359] osst :I: $Id: osst.c,v 1.73 2005/01/01 21:13:34 wriede Exp $ [ 3.391329] libphy: Fixed MDIO Bus: probed [ 3.392929] tun: Universal TUN/TAP device driver, 1.6 [ 3.394654] PPP generic driver version 2.4.2 [ 3.396358] PPP BSD Compression module registered [ 3.397902] PPP Deflate Compression module registered [ 3.399459] PPP MPPE Compression module registered [ 3.400967] NET: Registered protocol family 24 [ 3.402506] SLIP: version 0.8.4-NET3.019-NEWTTY (dynamic channels, max=256). [ 3.404094] CSLIP: code copyright 1989 Regents of the University of California. [ 3.405707] SLIP linefill/keepalive option. [ 3.407374] usbcore: registered new interface driver r8152 [ 3.409086] usbcore: registered new interface driver lan78xx [ 3.410722] usbcore: registered new interface driver asix [ 3.412303] usbcore: registered new interface driver ax88179_178a [ 3.413850] usbcore: registered new interface driver smsc95xx [ 3.415351] usbcore: registered new interface driver cdc_ncm [ 3.416869] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 3.418257] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver [ 3.419640] dwc_otg: version 3.00a 10-AUG-2012 (platform bus) [ 3.446405] dwc_otg 3f980000.usb: base=(ptrval) [ 3.648011] Core Release: 2.80a [ 3.649359] Setting default values for core params [ 3.650711] Finished setting default values for core params [ 3.852289] Using Buffer DMA mode [ 3.853593] Periodic Transfer Interrupt Enhancement - disabled [ 3.854928] Multiprocessor Interrupt Enhancement - disabled [ 3.856249] OTG VER PARAM: 0, OTG VER FLAG: 0 [ 3.857570] Dedicated Tx FIFOs mode [ 3.859346] WARN::dwc_otg_hcd_init:1049: FIQ DMA bounce buffers: virt = bdc44000 dma = 0xfdc44000 len=9024 [ 3.862082] FIQ FSM acceleration enabled for : [ 3.862082] Non-periodic Split Transactions [ 3.862082] Periodic Split Transactions [ 3.862082] High-Speed Isochronous Endpoints [ 3.862082] Interrupt/Control Split Transaction hack enabled [ 3.868759] WARN::hcd_init_fiq:457: FIQ on core 1 [ 3.870054] WARN::hcd_init_fiq:458: FIQ ASM at 80825c58 length 36 [ 3.871382] WARN::hcd_init_fiq:484: MPHI regs_base at f0006000 [ 3.872777] dwc_otg 3f980000.usb: DWC OTG Controller [ 3.874174] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1 [ 3.875630] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000 [ 3.877116] Init: Port Power? op_state=1 [ 3.878527] Init: Power Port (0) [ 3.880166] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19 [ 3.883001] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 3.884520] usb usb1: Product: DWC OTG Controller [ 3.886024] usb usb1: Manufacturer: Linux 4.19.32-v7+ dwc_otg_hcd [ 3.887539] usb usb1: SerialNumber: 3f980000.usb [ 3.889616] hub 1-0:1.0: USB hub found [ 3.891130] hub 1-0:1.0: 1 port detected [ 3.893365] usbcore: registered new interface driver usb-storage [ 3.894924] usbcore: registered new interface driver usbserial_generic [ 3.896409] usbserial: USB Serial support registered for generic [ 3.897876] usbcore: registered new interface driver ftdi_sio [ 3.899333] usbserial: USB Serial support registered for FTDI USB Serial Device [ 3.900880] usbcore: registered new interface driver pl2303 [ 3.902364] usbserial: USB Serial support registered for pl2303 [ 3.904074] mousedev: PS/2 mouse device common for all mice [ 3.906556] i2c /dev entries driver [ 3.908524] pps_ldisc: PPS line discipline registered [ 3.911232] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer [ 3.913088] bcm2835-cpufreq: min=600000 max=1200000 [ 3.915113] sdhci: Secure Digital Host Controller Interface driver [ 3.916675] sdhci: Copyright(c) Pierre Ossman [ 3.918492] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe [ 3.920163] Error: Driver 'sdhost-bcm2835' is already registered, aborting... [ 3.920987] sdhci-pltfm: SDHCI platform and OF driver helper [ 3.922914] ledtrig-cpu: registered to indicate activity on CPUs [ 3.923827] hidraw: raw HID events driver (C) Jiri Kosina [ 3.924836] usbcore: registered new interface driver usbhid [ 3.925616] usbhid: USB HID core driver [ 3.926467] pktgen: Packet Generator for packet performance testing. Version: 2.75 [ 3.928329] GACT probability on [ 3.929130] Mirror/redirect action on [ 3.929940] Simple TC action Loaded [ 3.930732] netem: version 1.3 [ 3.931535] u32 classifier [ 3.932292] Actions configured [ 3.933825] xt_time: kernel timezone is -0000 [ 3.935129] ipt_CLUSTERIP: ClusterIP Version 0.8 loaded successfully [ 3.935959] Initializing XFRM netlink socket [ 3.936711] NET: Registered protocol family 17 [ 3.937457] NET: Registered protocol family 15 [ 3.938201] Bridge firewalling registered [ 3.938997] l2tp_core: L2TP core driver, V2.0 [ 3.939696] l2tp_ppp: PPPoL2TP kernel driver, V2.0 [ 3.940380] l2tp_ip: L2TP IP encapsulation support (L2TPv3) [ 3.941073] l2tp_netlink: L2TP netlink interface [ 3.941783] l2tp_eth: L2TP ethernet pseudowire support (L2TPv3) [ 3.942493] sctp: Hash tables configured (bind 512/512) [ 3.943308] Key type dns_resolver registered [ 3.944194] Registering SWP/SWPB emulation handler [ 3.945775] registered taskstats version 1 [ 3.947195] Btrfs loaded, crc32c=crc32c-generic [ 3.951738] uart-pl011 3f201000.serial: cts_event_workaround enabled [ 3.952452] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2 [ 5.286940] console [ttyAMA0] enabled [ 5.292810] rtc-ds1307: probe of 1-006f failed with error -121 [ 5.299947] sdhost: log_buf @ (ptrval) (fdc47000) [ 5.352006] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) [ 5.360405] hctosys: unable to open rtc device (rtc0) [ 5.366831] of_cfs_init [ 5.370744] of_cfs_init: OK [ 5.375073] Waiting for root device /dev/sda3... [ 5.398822] Indeed it is in host mode hprt0 = 00021501 [ 5.492021] random: fast init done [ 5.608804] usb 1-1: new high-speed USB device number 2 using dwc_otg [ 5.616774] Indeed it is in host mode hprt0 = 00001101 [ 5.879041] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00 [ 5.890182] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 [ 5.899494] hub 1-1:1.0: USB hub found [ 5.904506] hub 1-1:1.0: 5 ports detected [ 6.228799] usb 1-1.1: new high-speed USB device number 3 using dwc_otg [ 6.359044] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00 [ 6.370534] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 [ 6.381999] smsc95xx v1.0.6 [ 6.472164] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:a7:10:4b [ 6.578818] usb 1-1.3: new high-speed USB device number 4 using dwc_otg [ 6.720152] usb 1-1.3: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00 [ 6.731912] usb 1-1.3: New USB device strings: Mfr=2, Product=3, SerialNumber=1 [ 6.741010] usb 1-1.3: Product: IB-AC704-6G [ 6.746934] usb 1-1.3: Manufacturer: ICY BOX [ 6.752935] usb 1-1.3: SerialNumber: 201712000023 [ 6.760001] usb-storage 1-1.3:1.0: USB Mass Storage device detected [ 6.767825] usb-storage 1-1.3:1.0: Quirks match for vid 174c pid 55aa: 400000 [ 6.775919] scsi host0: usb-storage 1-1.3:1.0 [ 6.878794] usb 1-1.4: new high-speed USB device number 5 using dwc_otg [ 7.051034] usb 1-1.4: New USB device found, idVendor=0b95, idProduct=772b, bcdDevice= 0.01 [ 7.061214] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [ 7.069455] usb 1-1.4: Product: AX88772B [ 7.074269] usb 1-1.4: Manufacturer: ASIX Elec. Corp. [ 7.080205] usb 1-1.4: SerialNumber: 1D6094 [ 7.532879] asix 1-1.4:1.0 eth1: register 'asix' at usb-3f980000.usb-1.4, ASIX AX88772B USB 2.0 Ethernet, 00:50:b6:1d:60:94 [ 7.638801] usb 1-1.5: new high-speed USB device number 6 using dwc_otg [ 7.791147] usb 1-1.5: New USB device found, idVendor=0b95, idProduct=772b, bcdDevice= 0.01 [ 7.803082] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [ 7.812236] usb 1-1.5: Product: AX88772B [ 7.817940] usb 1-1.5: Manufacturer: ASIX Elec. Corp. [ 7.824757] usb 1-1.5: SerialNumber: 104B99 [ 7.839833] scsi 0:0:0:0: Direct-Access ICY BOX IB-AC704-6G 0 PQ: 0 ANSI: 6 [ 7.852070] sd 0:0:0:0: Attached scsi generic sg0 type 0 [ 7.852516] sd 0:0:0:0: [sda] 1953525168 512-byte logical blocks: (1.00 TB/932 GiB) [ 7.870193] sd 0:0:0:0: [sda] 4096-byte physical blocks [ 7.877713] sd 0:0:0:0: [sda] Write Protect is off [ 7.884134] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 7.894941] sd 0:0:0:0: [sda] Optimal transfer size 0 bytes < PAGE_SIZE (4096 bytes) [ 8.303527] asix 1-1.5:1.0 eth2: register 'asix' at usb-3f980000.usb-1.5, ASIX AX88772B USB 2.0 Ethernet, 00:50:b6:10:4b:99 [ 10.025742] sda: sda1 sda2 sda3 sda4 [ 10.033868] sd 0:0:0:0: [sda] Attached SCSI disk [ 10.079239] BTRFS: device fsid 194aec8e-790e-4bbc-8efa-ff9cedeb4dfd devid 1 transid 49482 /dev/root [ 10.093412] BTRFS info (device sda3): disk space caching is enabled [ 10.101536] BTRFS info (device sda3): has skinny extents [ 10.158297] BTRFS info (device sda3): bdev /dev/root errs: wr 0, rd 6, flush 0, corrupt 0, gen 0 [ 10.290639] BTRFS info (device sda3): checking UUID tree [ 10.310466] VFS: Mounted root (btrfs filesystem) on device 0:16. [ 10.336200] devtmpfs: mounted [ 10.348861] Freeing unused kernel memory: 1024K [ 10.369343] Run /usr/lib/systemd/systemd as init process [ 11.101491] systemd[1]: System time before build time, advancing clock. [ 11.151433] systemd[1]: systemd 239 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL -XZ -LZ4 -SECCOMP +BLKID -ELFUTILS -KMOD -IDN2 -IDN +PCRE2 default-hierarchy=hybrid) [ 11.179043] systemd[1]: Detected architecture arm. [ 11.231319] systemd[1]: Set hostname to . [ 11.359213] uart-pl011 3f201000.serial: no DMA platform data [ 11.427170] systemd-gpt-auto-generator[159]: Failed to determine block device of root file system: No such file or directory [ 11.756393] systemd[152]: /lib/systemd/system-generators/systemd-gpt-auto-generator failed with exit status 1. [ 12.088483] random: systemd: uninitialized urandom read (16 bytes read) [ 12.097661] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point. [ 12.112713] random: systemd: uninitialized urandom read (16 bytes read) [ 12.121706] systemd[1]: Created slice system-systemd\x2dfsck.slice. [ 12.130175] random: systemd: uninitialized urandom read (16 bytes read) [ 12.138171] systemd[1]: Created slice User and Session Slice. [ 12.146595] systemd[1]: Listening on Journal Socket. [ 12.156171] systemd[1]: Mounting FUSE Control File System... [ 12.288469] systemd[1]: Reached target Remote File Systems. [ 12.989591] BTRFS info (device sda3): disk space caching is enabled [ 13.366115] systemd-journald[172]: Received request to flush runtime journal from PID 1 [ 13.880933] asix 1-1.5:1.0 eth_inet: renamed from eth2 [ 13.951759] smsc95xx 1-1.1:1.0 eth_lan1: renamed from eth0 [ 14.008957] asix 1-1.4:1.0 eth_lan0: renamed from eth1 [ 14.249668] random: crng init done [ 14.253794] random: 7 urandom warning(s) missed due to ratelimiting [ 14.548146] BTRFS: device fsid e33a88f2-8564-49fa-ad21-67da26f3c0ba devid 1 transid 1967 /dev/sda4 [ 14.905519] BTRFS info (device sda3): device fsid 194aec8e-790e-4bbc-8efa-ff9cedeb4dfd devid 1 moved old:/dev/root new:/dev/sda3 [ 15.034273] Adding 2097148k swap on /dev/sda2. Priority:-2 extents:1 across:2097148k FS [ 15.125012] BTRFS info (device sda4): disk space caching is enabled [ 15.132327] BTRFS info (device sda4): has skinny extents [ 18.281541] smsc95xx 1-1.1:1.0 eth_lan1: hardware isn't capable of remote wakeup [ 18.323493] asix 1-1.5:1.0 eth_inet: link up, 100Mbps, full-duplex, lpa 0xCDE1 [ 18.335428] asix 1-1.4:1.0 eth_lan0: link up, 100Mbps, full-duplex, lpa 0xCDE1 [ 19.886838] smsc95xx 1-1.1:1.0 eth_lan1: link up, 100Mbps, full-duplex, lpa 0x45E1 [ 21.151493] ERROR::assign_and_init_hc:1394: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case [ 21.151493]

This is rpi (Linux armv7l 4.19.32-v7+) 13:41:11

rpi login: root Password: Last login: Sun Apr 14 13:36:19 CEST 2019 from 192.168.241.52 on pts/0 Welcome! root@rpi ~ # [ 84.078772] ------------[ cut here ]------------ [ 84.083528] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x298/0x29c [ 84.091928] NETDEV WATCHDOG: eth_inet (asix): transmit queue 0 timed out [ 84.098742] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.32-v7+ #54 [ 84.105268] Hardware name: BCM2835 [ 84.108740] [<80110070>] (unwind_backtrace) from [<8010c82c>] (show_stack+0x20/0x24) [ 84.116596] [<8010c82c>] (show_stack) from [<80ac87a8>] (dump_stack+0xcc/0x110) [ 84.124014] [<80ac87a8>] (dump_stack) from [<80127898>] (warn.part.3+0xc8/0xe4) [ 84.131610] [<80127898>] (warn.part.3) from [<8012791c>] (warn_slowpath_fmt+0x68/0x70) [ 84.139822] [<8012791c>] (warn_slowpath_fmt) from [<809260bc>] (dev_watchdog+0x298/0x29c) [ 84.148118] [<809260bc>] (dev_watchdog) from [<801995c0>] (call_timer_fn+0x3c/0x1a4) [ 84.155972] [<801995c0>] (call_timer_fn) from [<80199820>] (expire_timers+0xf8/0x168) [ 84.163912] [<80199820>] (expire_timers) from [<80199934>] (run_timer_softirq+0xa4/0x1c0) [ 84.175346] [<80199934>] (run_timer_softirq) from [<80102370>] (do_softirq+0x188/0x410) [ 84.190308] [<80102370>] (__do_softirq) from [<8012d3f0>] (irq_exit+0xf8/0x134) [ 84.201162] [<8012d3f0>] (irq_exit) from [<80183618>] (handle_domain_irq+0x70/0xc4) [ 84.216119] [<80183618>] (handle_domain_irq) from [<8010219c>] (bcm2836_arm_irqchip_handle_irq+0x60/0xa8) [ 84.233094] [<8010219c>] (bcm2836_arm_irqchip_handle_irq) from [<801019bc>] (irq_svc+0x5c/0x7c) [ 84.249107] Exception stack(0x81001ee8 to 0x81001f30) [ 84.257725] 1ee0: 801092a4 00000000 400e0093 400e0093 ffffe000 8100616c [ 84.273070] 1f00: 810061b4 00000001 00000001 8109cd8d 80cc1a74 81001f44 81000000 81001f38 [ 84.288486] 1f20: 00000000 801092a8 400e0013 ffffffff [ 84.297181] [<801019bc>] (__irq_svc) from [<801092a8>] (arch_cpu_idle+0x34/0x4c) [ 84.311657] [<801092a8>] (arch_cpu_idle) from [<80ae3000>] (default_idle_call+0x40/0x48) [ 84.326816] [<80ae3000>] (default_idle_call) from [<80157144>] (do_idle+0x134/0x174) [ 84.341634] [<80157144>] (do_idle) from [<80157420>] (cpu_startup_entry+0x28/0x2c) [ 84.356304] [<80157420>] (cpu_startup_entry) from [<80adcc34>] (rest_init+0xb8/0xbc) [ 84.371161] [<80adcc34>] (rest_init) from [<80f01020>] (start_kernel+0x3b4/0x3c8) [ 84.385817] ---[ end trace a3e1fa7b43dc358e ]--- [ 84.394793] ERROR::assign_and_init_hc:1394: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case [ 84.394793]

root@rpi ~ # systemctl poweroff [ 98.117761] systemd-shutdow: 29 output lines suppressed due to ratelimiting [ 98.141589] systemd-shutdown[1]: Syncing filesystems and block devices. [ 98.388066] systemd-shutdown[1]: Sending SIGTERM to remaining processes... [ 98.412689] systemd-journald[172]: Received SIGTERM from PID 1 (systemd-shutdow). [ 98.499822] systemd-shutdown[1]: Sending SIGKILL to remaining processes... [ 98.523217] systemd-shutdown[1]: Unmounting file systems. [ 98.532316] [368]: Remounting '/' read-only in with options 'space_cache,subvolid=5,subvol=/'. [ 98.548451] BTRFS info (device sda3): disk space caching is enabled [ 98.748321] systemd-shutdown[1]: All filesystems unmounted. [ 98.756129] systemd-shutdown[1]: Deactivating swaps. [ 98.763464] systemd-shutdown[1]: All swaps deactivated. [ 98.770888] systemd-shutdown[1]: Detaching loop devices. [ 98.781066] systemd-shutdown[1]: All loop devices detached. [ 98.788254] systemd-shutdown[1]: Detaching DM devices. [ 98.798600] sd 0:0:0:0: [sda] Synchronizing SCSI cache [ 98.848792] reboot: Power down

mkosch commented 5 years ago

I experience a similar problem since kernel 4.19.23 and newer. Everything works up to kernel 4.14.98.

Tested setup:

What happens:

Test case:

m1027 commented 5 years ago

Updates:

(1) The issue (summary)

(2) Test with newer kernel

Same issues with newest kernel/firmware 4.19.36 (was 4.19.32).

(3) Low memory?

Running out of memory in this context is likely to be fatal to other consumers, not just USB.

So, I did the following:

(3.1) Checking memory with free command

The free command before/after the first kernel error message does not reveal any low mem situation:

free total used free shared buff/cache available Mem: 1000900 45348 893316 5684 62236 872492 Swap: 2097148 0 2097148

[ 79.535682] asix 1-1.5:1.0 eth_inet: link up, 100Mbps, full-duplex, lpa 0xCDE1 [ 216.853593] ERROR::assign_and_init_hc:1391: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

free total used free shared buff/cache available Mem: 1000900 38780 892936 10472 69184 873200 Swap: 2097148 0 2097148

(3.2) Booting with nearly no user space daemon (no sshd, no apache, etc)

Still the same issue.

(4) New hints on what can trigger the issue

To recall: In my OP I saw a work-around by not connecting one of the two USB/ethernet adapters.

One of the adapters is connected to a WLAN router. Now I see that I can boot with all adapters connected without the issue, and later trigger the above error message immediately when the first laptop connects over WLAN and tries to send/receive some data (like connecting to a website in my case).

I repeated that several times by rebooting the RPI, waiting an arbitrary time and then connecting a laptop over WLAN / opening a website.

(4) Conclusion for now

I cannot confirm a memory issue yet (always note that kernel 4.14.x works).

I can trigger the error by the first network packets sent over one of the adapters.

P33M commented 5 years ago

I can replicate with 2x Pi zero plugged into a 3B+ with the zero devices acting as CDC-ether gadgets.

P33M commented 5 years ago

Oh this is fun. In 4.14.122, there are 3 allocations for non-aligned buffers across three Ethernet devices (lan95xx plus two cdc_ether devices). Each of these is a 64k-1b buffer. In 4.19, the number of allocations grows to 5, with 2 of the requests failing. Increasing the CMA region size doesn't help; even with a 32MB region the same number of failures occurs.

There's two worrying implications here:

We can't do much about the first point, as there's a hardware requirement that can't be communicated up the stack. We can fix the second point by a) moving this alloc out of an atomic context and b) figuring out which page pool is getting exhausted after only 3 allocations.

There's yet more fun in the failure mechanism: the allocation failure happens after dwc_otg has "accepted" the URB and returned success to the caller - silently failing to perform the actual transfer and never giving the URB back with a failure status.

P33M commented 5 years ago

@m1027 @mkosch can you try adding the parameter "coherent_pool=4M" to /boot/cmdline.txt?

6by9 commented 5 years ago

4.20 gains https://github.com/raspberrypi/linux/commit/1ee5c23eb5b7bb3ac8a6848e91265a294a811246 which signals up the stack that some part of the buffers can be aligned. Does that help in this context? I think the same thing is valid for lan7800.c if we're seeing the issue on both 3B and 3B+.

m1027 commented 5 years ago

@m1027 @mkosch can you try adding the parameter "coherent_pool=4M" to /boot/cmdline.txt?

Man, this is awesome.

It seems we can finally upgrade the kernel from 4.14 to 4.19.!

No error message, no crash since 20 minutes, and also some reboots.

In case you want to drop some lines about what this actually changes, when (not) to apply this setting, possible drawbacks... that would help, too, as there are several slightly different setups here.

mkosch commented 5 years ago

@m1027 @mkosch can you try adding the parameter "coherent_pool=4M" to /boot/cmdline.txt? It seems to work. Thanks.

I can ping the slave Raspberry Pis and connect to it via SSH with the latest kernel. It even works with a third USB Ethernet device attached.

P33M commented 5 years ago

Increasing the coherent pool size reduces total available RAM for other users, so this is a diagnostic test rather than a fix. This is a boot-time allocated pool of memory for DMA-coherent buffers allocated in atomic context. The way dwc_otg is using this is suboptimal - the allocations it uses are large and persist until the device is disconnected. The aligned buffer also incurs an extra memcpy to/from the provided buffer, so this also adds a performance penalty.

Usbnet should make a better effort at allocating aligned RX buffers, since that's gone backwards since 4.14.

P33M commented 5 years ago

Naively forcing NET_IP_ALIGN to be 0 stops RX buffers being misaligned, but ipv6 multicast tx is giving us misaligned buffers - so we still get one 64k allocation per net device. Somehow I think we're never going to completely get rid of the requirement to allocate a bounce buffer, but at the very least we need to stop memcpying every single RX packet.

I'll do some profiling to see which is the least worst option.

JamesH65 commented 5 years ago

2599 Is this related?

P33M commented 5 years ago

There's a difference in nomenclature here - from the point of view of the USB hardware, it needs the start of a read or write buffer to be 32-bit aligned. I'm not tracking CPU alignment faults, but there's potentially knobs in the USB-ethernet drivers for changing the offset of packet data start relative to the buffer data start if changing the URB alignment impacts the frequency of CPU faults.

P33M commented 5 years ago

I've done various trials monitoring how often an unaligned URB is passed to dwc_otg. Between 4.14 and 4.19, usb-ethernet RX buffers became "unaligned" for ASIX and cdc_ether drivers, but unchanged for smsc95xx. In both 4.14 and 4.19 tx buffers are unaligned in almost all cases, with ASIX being the exception for ipv4 packets.

Setting NET_IP_ALIGN=0 reverts 4.19 to the old behaviour, as in no unaligned RX buffers. However, with the misalignment of IP headers we now get a lot more faults being handled - I believe one for every ipv6 packet received.

It also looks like for ASIX and cdc_ether, the tx header must immediately precede the data so there's no scope for adding a padding fudge factor. The smsc95xx and lan78xx drivers need further investigation.

P33M commented 5 years ago

smsc95xx can have a variable start offset of up to 3 bytes between the 2 tx words and the start of data, specified in tx_cmd_a[17:16] - so we can mangle TX buffers presented to dwc_otg to be aligned to a word boundary. In lan78xx, there's multiple undefined bitfields in the TX command words that could be start-of-data offset fields. Assuming we can fixup both of these drivers, the default Ethernet interfaces should no longer require bounce buffers.

For an immediate "make 4.19 be less broken than 4.14" patch, I propose expanding the atomic allocation pool to 512K and moving the allocation code in dwc_otg up several levels so that USB device drivers get told about failure.

P33M commented 5 years ago

Please retest with latest rpi-update firmware.

mkosch commented 5 years ago

Please retest with latest rpi-update firmware.

It doesn't work with latest kernel 4.19.37-v7+ (hash 18e0a0f9a31e7a3a47d9c4301c7705b980ab0516) and without specifying the /boot/cmdline.txt parameter "coherent_pool". I can (more or less) ping the first slave Raspberry Pi, but cannot ping the second one.

Output from "dmesg":

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.37-v7+ (dom@dom-XPS-13-9370) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1216 SMP Thu May 2 13:32:40 BST 2019
[    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 Plus Rev 1.3
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x37800000
[    0.000000] On node 0 totalpages: 229376
[    0.000000]   Normal zone: 2016 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 229376 pages, LIFO batch:63
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
[    0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632
[    0.000000] pcpu-alloc: s39488 r8192 d21952 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: 227360
[    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=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=6bda1aab-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    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: 886304K/917504K available (8192K kernel code, 627K rwdata, 2164K rodata, 1024K init, 821K bss, 23008K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xb8800000 - 0xff800000   (1136 MB)
                   lowmem  : 0x80000000 - 0xb8000000   ( 896 MB)
                   modules : 0x7f000000 - 0x80000000   (  16 MB)
                     .text : 0x(ptrval) - 0x(ptrval)   (9184 kB)
                     .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
                     .data : 0x(ptrval) - 0x(ptrval)   ( 628 kB)
                      .bss : 0x(ptrval) - 0x(ptrval)   ( 822 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 26225 entries in 77 pages
[    0.000000] rcu: 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.000287] Console: colour dummy device 80x30
[    0.000903] console [tty1] enabled
[    0.000964] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.001009] pid_max: default: 32768 minimum: 301
[    0.001368] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001404] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.002334] CPU: Testing write buffer coherency: ok
[    0.002817] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003482] Setting up static identity map for 0x100000 - 0x10003c
[    0.003646] rcu: Hierarchical SRCU implementation.
[    0.004455] smp: Bringing up secondary CPUs ...
[    0.005323] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.006243] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.007105] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007225] smp: Brought up 1 node, 4 CPUs
[    0.007307] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.007331] CPU: All CPU(s) started in HYP mode.
[    0.007351] CPU: Virtualization extensions available.
[    0.008324] devtmpfs: initialized
[    0.020141] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.020412] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.020460] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.021065] pinctrl core: initialized pinctrl subsystem
[    0.021956] NET: Registered protocol family 16
[    0.024215] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.029844] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.029880] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.030158] Serial: AMBA PL011 UART driver
[    0.032452] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.067965] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.069647] SCSI subsystem initialized
[    0.069886] usbcore: registered new interface driver usbfs
[    0.069968] usbcore: registered new interface driver hub
[    0.070082] usbcore: registered new device driver usb
[    0.090206] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-03-27 15:48, variant start_x
[    0.100447] raspberrypi-firmware soc:firmware: Firmware hash is 2e98b31d18547962e564bdf88e57b3df7085c29b
[    0.111785] clocksource: Switched to clocksource arch_sys_counter
[    0.201947] VFS: Disk quotas dquot_6.6.0
[    0.202058] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.202304] FS-Cache: Loaded
[    0.202528] CacheFiles: Loaded
[    0.212447] NET: Registered protocol family 2
[    0.213257] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[    0.213321] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.213451] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.213655] TCP: Hash tables configured (established 8192 bind 8192)
[    0.213812] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.213882] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.214232] NET: Registered protocol family 1
[    0.214840] RPC: Registered named UNIX socket transport module.
[    0.214867] RPC: Registered udp transport module.
[    0.214888] RPC: Registered tcp transport module.
[    0.214909] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.216511] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.219614] Initialise system trusted keyrings
[    0.219823] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.229658] FS-Cache: Netfs 'nfs' registered for caching
[    0.230258] NFS: Registering the id_resolver key type
[    0.230309] Key type id_resolver registered
[    0.230331] Key type id_legacy registered
[    0.230362] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.232742] Key type asymmetric registered
[    0.232771] Asymmetric key parser 'x509' registered
[    0.232838] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.233020] io scheduler noop registered
[    0.233045] io scheduler deadline registered (default)
[    0.233238] io scheduler cfq registered
[    0.233261] io scheduler mq-deadline registered (default)
[    0.233285] io scheduler kyber registered
[    0.235915] BCM2708FB: allocated DMA memory 0xf7840000
[    0.235982] BCM2708FB: allocated DMA channel 0
[    0.247706] Console: switching to colour frame buffer device 80x30
[    0.256354] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    0.260579] bcm2835-rng 3f104000.rng: hwrng registered
[    0.263574] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.269674] vc-sm: Videocore shared memory driver
[    0.272839] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.289309] brd: module loaded
[    0.302283] loop: module loaded
[    0.305041] Loading iSCSI transport class v2.0-870.
[    0.308519] libphy: Fixed MDIO Bus: probed
[    0.311407] usbcore: registered new interface driver lan78xx
[    0.314302] usbcore: registered new interface driver smsc95xx
[    0.317013] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.347622] dwc_otg 3f980000.usb: base=(ptrval)
[    0.550503] Core Release: 2.80a
[    0.553091] Setting default values for core params
[    0.555706] Finished setting default values for core params
[    0.758623] Using Buffer DMA mode
[    0.761259] Periodic Transfer Interrupt Enhancement - disabled
[    0.764014] Multiprocessor Interrupt Enhancement - disabled
[    0.766787] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.769548] Dedicated Tx FIFOs mode
[    0.772874] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = b7854000 dma = 0xf7854000 len=9024
[    0.778555] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.791916] dwc_otg: Microframe scheduler enabled
[    0.791971] WARN::hcd_init_fiq:457: FIQ on core 1
[    0.794513] WARN::hcd_init_fiq:458: FIQ ASM at 8064b4e8 length 36
[    0.797074] WARN::hcd_init_fiq:484: MPHI regs_base at f0006000
[    0.799700] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.802326] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.807487] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    0.810267] Init: Port Power? op_state=1
[    0.812980] Init: Power Port (0)
[    0.815861] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.821343] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.827043] usb usb1: Product: DWC OTG Controller
[    0.829926] usb usb1: Manufacturer: Linux 4.19.37-v7+ dwc_otg_hcd
[    0.832850] usb usb1: SerialNumber: 3f980000.usb
[    0.836325] hub 1-0:1.0: USB hub found
[    0.839214] hub 1-0:1.0: 1 port detected
[    0.842552] dwc_otg: FIQ enabled
[    0.842557] dwc_otg: NAK holdoff enabled
[    0.842563] dwc_otg: FIQ split-transaction FSM enabled
[    0.842573] Module dwc_common_port init
[    0.842835] usbcore: registered new interface driver usb-storage
[    0.845770] mousedev: PS/2 mouse device common for all mice
[    0.849407] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    0.852605] bcm2835-cpufreq: min=600000 max=1400000
[    0.855933] sdhci: Secure Digital Host Controller Interface driver
[    0.858884] sdhci: Copyright(c) Pierre Ossman
[    0.862191] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[    0.865573] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    0.868758] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.873382] ledtrig-cpu: registered to indicate activity on CPUs
[    0.876640] hidraw: raw HID events driver (C) Jiri Kosina
[    0.879949] usbcore: registered new interface driver usbhid
[    0.883044] usbhid: USB HID core driver
[    0.886796] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    0.891369] [vc_sm_connected_init]: start
[    0.900266] [vc_sm_connected_init]: end - returning 0
[    0.904392] Initializing XFRM netlink socket
[    0.907371] NET: Registered protocol family 17
[    0.910346] Key type dns_resolver registered
[    0.913591] Registering SWP/SWPB emulation handler
[    0.917052] registered taskstats version 1
[    0.919834] Loading compiled-in X.509 certificates
[    0.929837] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    0.932882] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    0.940322] console [ttyS0] disabled
[    0.943285] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 53, base_baud = 31250000) is a 16550
[    1.970018] console [ttyS0] enabled
[    1.977553] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    1.986444] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    2.021198] sdhost: log_buf @ (ptrval) (f7853000)
[    2.063916] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    2.073890] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.082316] Indeed it is in host mode hprt0 = 00021501
[    2.150267] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    2.159882] of_cfs_init
[    2.165204] of_cfs_init: OK
[    2.171218] Waiting for root device PARTUUID=6bda1aab-02...
[    2.173530] random: fast init done
[    2.186173] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.197252] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    2.261617] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.280419] mmc0: new high speed SDHC card at address aaaa
[    2.291537] mmc1: new high speed SDIO card at address 0001
[    2.300498] mmcblk0: mmc0:aaaa SE32G 28.8 GiB
[    2.307649] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.317585] Indeed it is in host mode hprt0 = 00001101
[    2.387051]  mmcblk0: p1 p2 p3 p4
[    2.423776] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.437336] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.448147] devtmpfs: mounted
[    2.459801] Freeing unused kernel memory: 1024K
[    2.467592] Run /sbin/init as init process
[    2.572119] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    2.586105] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.597039] hub 1-1:1.0: USB hub found
[    2.603918] hub 1-1:1.0: 4 ports detected
[    2.931836] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    2.961400] systemd[1]: System time before build time, advancing clock.
[    3.072115] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    3.086870] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.101596] hub 1-1.1:1.0: USB hub found
[    3.109152] hub 1-1.1:1.0: 3 ports detected
[    3.120852] NET: Registered protocol family 10
[    3.129878] Segment Routing with IPv6
[    3.168314] random: systemd: uninitialized urandom read (16 bytes read)
[    3.181458] random: systemd: uninitialized urandom read (16 bytes read)
[    3.196868] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    3.225504] systemd[1]: Detected architecture arm.
[    3.253695] systemd[1]: Set hostname to <ROBOT>.
[    3.322523] random: systemd-cryptse: uninitialized urandom read (16 bytes read)
[    3.469699] dwc_otg_handle_wakeup_detected_intr lxstate = 2
[    3.903475] systemd[1]: avahi-daemon.socket: Cannot add dependency job, ignoring: Unit avahi-daemon.socket is masked.
[    3.928638] systemd[1]: Listening on Journal Socket.
[    3.941122] systemd[1]: Listening on Syslog Socket.
[    3.953397] systemd[1]: Created slice User and Session Slice.
[    3.966028] systemd[1]: Listening on Journal Socket (/dev/log).
[    3.979112] systemd[1]: Listening on udev Kernel Socket.
[    3.991711] systemd[1]: Listening on udev Control Socket.
[    4.071983] usb 1-1.1.1: new high-speed USB device number 4 using dwc_otg
[    4.188703] i2c /dev entries driver
[    4.212422] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
[    4.212435] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.477297] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
[    4.478284] libphy: lan78xx-mdiobus: probed
[    4.500040] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
[    4.542391] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    4.662496] systemd-journald[98]: Received request to flush runtime journal from PID 1
[    5.476888] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    5.490712] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    5.490728] [vc_sm_connected_init]: start
[    5.491167] media: Linux media interface: v0.10
[    5.494145] [vc_sm_connected_init]: installed successfully
[    5.536566] videodev: Linux video capture interface: v2.00
[    5.546079] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    5.556148] bcm2835_audio soc:audio: card created with 8 channels
[    5.590131] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.634150] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    5.698393] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    5.772142] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    5.781236] rpi-sense 1-0046: Raspberry Pi Sense HAT firmware version 0
[    5.859872] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    5.903655] input: Raspberry Pi Sense HAT Joystick as /devices/virtual/input/input0
[    5.960717] brcmfmac: F1 signature read @0x18000000=0x15264345
[    5.970901] fb1: RPi-Sense FB frame buffer device
[    5.971198] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    5.972302] usbcore: registered new interface driver brcmfmac
[    6.079546] Adding 823804k swap on /dev/mmcblk0p4.  Priority:-2 extents:1 across:823804k SSFS
[    6.214583] random: crng init done
[    6.214598] random: 7 urandom warning(s) missed due to ratelimiting
[    6.241436] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    6.262578] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
[    6.266788] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    6.266800] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    6.271481] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    6.271496] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    6.277189] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    6.277202] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    6.336008] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
[    7.611975] uart-pl011 3f201000.serial: no DMA platform data
[    7.836083] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    8.284684] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    8.284885] brcmfmac: power management disabled
[    8.840595] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   12.291821] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
[   12.661894] usb 1-1.3: device descriptor read/64, error -71
[   13.711810] usb 1-1.3: device descriptor read/64, error -71
[   13.931836] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
[   14.052110] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   14.062787] usb 1-1.3: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[   14.062796] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   14.062800] usb 1-1.3: Product: RNDIS/Ethernet Gadget
[   14.062804] usb 1-1.3: Manufacturer: Linux 4.19.36+ with 20980000.usb
[   14.100199] cdc_subset: probe of 1-1.3:1.0 failed with error -22
[   14.103666] cdc_subset 1-1.3:1.1 usb0: register 'cdc_subset' at usb-3f980000.usb-1.3, Linux Device, a6:cc:28:bb:51:7f
[   14.103918] cdc_ether: probe of 1-1.3:1.0 failed with error -16
[   14.103959] usbcore: registered new interface driver cdc_ether
[   14.105144] usbcore: registered new interface driver cdc_subset
[   14.144355] br0: port 1(usb0) entered blocking state
[   14.144363] br0: port 1(usb0) entered disabled state
[   14.144800] device usb0 entered promiscuous mode
[   14.148359] br0: port 1(usb0) entered blocking state
[   14.148369] br0: port 1(usb0) entered forwarding state
[   14.168672] Bluetooth: Core ver 2.22
[   14.168769] NET: Registered protocol family 31
[   14.168772] Bluetooth: HCI device and connection manager initialized
[   14.168791] Bluetooth: HCI socket layer initialized
[   14.168801] Bluetooth: L2CAP socket layer initialized
[   14.168836] Bluetooth: SCO socket layer initialized
[   14.171942] usb 1-1.1.2: new high-speed USB device number 6 using dwc_otg
[   14.183822] Bluetooth: HCI UART driver ver 2.3
[   14.183834] Bluetooth: HCI UART protocol H4 registered
[   14.183946] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   14.184126] Bluetooth: HCI UART protocol Broadcom registered
[   14.308473] usb 1-1.1.2: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[   14.308491] usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   14.308498] usb 1-1.1.2: Product: RNDIS/Ethernet Gadget
[   14.308506] usb 1-1.1.2: Manufacturer: Linux 4.19.36+ with 20980000.usb
[   14.312108] cdc_subset: probe of 1-1.1.2:1.0 failed with error -22
[   14.316162] cdc_ether 1-1.1.2:1.0 usb1: register 'cdc_ether' at usb-3f980000.usb-1.1.2, CDC Ethernet Device, 62:35:4c:93:cb:9b
[   14.415938] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   14.415961] Bluetooth: BNEP filters: protocol multicast
[   14.415993] Bluetooth: BNEP socket layer initialized
[   14.491745] br0: port 2(usb1) entered blocking state
[   14.491756] br0: port 2(usb1) entered disabled state
[   14.492958] device usb1 entered promiscuous mode
[   14.497026] IPv6: ADDRCONF(NETDEV_UP): usb1: link is not ready
[   14.497039] br0: port 2(usb1) entered blocking state
[   14.497044] br0: port 2(usb1) entered forwarding state
[   14.720613] Bluetooth: RFCOMM TTY layer initialized
[   14.720642] Bluetooth: RFCOMM socket layer initialized
[   14.720661] Bluetooth: RFCOMM ver 1.11
[   14.872130] br0: port 2(usb1) entered disabled state
[   25.734930] IPv6: ADDRCONF(NETDEV_CHANGE): usb1: link becomes ready
[   25.735073] br0: port 2(usb1) entered blocking state
[   25.735083] br0: port 2(usb1) entered forwarding state
[   25.771918] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

[   46.071794] ------------[ cut here ]------------
[   46.071839] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x294/0x298
[   46.071851] NETDEV WATCHDOG: usb1 (cdc_ether): transmit queue 0 timed out
[   46.071860] Modules linked in: rfcomm bnep hci_uart btbcm serdev bluetooth ecdh_generic cdc_ether cdc_subset bridge stp llc ip6table_filter ip6t_MASQUERADE ip6table_nat nf_nat_ipv6 ip6_tables iptable_filter ipt_MASQUERADE xt_nat xt_tcpudp iptable_nat nf_nat_ipv4 nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 evdev rpisense_fb syscopyarea brcmfmac sysfillrect sysimgblt fb_sys_fops rpisense_js brcmutil sha256_generic rpisense_core cfg80211 bcm2835_codec(C) bcm2835_v4l2(C) rfkill v4l2_mem2mem v4l2_common bcm2835_mmal_vchiq(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common snd_bcm2835(C) snd_pcm videodev media snd_timer raspberrypi_hwmon hwmon vc_sm_cma(C) snd i2c_bcm2835 fixed uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6
[   46.072436] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G         C        4.19.37-v7+ #1216
[   46.072442] Hardware name: BCM2835
[   46.072471] [<80111eac>] (unwind_backtrace) from [<8010d430>] (show_stack+0x20/0x24)
[   46.072490] [<8010d430>] (show_stack) from [<8080e880>] (dump_stack+0xd4/0x118)
[   46.072509] [<8080e880>] (dump_stack) from [<80120904>] (__warn+0x104/0x11c)
[   46.072525] [<80120904>] (__warn) from [<80120974>] (warn_slowpath_fmt+0x58/0x74)
[   46.072540] [<80120974>] (warn_slowpath_fmt) from [<807352b0>] (dev_watchdog+0x294/0x298)
[   46.072561] [<807352b0>] (dev_watchdog) from [<8019654c>] (call_timer_fn+0x3c/0x198)
[   46.072580] [<8019654c>] (call_timer_fn) from [<80196794>] (expire_timers+0xec/0x14c)
[   46.072597] [<80196794>] (expire_timers) from [<801968ac>] (run_timer_softirq+0xb8/0x1ec)
[   46.072614] [<801968ac>] (run_timer_softirq) from [<80102388>] (__do_softirq+0x190/0x3f0)
[   46.072631] [<80102388>] (__do_softirq) from [<801268dc>] (irq_exit+0xfc/0x120)
[   46.072650] [<801268dc>] (irq_exit) from [<8017eed8>] (__handle_domain_irq+0x70/0xc4)
[   46.072673] [<8017eed8>] (__handle_domain_irq) from [<801021b4>] (bcm2836_arm_irqchip_handle_irq+0x60/0xa4)
[   46.072687] [<801021b4>] (bcm2836_arm_irqchip_handle_irq) from [<801019bc>] (__irq_svc+0x5c/0x7c)
[   46.072694] Exception stack(0x80d01ee8 to 0x80d01f30)
[   46.072706] 1ee0:                   80109a04 00000000 40000093 40000093 80d04d70 80d00000
[   46.072719] 1f00: 80d04db8 00000001 80d8e47e b77ffa00 80c63a38 80d01f44 80d0517c 80d01f38
[   46.072727] 1f20: 00000000 80109a08 40000013 ffffffff
[   46.072745] [<801019bc>] (__irq_svc) from [<80109a08>] (arch_cpu_idle+0x34/0x4c)
[   46.072763] [<80109a08>] (arch_cpu_idle) from [<8082b8d4>] (default_idle_call+0x34/0x48)
[   46.072782] [<8082b8d4>] (default_idle_call) from [<80152478>] (do_idle+0xec/0x17c)
[   46.072800] [<80152478>] (do_idle) from [<801527c8>] (cpu_startup_entry+0x28/0x2c)
[   46.072816] [<801527c8>] (cpu_startup_entry) from [<80824fe4>] (rest_init+0xbc/0xc0)
[   46.072835] [<80824fe4>] (rest_init) from [<80c00fb0>] (start_kernel+0x484/0x4b4)
[   46.072848] ---[ end trace f91d15236d9d5cd9 ]---
[   46.073615] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

[   76.068545] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
pelwell commented 5 years ago

I'm not surprised it fails:

    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=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1

The fix was to modify the dtb to include the necessary command line parameter, but clearly for some reason that hasn't worked.

m1027 commented 5 years ago

Please retest with latest rpi-update firmware.

It doesn't work with latest kernel 4.19.37-v7+ (hash 18e0a0f9a31e7a3a47d9c4301c7705b980ab0516) and without specifying the /boot/cmdline.txt parameter "coherent_pool". I can (more or less) ping the first slave Raspberry Pi, but cannot ping the second one.

Similar here. With coherent_pool it works, without I get this:

[ 36.289695] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

[ 203.127427] ------------[ cut here ]------------ [ 203.132153] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x288/0x28c [ 203.140554] NETDEV WATCHDOG: eth_lan0 (asix): transmit queue 0 timed out [ 203.147387] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.37-v7+ #42 [ 203.153908] Hardware name: BCM2835 [ 203.157375] [<8010d3b4>] (unwind_backtrace) from [<8010ac6c>] (show_stack+0x10/0x14) [ 203.165218] [<8010ac6c>] (show_stack) from [<8083f724>] (dump_stack+0x98/0xb8) [ 203.172482] [<8083f724>] (dump_stack) from [<80121e6c>] (warn+0xd0/0xec) [ 203.179395] [<80121e6c>] (warn) from [<80121b20>] (warn_slowpath_fmt+0x38/0x48) [ 203.186922] [<80121b20>] (warn_slowpath_fmt) from [<806fff54>] (dev_watchdog+0x288/0x28c) [ 203.195149] [<806fff54>] (dev_watchdog) from [<801824cc>] (call_timer_fn+0x24/0x94) [ 203.202850] [<801824cc>] (call_timer_fn) from [<801825d8>] (expire_timers+0x9c/0xa8) [ 203.212948] [<801825d8>] (expire_timers) from [<80182678>] (run_timer_softirq+0x94/0x1a8) [ 203.226018] [<80182678>] (run_timer_softirq) from [<8010210c>] (__do_softirq+0x114/0x278) [ 203.239362] unwind: Unknown symbol address 8010210c [ 203.246870] unwind: Index not found 8010210c [ 203.253697] ---[ end trace 8207672d8a842813 ]--- [ 204.908228] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

My cmdline is:

console=ttyAMA0,115200n8 console=tty1 root=/dev/sda3 rootfstype=btrfs rootwait init=/usr/lib/systemd/systemd usbcore.autosuspend=-1 coherent_pool=4M

pelwell commented 5 years ago

It appears that only the non-WiFi DTBs have been updated in the firmware repo - bm2710-rpi-3-b.dtb, bcm2710-rpi-3-b-plus.dtb and bcm2708-rpi-0-w.dtb are unchanged. Building the DTBs myself gives the same result - doh! The WiFi/BT equipped Pis use the other UART - an 8250 clone - which requires that "8250.nr_uarts=1" is in the kernel command line. I told @P33M that the firmware has special handling for the bootargs property that allows overlays to append to the kernel command line. However, this doesn't apply during the building of the DTBs, so the updating of bootargs to add the 8250 parameter overwrites the coherent_pool parameter.

591bd5452ad fixes the DTBs for the remaining Pis by explicitly including the coherent_pool setting wherever bootargs is defined.

P33M commented 5 years ago

And of course I was testing on a Pi2 due to simultaneous debugging of smsc95xx and not a 3b+... derp

m1027 commented 5 years ago

591bd54 fixes the DTBs for the remaining Pis by explicitly including the coherent_pool setting wherever bootargs is defined.

Ok, for completeness: After applying the abovementioned commit, coherent_pool does obviously not need to be configured on the cmdline anymore as you apply it internally in any case.

Thank's a lot for all your support on fixing this issue.

As my box is doing well without issues I'll close this issue now.

macmpi commented 5 years ago

Shouldn't we keep this issue opened until a definitive fix is applied, since current solution seems more of workaround at this point?

P33M commented 5 years ago

Correct, the coherent pool is a memory reservation that's unavailable to other users. Ideally dwc_otg should not allocate in atomic context at all, but there's a pile of edge cases under the heading "we're partway through a transfer and find we have to do an unaligned DMA" that need understanding.

macmpi commented 5 years ago

Ideally dwc_otg should not allocate in atomic context at all

Is this been tracked/worked-out upstream somewhere? Thanks.

pelwell commented 5 years ago

Is this been tracked/worked-out upstream somewhere? Thanks.

dwc_otg is a downstream-only driver, so no.

ghost commented 5 years ago

I'm getting a similar stack trace on my Pi 1:

Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Booting Linux on physical CPU 0x0 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Linux version 4.19.42+ (dom@dom-XPS-13-9370) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1219 Tue May 14 21:16:38 BST 2019 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d Jun 14 15:50:41 raspi2 kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache Jun 14 15:50:41 raspi2 kernel: [ 0.000000] OF: fdt: Machine model: Raspberry Pi Model B Rev 1 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Memory policy: Data cache writeback Jun 14 15:50:41 raspi2 kernel: [ 0.000000] cma: Reserved 8 MiB at 0x0e400000 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] random: get_random_bytes called from start_kernel+0x8c/0x49c with crng_init=0 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 60900 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Kernel command line: coherent_pool=1M bcm2708_fb.fbwidth=720 bcm2708_fb.fbheight=480 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 vc_mem.mem_base=0xfa00000 vc_mem.mem_size=0x10000000 dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=63242b5f-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait ipv6.disable=1 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Memory: 223564K/245760K available (6932K kernel code, 633K rwdata, 2068K rodata, 456K init, 797K bss, 14004K reserved, 8192K cma-reserved) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] Virtual kernel memory layout: Jun 14 15:50:41 raspi2 kernel: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] vmalloc : 0xcf800000 - 0xff800000 ( 768 MB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] lowmem : 0xc0000000 - 0xcf000000 ( 240 MB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] modules : 0xbf000000 - 0xc0000000 ( 16 MB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] .text : 0x(ptrval) - 0x(ptrval) (6934 kB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] .init : 0x(ptrval) - 0x(ptrval) ( 456 kB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] .data : 0x(ptrval) - 0x(ptrval) ( 634 kB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] .bss : 0x(ptrval) - 0x(ptrval) ( 798 kB) Jun 14 15:50:41 raspi2 kernel: [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 Jun 14 15:50:41 raspi2 kernel: [ 0.000000] ftrace: allocating 25044 entries in 74 pages Jun 14 15:50:41 raspi2 kernel: [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 Jun 14 15:50:41 raspi2 kernel: [ 0.000029] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns Jun 14 15:50:41 raspi2 kernel: [ 0.000086] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns Jun 14 15:50:41 raspi2 kernel: [ 0.000194] bcm2835: system timer (irq = 27) Jun 14 15:50:41 raspi2 kernel: [ 0.000794] Console: colour dummy device 80x30 Jun 14 15:50:41 raspi2 kernel: [ 0.001423] console [tty1] enabled Jun 14 15:50:41 raspi2 kernel: [ 0.001505] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792) Jun 14 15:50:41 raspi2 kernel: [ 0.060374] pid_max: default: 32768 minimum: 301 Jun 14 15:50:41 raspi2 kernel: [ 0.060964] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.061023] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.062485] CPU: Testing write buffer coherency: ok Jun 14 15:50:41 raspi2 kernel: [ 0.063881] Setting up static identity map for 0x8200 - 0x8238 Jun 14 15:50:41 raspi2 kernel: [ 0.065310] devtmpfs: initialized Jun 14 15:50:41 raspi2 kernel: [ 0.076164] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5 Jun 14 15:50:41 raspi2 kernel: [ 0.076650] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns Jun 14 15:50:41 raspi2 kernel: [ 0.076726] futex hash table entries: 256 (order: -1, 3072 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.078122] pinctrl core: initialized pinctrl subsystem Jun 14 15:50:41 raspi2 kernel: [ 0.079732] NET: Registered protocol family 16 Jun 14 15:50:41 raspi2 kernel: [ 0.082977] DMA: preallocated 1024 KiB pool for atomic coherent allocations Jun 14 15:50:41 raspi2 kernel: [ 0.090135] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers. Jun 14 15:50:41 raspi2 kernel: [ 0.090212] hw-breakpoint: maximum watchpoint size is 4 bytes. Jun 14 15:50:41 raspi2 kernel: [ 0.090384] Serial: AMBA PL011 UART driver Jun 14 15:50:41 raspi2 kernel: [ 0.094071] bcm2835-mbox 2000b880.mailbox: mailbox enabled Jun 14 15:50:41 raspi2 kernel: [ 0.136638] bcm2835-dma 20007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1 Jun 14 15:50:41 raspi2 kernel: [ 0.139219] SCSI subsystem initialized Jun 14 15:50:41 raspi2 kernel: [ 0.139543] usbcore: registered new interface driver usbfs Jun 14 15:50:41 raspi2 kernel: [ 0.139690] usbcore: registered new interface driver hub Jun 14 15:50:41 raspi2 kernel: [ 0.139955] usbcore: registered new device driver usb Jun 14 15:50:41 raspi2 kernel: [ 0.150898] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-03-27 15:46, variant start_cd Jun 14 15:50:41 raspi2 kernel: [ 0.160921] raspberrypi-firmware soc:firmware: Firmware hash is 2e98b31d18547962e564bdf88e57b3df7085c29b Jun 14 15:50:41 raspi2 kernel: [ 0.173285] clocksource: Switched to clocksource timer Jun 14 15:50:41 raspi2 kernel: [ 0.274679] VFS: Disk quotas dquot_6.6.0 Jun 14 15:50:41 raspi2 kernel: [ 0.274866] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.275234] FS-Cache: Loaded Jun 14 15:50:41 raspi2 kernel: [ 0.275613] CacheFiles: Loaded Jun 14 15:50:41 raspi2 kernel: [ 0.294583] NET: Registered protocol family 2 Jun 14 15:50:41 raspi2 kernel: [ 0.295967] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.296089] TCP established hash table entries: 2048 (order: 1, 8192 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.296168] TCP bind hash table entries: 2048 (order: 1, 8192 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.296245] TCP: Hash tables configured (established 2048 bind 2048) Jun 14 15:50:41 raspi2 kernel: [ 0.296438] UDP hash table entries: 256 (order: 0, 4096 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.296503] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes) Jun 14 15:50:41 raspi2 kernel: [ 0.296952] NET: Registered protocol family 1 Jun 14 15:50:41 raspi2 kernel: [ 0.298123] RPC: Registered named UNIX socket transport module. Jun 14 15:50:41 raspi2 kernel: [ 0.298188] RPC: Registered udp transport module. Jun 14 15:50:41 raspi2 kernel: [ 0.298217] RPC: Registered tcp transport module. Jun 14 15:50:41 raspi2 kernel: [ 0.298244] RPC: Registered tcp NFSv4.1 backchannel transport module. Jun 14 15:50:41 raspi2 kernel: [ 0.300372] hw perfevents: no irqs for PMU, sampling events not supported Jun 14 15:50:41 raspi2 kernel: [ 0.300500] hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available Jun 14 15:50:41 raspi2 kernel: [ 0.304675] Initialise system trusted keyrings Jun 14 15:50:41 raspi2 kernel: [ 0.305142] workingset: timestamp_bits=14 max_order=16 bucket_order=2 Jun 14 15:50:41 raspi2 kernel: [ 0.319968] FS-Cache: Netfs 'nfs' registered for caching Jun 14 15:50:41 raspi2 kernel: [ 0.321352] NFS: Registering the id_resolver key type Jun 14 15:50:41 raspi2 kernel: [ 0.321450] Key type id_resolver registered Jun 14 15:50:41 raspi2 kernel: [ 0.321483] Key type id_legacy registered Jun 14 15:50:41 raspi2 kernel: [ 0.321534] nfs4filelayout_init: NFSv4 File Layout Driver Registering... Jun 14 15:50:41 raspi2 kernel: [ 0.327269] Key type asymmetric registered Jun 14 15:50:41 raspi2 kernel: [ 0.327339] Asymmetric key parser 'x509' registered Jun 14 15:50:41 raspi2 kernel: [ 0.327476] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) Jun 14 15:50:41 raspi2 kernel: [ 0.327991] io scheduler noop registered Jun 14 15:50:41 raspi2 kernel: [ 0.328048] io scheduler deadline registered (default) Jun 14 15:50:41 raspi2 kernel: [ 0.328684] io scheduler cfq registered Jun 14 15:50:41 raspi2 kernel: [ 0.328735] io scheduler mq-deadline registered (default) Jun 14 15:50:41 raspi2 kernel: [ 0.328769] io scheduler kyber registered Jun 14 15:50:41 raspi2 kernel: [ 0.331960] BCM2708FB: allocated DMA memory 0x4e500000 Jun 14 15:50:41 raspi2 kernel: [ 0.332077] BCM2708FB: allocated DMA channel 0 Jun 14 15:50:41 raspi2 kernel: [ 0.338414] Console: switching to colour frame buffer device 90x30 Jun 14 15:50:41 raspi2 kernel: [ 0.347538] bcm2835-rng 20104000.rng: hwrng registered Jun 14 15:50:41 raspi2 kernel: [ 0.349842] vc-mem: phys_addr:0x00000000 mem_base=0x0fa00000 mem_size:0x10000000(256 MiB) Jun 14 15:50:41 raspi2 kernel: [ 0.355163] vc-sm: Videocore shared memory driver Jun 14 15:50:41 raspi2 kernel: [ 0.357904] gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000 Jun 14 15:50:41 raspi2 kernel: [ 0.380646] brd: module loaded Jun 14 15:50:41 raspi2 kernel: [ 0.396283] loop: module loaded Jun 14 15:50:41 raspi2 kernel: [ 0.398362] Loading iSCSI transport class v2.0-870. Jun 14 15:50:41 raspi2 kernel: [ 0.401296] usbcore: registered new interface driver smsc95xx Jun 14 15:50:41 raspi2 kernel: [ 0.403475] dwc_otg: version 3.00a 10-AUG-2012 (platform bus) Jun 14 15:50:41 raspi2 kernel: [ 0.433537] dwc_otg 20980000.usb: base=(ptrval) Jun 14 15:50:41 raspi2 kernel: [ 0.636034] Core Release: 2.80a Jun 14 15:50:41 raspi2 kernel: [ 0.638044] Setting default values for core params Jun 14 15:50:41 raspi2 kernel: [ 0.640007] Finished setting default values for core params Jun 14 15:50:41 raspi2 kernel: [ 0.842378] Using Buffer DMA mode Jun 14 15:50:41 raspi2 kernel: [ 0.844413] Periodic Transfer Interrupt Enhancement - disabled Jun 14 15:50:41 raspi2 kernel: [ 0.846350] Multiprocessor Interrupt Enhancement - disabled Jun 14 15:50:41 raspi2 kernel: [ 0.848274] OTG VER PARAM: 0, OTG VER FLAG: 0 Jun 14 15:50:41 raspi2 kernel: [ 0.850290] Dedicated Tx FIFOs mode Jun 14 15:50:41 raspi2 kernel: [ 0.853186] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = ce514000 dma = 0x4e514000 len=9024 Jun 14 15:50:41 raspi2 kernel: [ 0.857395] FIQ FSM acceleration enabled for : Jun 14 15:50:41 raspi2 kernel: [ 0.857395] Non-periodic Split Transactions Jun 14 15:50:41 raspi2 kernel: [ 0.857395] Periodic Split Transactions Jun 14 15:50:41 raspi2 kernel: [ 0.857395] High-Speed Isochronous Endpoints Jun 14 15:50:41 raspi2 kernel: [ 0.857395] Interrupt/Control Split Transaction hack enabled Jun 14 15:50:41 raspi2 kernel: [ 0.867684] WARN::hcd_init_fiq:457: FIQ on core 0 Jun 14 15:50:41 raspi2 kernel: [ 0.869676] WARN::hcd_init_fiq:458: FIQ ASM at c04f48a0 length 36 Jun 14 15:50:41 raspi2 kernel: [ 0.871623] WARN::hcd_init_fiq:484: MPHI regs_base at f0006000 Jun 14 15:50:41 raspi2 kernel: [ 0.873677] dwc_otg 20980000.usb: DWC OTG Controller Jun 14 15:50:41 raspi2 kernel: [ 0.875656] dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1 Jun 14 15:50:41 raspi2 kernel: [ 0.877668] dwc_otg 20980000.usb: irq 56, io mem 0x00000000 Jun 14 15:50:41 raspi2 kernel: [ 0.879626] Init: Port Power? op_state=1 Jun 14 15:50:41 raspi2 kernel: [ 0.881494] Init: Power Port (0) Jun 14 15:50:41 raspi2 kernel: [ 0.883815] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19 Jun 14 15:50:41 raspi2 kernel: [ 0.887638] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 Jun 14 15:50:41 raspi2 kernel: [ 0.889673] usb usb1: Product: DWC OTG Controller Jun 14 15:50:41 raspi2 kernel: [ 0.891674] usb usb1: Manufacturer: Linux 4.19.42+ dwc_otg_hcd Jun 14 15:50:41 raspi2 kernel: [ 0.893753] usb usb1: SerialNumber: 20980000.usb Jun 14 15:50:41 raspi2 kernel: [ 0.896941] hub 1-0:1.0: USB hub found Jun 14 15:50:41 raspi2 kernel: [ 0.899083] hub 1-0:1.0: 1 port detected Jun 14 15:50:41 raspi2 kernel: [ 0.902705] usbcore: registered new interface driver usb-storage Jun 14 15:50:41 raspi2 kernel: [ 0.905385] mousedev: PS/2 mouse device common for all mice Jun 14 15:50:41 raspi2 kernel: [ 0.908824] bcm2835-wdt 20100000.watchdog: Broadcom BCM2835 watchdog timer Jun 14 15:50:41 raspi2 kernel: [ 0.911400] bcm2835-cpufreq: min=700000 max=700000 Jun 14 15:50:41 raspi2 kernel: [ 0.914206] sdhci: Secure Digital Host Controller Interface driver Jun 14 15:50:41 raspi2 kernel: [ 0.916230] sdhci: Copyright(c) Pierre Ossman Jun 14 15:50:41 raspi2 kernel: [ 0.918860] sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe Jun 14 15:50:41 raspi2 kernel: [ 0.921178] sdhci-pltfm: SDHCI platform and OF driver helper Jun 14 15:50:41 raspi2 kernel: [ 0.923986] ledtrig-cpu: registered to indicate activity on CPUs Jun 14 15:50:41 raspi2 kernel: [ 0.926249] hidraw: raw HID events driver (C) Jiri Kosina Jun 14 15:50:41 raspi2 kernel: [ 0.928609] usbcore: registered new interface driver usbhid Jun 14 15:50:41 raspi2 kernel: [ 0.930723] usbhid: USB HID core driver Jun 14 15:50:41 raspi2 kernel: [ 0.933944] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0 Jun 14 15:50:41 raspi2 kernel: [ 0.938243] [vc_sm_connected_init]: start Jun 14 15:50:41 raspi2 kernel: [ 0.946992] [vc_sm_connected_init]: end - returning -1 Jun 14 15:50:41 raspi2 kernel: [ 0.950929] Initializing XFRM netlink socket Jun 14 15:50:41 raspi2 kernel: [ 0.953158] NET: Registered protocol family 17 Jun 14 15:50:41 raspi2 kernel: [ 0.955433] Key type dns_resolver registered Jun 14 15:50:41 raspi2 kernel: [ 0.959276] registered taskstats version 1 Jun 14 15:50:41 raspi2 kernel: [ 0.961335] Loading compiled-in X.509 certificates Jun 14 15:50:41 raspi2 kernel: [ 0.976193] sdhost: log_buf @ (ptrval) (4e513000) Jun 14 15:50:41 raspi2 kernel: [ 1.025719] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) Jun 14 15:50:41 raspi2 kernel: [ 1.029449] of_cfs_init Jun 14 15:50:41 raspi2 kernel: [ 1.031663] of_cfs_init: OK Jun 14 15:50:41 raspi2 kernel: [ 1.054986] Waiting for root device PARTUUID=63242b5f-02... Jun 14 15:50:41 raspi2 kernel: [ 1.067454] random: fast init done Jun 14 15:50:41 raspi2 kernel: [ 1.095587] mmc0: host does not support reading read-only switch, assuming write-enable Jun 14 15:50:41 raspi2 kernel: [ 1.100331] mmc0: new high speed SDHC card at address 0002 Jun 14 15:50:41 raspi2 kernel: [ 1.104102] mmcblk0: mmc0:0002 00000 3.70 GiB Jun 14 15:50:41 raspi2 kernel: [ 1.108904] mmcblk0: p1 p2 Jun 14 15:50:41 raspi2 kernel: [ 1.114323] Indeed it is in host mode hprt0 = 00021501 Jun 14 15:50:41 raspi2 kernel: [ 1.196002] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) Jun 14 15:50:41 raspi2 kernel: [ 1.200188] VFS: Mounted root (ext4 filesystem) readonly on device 179:2. Jun 14 15:50:41 raspi2 kernel: [ 1.215470] devtmpfs: mounted Jun 14 15:50:41 raspi2 kernel: [ 1.222651] Freeing unused kernel memory: 456K Jun 14 15:50:41 raspi2 kernel: [ 1.224875] This architecture does not have kernel memory protection. Jun 14 15:50:41 raspi2 kernel: [ 1.226987] Run /sbin/init as init process Jun 14 15:50:41 raspi2 kernel: [ 1.323412] usb 1-1: new high-speed USB device number 2 using dwc_otg Jun 14 15:50:41 raspi2 kernel: [ 1.326125] Indeed it is in host mode hprt0 = 00001101 Jun 14 15:50:41 raspi2 kernel: [ 1.563924] usb 1-1: New USB device found, idVendor=0424, idProduct=9512, bcdDevice= 2.00 Jun 14 15:50:41 raspi2 kernel: [ 1.568491] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Jun 14 15:50:41 raspi2 kernel: [ 1.572435] hub 1-1:1.0: USB hub found Jun 14 15:50:41 raspi2 kernel: [ 1.575588] hub 1-1:1.0: 3 ports detected Jun 14 15:50:41 raspi2 kernel: [ 1.893442] usb 1-1.1: new high-speed USB device number 3 using dwc_otg Jun 14 15:50:41 raspi2 kernel: [ 2.023954] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00 Jun 14 15:50:41 raspi2 kernel: [ 2.028775] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Jun 14 15:50:41 raspi2 kernel: [ 2.036127] smsc95xx v1.0.6 Jun 14 15:50:41 raspi2 kernel: [ 2.131568] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-20980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:cd:4f:34 Jun 14 15:50:41 raspi2 kernel: [ 2.233402] usb 1-1.2: new full-speed USB device number 4 using dwc_otg Jun 14 15:50:41 raspi2 kernel: [ 2.316604] IPv6: Loaded, but administratively disabled, reboot required to enable Jun 14 15:50:41 raspi2 kernel: [ 2.367731] random: systemd: uninitialized urandom read (16 bytes read) Jun 14 15:50:41 raspi2 kernel: [ 2.398536] usb 1-1.2: New USB device found, idVendor=239a, idProduct=800c, bcdDevice= 1.00 Jun 14 15:50:41 raspi2 kernel: [ 2.404066] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Jun 14 15:50:41 raspi2 kernel: [ 2.406821] usb 1-1.2: Product: Feather 32u4 Jun 14 15:50:41 raspi2 kernel: [ 2.409491] usb 1-1.2: Manufacturer: Adafruit Jun 14 15:50:41 raspi2 kernel: [ 2.484929] random: systemd: uninitialized urandom read (16 bytes read) Jun 14 15:50:41 raspi2 kernel: [ 2.770320] random: systemd-gpt-aut: uninitialized urandom read (16 bytes read) Jun 14 15:50:41 raspi2 kernel: [ 3.984665] i2c /dev entries driver Jun 14 15:50:41 raspi2 kernel: [ 6.113180] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null) Jun 14 15:50:41 raspi2 kernel: [ 9.241193] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Jun 14 15:50:41 raspi2 kernel: [ 9.248647] bcm2835_vc_sm_cma_probe: Videocore shared memory driver Jun 14 15:50:41 raspi2 kernel: [ 9.248674] [vc_sm_connected_init]: start Jun 14 15:50:41 raspi2 kernel: [ 9.248992] [vc_sm_connected_init]: failed, ret -1 Jun 14 15:50:41 raspi2 kernel: [ 9.253003] media: Linux media interface: v0.10 Jun 14 15:50:41 raspi2 kernel: [ 9.391816] videodev: Linux video capture interface: v2.00 Jun 14 15:50:41 raspi2 kernel: [ 9.519442] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Jun 14 15:50:41 raspi2 kernel: [ 9.553681] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Jun 14 15:50:41 raspi2 kernel: [ 9.562465] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Jun 14 15:50:41 raspi2 kernel: [ 9.591514] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Jun 14 15:50:41 raspi2 kernel: [ 12.553778] cdc_acm 1-1.2:1.0: ttyACM0: USB ACM device Jun 14 15:50:41 raspi2 kernel: [ 12.601825] usbcore: registered new interface driver cdc_acm Jun 14 15:50:41 raspi2 kernel: [ 12.601844] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters Jun 14 15:50:41 raspi2 kernel: [ 13.808358] random: crng init done Jun 14 15:50:41 raspi2 kernel: [ 13.808382] random: 7 urandom warning(s) missed due to ratelimiting Jun 14 15:50:42 raspi2 kernel: [ 14.940258] cfg80211: Loading compiled-in X.509 certificates for regulatory database Jun 14 15:50:42 raspi2 kernel: [ 15.144806] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Jun 14 15:50:43 raspi2 kernel: [ 15.883010] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Jun 14 15:50:44 raspi2 kernel: [ 16.954025] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS Jun 14 15:50:44 raspi2 kernel: [ 17.351594] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1 Jun 14 15:51:30 raspi2 smokeping[409]: Starting syslog logging Jun 14 15:51:30 raspi2 smokeping[667]: Smokeping version 2.006011 successfully launched. Jun 14 15:51:30 raspi2 smokeping[667]: Not entering multiprocess mode for just a single probe. Jun 14 15:51:30 raspi2 smokeping[667]: FPing: probing 1 targets with step 10 s and offset 9 s. Jun 14 15:52:22 raspi2 /temps.py: Starting up Jun 14 23:58:49 raspi2 kernel: [29284.909880] ------------[ cut here ]------------ Jun 14 23:58:49 raspi2 kernel: [29284.909937] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x26c/0x288 Jun 14 23:58:49 raspi2 kernel: [29284.909948] NETDEV WATCHDOG: eth0 (smsc95xx): transmit queue 0 timed out Jun 14 23:58:49 raspi2 kernel: [29284.909954] Modules linked in: sha256_generic cfg80211 rfkill cdc_acm raspberrypi_hwmon hwmon bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) v4l2_common videobuf2_dma_contig videobuf2_vmalloc i2c_bcm2835 videobuf2_memops videobuf2_v4l2 videobuf2_common videodev media vc_sm_cma(C) fixed uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6 Jun 14 23:58:49 raspi2 kernel: [29284.910137] CPU: 0 PID: 0 Comm: swapper Tainted: G C 4.19.42+ #1219 Jun 14 23:58:49 raspi2 kernel: [29284.910145] Hardware name: BCM2835 Jun 14 23:58:49 raspi2 kernel: [29284.910193] [] (unwind_backtrace) from [] (show_stack+0x20/0x24) Jun 14 23:58:49 raspi2 kernel: [29284.910236] [] (show_stack) from [] (dump_stack+0x20/0x28) Jun 14 23:58:49 raspi2 kernel: [29284.910322] [] (dump_stack) from [] (warn+0xf4/0x11c) Jun 14 23:58:49 raspi2 kernel: [29284.910357] [] (warn) from [] (warn_slowpath_fmt+0x54/0x74) Jun 14 23:58:49 raspi2 kernel: [29284.910423] [] (warn_slowpath_fmt) from [] (dev_watchdog+0x26c/0x288) Jun 14 23:58:49 raspi2 kernel: [29284.910467] [] (dev_watchdog) from [] (call_timer_fn+0x3c/0x120) Jun 14 23:58:49 raspi2 kernel: [29284.910493] [] (call_timer_fn) from [] (expire_timers+0x9c/0xd8) Jun 14 23:58:49 raspi2 kernel: [29284.910517] [] (expire_timers) from [] (run_timer_softirq+0xa4/0x1ac) Jun 14 23:58:49 raspi2 kernel: [29284.910545] [] (run_timer_softirq) from [] (do_softirq+0x12c/0x344) Jun 14 23:58:49 raspi2 kernel: [29284.910577] [] (__do_softirq) from [] (irq_exit+0xe4/0x100) Jun 14 23:58:49 raspi2 kernel: [29284.910610] [] (irq_exit) from [] (handle_domain_irq+0x60/0xb8) Jun 14 23:58:49 raspi2 kernel: [29284.910634] [] (handle_domain_irq) from [] (bcm2835_handle_irq+0x28/0x48) Jun 14 23:58:49 raspi2 kernel: [29284.910656] [] (bcm2835_handle_irq) from [] (irq_svc+0x5c/0x7c) Jun 14 23:58:49 raspi2 kernel: [29284.910666] Exception stack(0xc09d7ef0 to 0xc09d7f38) Jun 14 23:58:49 raspi2 kernel: [29284.910680] 7ee0: c001155c 00000000 40000093 40000093 Jun 14 23:58:49 raspi2 kernel: [29284.910697] 7f00: c09d6000 c09d9090 c0a66a56 c09d9020 c0a74660 cefffa40 c09b1a30 c09d7f4c Jun 14 23:58:49 raspi2 kernel: [29284.910713] 7f20: c09d941c c09d7f40 00000000 c0011560 40000013 ffffffff Jun 14 23:58:49 raspi2 kernel: [29284.910744] [] (__irq_svc) from [] (arch_cpu_idle+0x30/0x40) Jun 14 23:58:49 raspi2 kernel: [29284.910782] [] (arch_cpu_idle) from [] (default_idle_call+0x34/0x48) Jun 14 23:58:49 raspi2 kernel: [29284.910821] [] (default_idle_call) from [] (do_idle+0x94/0xf4) Jun 14 23:58:49 raspi2 kernel: [29284.910850] [] (do_idle) from [] (cpu_startup_entry+0x1c/0x20) Jun 14 23:58:49 raspi2 kernel: [29284.910874] [] (cpu_startup_entry) from [] (rest_init+0x7c/0x9c) Jun 14 23:58:49 raspi2 kernel: [29284.910899] [] (rest_init) from [] (start_kernel+0x3e8/0x49c) Jun 14 23:58:49 raspi2 kernel: [29284.910913] ---[ end trace 4b5e7be83442ccbe ]---

ghost commented 5 years ago

I've also got a stack trace from a Pi 3B+. As far as I can tell there was nothing particularly happening on my Pi at the time, so from my analysis it looks somewhat random as to when this occurs. Can someone tell me what effect this has on network traffic? Does the network get reset, or does the driver just carry on as if nothing has happened?

Stack trace:

Jun 15 01:28:55 livingroom kernel: [14175.155918] ------------[ cut here ]------------ Jun 15 01:28:55 livingroom kernel: [14175.155961] WARNING: CPU: 1 PID: 85 at net/sched/sch_generic.c:461 dev_watchdog+0x294/0x298 Jun 15 01:28:55 livingroom kernel: [14175.155971] NETDEV WATCHDOG: eth0 (lan78xx): transmit queue 0 timed out Jun 15 01:28:55 livingroom kernel: [14175.155977] Modules linked in: btrfs xor xor_neon zstd_decompress zstd_compress xxhash lzo_compress raid6_pq zlib_deflate evdev sg uas snd_soc_pcm512x_i2c snd_soc_bcm2835_i2s snd_soc_iqaudio_dac snd_soc_pcm512x bcm2835_v4l2(C) bcm2835_codec(C) snd_soc_core v4l2_mem2mem v4l2_common bcm2835_mmal_vchiq(C) snd_compress videobuf2_vmalloc videobuf2_dma_contig snd_pcm_dmaengine videobuf2_memops videobuf2_v4l2 snd_pcm videobuf2_common videodev snd_timer media snd raspberrypi_hwmon hwmon i2c_bcm2835 vc_sm_cma(C) uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6 Jun 15 01:28:55 livingroom kernel: [14175.156243] CPU: 1 PID: 85 Comm: kworker/1:1H Tainted: G C 4.19.42-v7+ #1219 Jun 15 01:28:55 livingroom kernel: [14175.156249] Hardware name: BCM2835 Jun 15 01:28:55 livingroom kernel: [14175.156271] Workqueue: (null) (kblockd) Jun 15 01:28:55 livingroom kernel: [14175.156311] [<80111eac>] (unwind_backtrace) from [<8010d430>] (show_stack+0x20/0x24) Jun 15 01:28:55 livingroom kernel: [14175.156330] [<8010d430>] (show_stack) from [<8080ec80>] (dump_stack+0xd4/0x118) Jun 15 01:28:55 livingroom kernel: [14175.156350] [<8080ec80>] (dump_stack) from [<80120904>] (warn+0x104/0x11c) Jun 15 01:28:55 livingroom kernel: [14175.156366] [<80120904>] (warn) from [<80120974>] (warn_slowpath_fmt+0x58/0x74) Jun 15 01:28:55 livingroom kernel: [14175.156384] [<80120974>] (warn_slowpath_fmt) from [<807355b8>] (dev_watchdog+0x294/0x298) Jun 15 01:28:55 livingroom kernel: [14175.156404] [<807355b8>] (dev_watchdog) from [<801965a0>] (call_timer_fn+0x3c/0x198) Jun 15 01:28:55 livingroom kernel: [14175.156424] [<801965a0>] (call_timer_fn) from [<801967e8>] (expire_timers+0xec/0x14c) Jun 15 01:28:55 livingroom kernel: [14175.156441] [<801967e8>] (expire_timers) from [<80196900>] (run_timer_softirq+0xb8/0x1ec) Jun 15 01:28:55 livingroom kernel: [14175.156459] [<80196900>] (run_timer_softirq) from [<80102388>] (do_softirq+0x190/0x3f0) Jun 15 01:28:55 livingroom kernel: [14175.156478] [<80102388>] (__do_softirq) from [<801268dc>] (irq_exit+0xfc/0x120) Jun 15 01:28:55 livingroom kernel: [14175.156501] [<801268dc>] (irq_exit) from [<8017ef24>] (handle_domain_irq+0x70/0xc4) Jun 15 01:28:55 livingroom kernel: [14175.156522] [<8017ef24>] (handle_domain_irq) from [<801021b4>] (bcm2836_arm_irqchip_handle_irq+0x60/0xa4) Jun 15 01:28:55 livingroom kernel: [14175.156537] [<801021b4>] (bcm2836_arm_irqchip_handle_irq) from [<801019bc>] (irq_svc+0x5c/0x7c) Jun 15 01:28:55 livingroom kernel: [14175.156545] Exception stack(0xb63dfe20 to 0xb63dfe68) Jun 15 01:28:55 livingroom kernel: [14175.156562] fe20: 8014ac30 00000000 40000093 40000093 80c92e40 00000000 a48f1e00 b6fd7e40 Jun 15 01:28:55 livingroom kernel: [14175.156575] fe40: 80826430 b63c8f00 00000002 b63dfeb4 80d0517c b63dfe70 00000000 8014ac34 Jun 15 01:28:55 livingroom kernel: [14175.156581] fe60: 40000013 ffffffff Jun 15 01:28:55 livingroom kernel: [14175.156597] [<801019bc>] (__irq_svc) from [<8014ac34>] (finish_task_switch+0x9c/0x230) Jun 15 01:28:55 livingroom kernel: [14175.156615] [<8014ac34>] (finish_task_switch) from [<80826430>] (schedule+0x390/0x9ac) Jun 15 01:28:55 livingroom kernel: [14175.156631] [<80826430>] (schedule) from [<80826a9c>] (schedule+0x50/0xa8) Jun 15 01:28:55 livingroom kernel: [14175.156646] [<80826a9c>] (schedule) from [<8013c174>] (worker_thread+0x110/0x5a4) Jun 15 01:28:55 livingroom kernel: [14175.156665] [<8013c174>] (worker_thread) from [<801423ac>] (kthread+0x138/0x168) Jun 15 01:28:55 livingroom kernel: [14175.156684] [<801423ac>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28) Jun 15 01:28:55 livingroom kernel: [14175.156692] Exception stack(0xb63dffb0 to 0xb63dfff8) Jun 15 01:28:55 livingroom kernel: [14175.156701] ffa0: 00000000 00000000 00000000 00000000 Jun 15 01:28:55 livingroom kernel: [14175.156713] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 Jun 15 01:28:55 livingroom kernel: [14175.156723] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000 Jun 15 01:28:55 livingroom kernel: [14175.156793] ---[ end trace 7ebdcdba1beb5bca ]---

ghost commented 5 years ago

Just to be clear - my stack traces were not resulting in any crash - I just get the above warning and stack trace, then things seem to carry on as normal.

mkosch commented 5 years ago

I tested my previous setup with a Raspberry Pi 4 B. The two slave Raspberry Pi Zero W are connected to the USB 3.0 ports as USB Ethernet gadgets.

Currently I've got two issues:

First issue: At least after the first boot it appears that sometimes (?) the USB Ethernet devices are not recognized. In this case they don't show up in the output of the ifconfig command.

Second issue: When the USB Ethernet devices are recognized then I can only ping one of them. When pinging the other one I get a "Destination Host Unreachable" error and dmesg shows "transmit queue 0 timed out". I've also tried the parameter coherent_pool=4M inside the configuration file cmdline.txt but this didn't work.

Output from "dmesg" in case the USB Ethernet devices are not recognized:

[    0.000000] Booting Linux on physical CPU 0x0                                                                                                                                 
[    0.000000] Linux version 4.19.58-v7l+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1245 SMP Fri Jul 12 17:31:45 BST 2019               
[    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d                                                                                                   
[    0.000000] CPU: div instructions available: patching division code                                                                                                           
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache                                                                                                   
[    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.1                                                                                                            
[    0.000000] Memory policy: Data cache writealloc                                                                                                                              
[    0.000000] cma: Reserved 256 MiB at 0x000000001ec00000                                                                                                                       
[    0.000000] On node 0 totalpages: 999424                                                                                                                                      
[    0.000000]   DMA zone: 1728 pages used for memmap                                                                                                                            
[    0.000000]   DMA zone: 0 pages reserved                                                                                                                                      
[    0.000000]   DMA zone: 196608 pages, LIFO batch:63                                                                                                                           
[    0.000000]   HighMem zone: 802816 pages, LIFO batch:63                                                                                                                       
[    0.000000] random: get_random_bytes called from start_kernel+0xc0/0x4e8 with crng_init=0                                                                                     
[    0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632                                                                                                          
[    0.000000] pcpu-alloc: s39488 r8192 d21952 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: 997696                                                                                                     
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M cma=256M video=HDMI-A-1:640x480@60 smsc95xx.macaddr=DC:A6:32:0D:A3:94 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait                   
[    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: 3682812K/3997696K available (8192K kernel code, 658K rwdata, 2340K rodata, 2048K init, 850K bss, 52740K reserved, 262144K cma-reserved, 3211264K highmem)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xf0800000 - 0xff800000   ( 240 MB)
                   lowmem  : 0xc0000000 - 0xf0000000   ( 768 MB)
                   pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                   modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                     .text : 0x(ptrval) - 0x(ptrval)   (10208 kB)
                     .init : 0x(ptrval) - 0x(ptrval)   (2048 kB)
                     .data : 0x(ptrval) - 0x(ptrval)   ( 659 kB)
                      .bss : 0x(ptrval) - 0x(ptrval)   ( 851 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 27981 entries in 83 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000005] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000022] Switching to timer-based delay loop, resolution 18ns
[    0.000248] Console: colour dummy device 80x30
[    0.000738] console [tty1] enabled
[    0.000790] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[    0.000834] pid_max: default: 32768 minimum: 301
[    0.001106] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001138] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001894] CPU: Testing write buffer coherency: ok
[    0.002313] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.002955] Setting up static identity map for 0x200000 - 0x20003c
[    0.003126] rcu: Hierarchical SRCU implementation.
[    0.003998] smp: Bringing up secondary CPUs ...
[    0.004908] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.005921] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.006897] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007029] smp: Brought up 1 node, 4 CPUs
[    0.007095] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[    0.007118] CPU: All CPU(s) started in HYP mode.
[    0.007138] CPU: Virtualization extensions available.
[    0.007915] devtmpfs: initialized
[    0.018181] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[    0.018429] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.018471] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.025768] pinctrl core: initialized pinctrl subsystem
[    0.026624] NET: Registered protocol family 16
[    0.029480] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.030885] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.030916] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.031124] Serial: AMBA PL011 UART driver
[    0.034183] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.070433] bcm2835-dma fe007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.072768] vgaarb: loaded
[    0.073151] SCSI subsystem initialized
[    0.073353] usbcore: registered new interface driver usbfs
[    0.073425] usbcore: registered new interface driver hub
[    0.073535] usbcore: registered new device driver usb
[    0.090395] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-07-09 14:40, variant start_x
[    0.100102] raspberrypi-firmware soc:firmware: Firmware hash is d2b1b7fb01475cb3914b2086299e32d724e832f1
[    0.111552] clocksource: Switched to clocksource arch_sys_counter
[    0.188804] VFS: Disk quotas dquot_6.6.0
[    0.188896] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.189060] FS-Cache: Loaded
[    0.189245] CacheFiles: Loaded
[    0.189790] simple-framebuffer 3eb64000.framebuffer: framebuffer at 0x3eb64000, 0x96000 bytes, mapped to 0x(ptrval)
[    0.189828] simple-framebuffer 3eb64000.framebuffer: format=r5g6b5, mode=640x480x16, linelength=1280
[    0.191274] Console: switching to colour frame buffer device 80x30
[    0.193286] simple-framebuffer 3eb64000.framebuffer: fb0: simplefb registered!
[    0.203655] NET: Registered protocol family 2
[    0.205037] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[    0.206521] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.207358] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.208208] TCP: Hash tables configured (established 8192 bind 8192)
[    0.209108] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.209940] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.211052] NET: Registered protocol family 1
[    0.212454] RPC: Registered named UNIX socket transport module.
[    0.213269] RPC: Registered udp transport module.
[    0.214050] RPC: Registered tcp transport module.
[    0.214799] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.215555] PCI: CLS 0 bytes, default 64
[    0.218514] Initialise system trusted keyrings
[    0.219433] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[    0.228825] FS-Cache: Netfs 'nfs' registered for caching
[    0.230066] NFS: Registering the id_resolver key type
[    0.230845] Key type id_resolver registered
[    0.231643] Key type id_legacy registered
[    0.232371] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.235294] Key type asymmetric registered
[    0.236009] Asymmetric key parser 'x509' registered
[    0.236803] bounce: pool size: 64 pages
[    0.237513] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.239019] io scheduler noop registered
[    0.239706] io scheduler deadline registered (default)
[    0.240515] io scheduler cfq registered
[    0.241160] io scheduler mq-deadline registered (default)
[    0.241838] io scheduler kyber registered
[    0.271074] brcm-pcie fd500000.pcie: dmabounce: initialised - 32768 kB, threshold 0x00000000c0000000
[    0.272390] brcm-pcie fd500000.pcie: could not get clock
[    0.273112] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    0.273797] brcm-pcie fd500000.pcie:   MEM 0x600000000..0x603ffffff -> 0xf8000000
[    0.331578] brcm-pcie fd500000.pcie: link up, 5.0 Gbps x1 (!SSC)
[    0.332519] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    0.333211] pci_bus 0000:00: root bus resource [bus 00-01]
[    0.333896] pci_bus 0000:00: root bus resource [mem 0x600000000-0x603ffffff] (bus address [0xf8000000-0xfbffffff])
[    0.335248] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    0.335384] pci 0000:00:00.0: PME# supported from D0 D3hot
[    0.338187] PCI: bus0: Fast back to back transfers disabled
[    0.338883] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    0.340411] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    0.340471] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    0.340639] pci 0000:01:00.0: PME# supported from D0 D3cold
[    0.343387] PCI: bus1: Fast back to back transfers disabled
[    0.344105] pci_bus 0000:01: busn_res: [bus 01] end is updated to 01
[    0.344152] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    0.344887] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    0.346285] pci 0000:00:00.0: PCI bridge to [bus 01]
[    0.346988] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    0.347748] pci 0000:00:00.0: enabling device (0140 -> 0142)
[    0.348470] pci 0000:01:00.0: enabling device (0140 -> 0142)
[    0.352397] iproc-rng200 fe104000.rng: hwrng registered
[    0.353321] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.355220] vc-sm: Videocore shared memory driver
[    0.356317] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    0.367607] brd: module loaded
[    0.377775] loop: module loaded
[    0.379217] Loading iSCSI transport class v2.0-870.
[    0.381591] libphy: Fixed MDIO Bus: probed
[    0.382705] bcmgenet fd580000.genet: failed to get enet clock
[    0.383411] bcmgenet fd580000.genet: GENET 5.0 EPHY: 0x0000
[    0.384111] bcmgenet fd580000.genet: failed to get enet-wol clock
[    0.384791] bcmgenet fd580000.genet: failed to get enet-eee clock
[    0.385681] unimac-mdio unimac-mdio.-19: DMA mask not set
[    0.401580] libphy: bcmgenet MII bus: probed
[    0.442072] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus at 0x(ptrval)
[    0.444170] usbcore: registered new interface driver r8152
[    0.444890] usbcore: registered new interface driver lan78xx
[    0.445566] usbcore: registered new interface driver smsc95xx
[    0.446427] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    0.447064] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    0.450011] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000001000000890
[    0.451444] genirq: irq_chip Brcm_MSI did not update eff. affinity mask of irq 56
[    0.453379] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.454720] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.456112] usb usb1: Product: xHCI Host Controller
[    0.456840] usb usb1: Manufacturer: Linux 4.19.58-v7l+ xhci-hcd
[    0.457573] usb usb1: SerialNumber: 0000:01:00.0
[    0.458796] hub 1-0:1.0: USB hub found
[    0.459565] hub 1-0:1.0: 1 port detected
[    0.460682] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    0.461441] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    0.462954] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    0.464037] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19
[    0.465510] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.467069] usb usb2: Product: xHCI Host Controller
[    0.467878] usb usb2: Manufacturer: Linux 4.19.58-v7l+ xhci-hcd
[    0.468693] usb usb2: SerialNumber: 0000:01:00.0
[    0.469972] hub 2-0:1.0: USB hub found
[    0.470793] hub 2-0:1.0: 4 ports detected
[    0.472644] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.498953] dwc_otg fe980000.usb: base=(ptrval)
[    0.699999] Core Release: 2.80a
[    0.700713] Setting default values for core params
[    0.701423] Finished setting default values for core params
[    0.902443] Using Buffer DMA mode
[    0.903109] Periodic Transfer Interrupt Enhancement - disabled
[    0.903781] Multiprocessor Interrupt Enhancement - disabled
[    0.904455] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.905168] Dedicated Tx FIFOs mode
[    0.906211] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = ded30000 dma = 0x00000000ded30000 len=9024
[    0.907621] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.910910] dwc_otg: Microframe scheduler enabled
[    0.910975] WARN::hcd_init_fiq:457: FIQ on core 1
[    0.911624] WARN::hcd_init_fiq:458: FIQ ASM at c07ae224 length 36
[    0.912249] WARN::hcd_init_fiq:497: MPHI regs_base at f0810200
[    0.912884] dwc_otg fe980000.usb: DWC OTG Controller
[    0.913517] dwc_otg fe980000.usb: new USB bus registered, assigned bus number 3
[    0.914744] dwc_otg fe980000.usb: irq 37, io mem 0x00000000
[    0.915433] Init: Port Power? op_state=1
[    0.916069] Init: Power Port (0)
[    0.916945] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.918229] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.919552] usb usb3: Product: DWC OTG Controller
[    0.920233] usb usb3: Manufacturer: Linux 4.19.58-v7l+ dwc_otg_hcd
[    0.920919] usb usb3: SerialNumber: fe980000.usb
[    0.922145] hub 3-0:1.0: USB hub found
[    0.922863] hub 3-0:1.0: 1 port detected
[    0.924095] dwc_otg: FIQ enabled
[    0.924104] dwc_otg: NAK holdoff enabled
[    0.924113] dwc_otg: FIQ split-transaction FSM enabled
[    0.924127] Module dwc_common_port init
[    0.924343] usbcore: registered new interface driver uas
[    0.925095] usbcore: registered new interface driver usb-storage
[    0.925893] mousedev: PS/2 mouse device common for all mice
[    0.927706] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    0.928562] bcm2835-cpufreq: min=600000 max=1500000
[    0.929820] sdhci: Secure Digital Host Controller Interface driver
[    0.930495] sdhci: Copyright(c) Pierre Ossman
[    0.931525] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
[    0.932617] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.936267] ledtrig-cpu: registered to indicate activity on CPUs
[    0.937113] hidraw: raw HID events driver (C) Jiri Kosina
[    0.937973] usbcore: registered new interface driver usbhid
[    0.938659] usbhid: USB HID core driver
[    0.940040] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    0.942316] [vc_sm_connected_init]: start
[    0.950665] [vc_sm_connected_init]: end - returning 0
[    0.952473] Initializing XFRM netlink socket
[    0.953159] NET: Registered protocol family 17
[    0.953876] Key type dns_resolver registered
[    0.954813] Registering SWP/SWPB emulation handler
[    0.956004] registered taskstats version 1
[    0.956627] Loading compiled-in X.509 certificates
[    0.965051] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    0.965759] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 33, base_baud = 0) is a PL011 rev2
[    0.970023] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    0.971920] brcmstb_thermal fd5d2200.thermal: registered AVS TMON of-sensor driver
[    0.973913] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    0.974646] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[    1.001352] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.1
[    1.020050] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.022371] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.024660] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.028194] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.030436] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.034123] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
[    1.038089] of_cfs_init
[    1.038830] of_cfs_init: OK
[    1.040163] Waiting for root device /dev/mmcblk0p2...
[    1.051594] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.084936] random: fast init done
[    1.137798] mmc0: new ultra high speed DDR50 SDXC card at address e624
[    1.141120] mmcblk0: mmc0:e624 SN64G 59.5 GiB
[    1.142468] mmc1: new high speed SDIO card at address 0001
[    1.144851]  mmcblk0: p1 p2 p3 p4
[    1.161629] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.162962] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.168894] devtmpfs: mounted
[    1.176019] Freeing unused kernel memory: 2048K
[    1.201890] Run /sbin/init as init process
[    1.232795] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.20
[    1.234114] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.234785] usb 1-1: Product: USB2.0 Hub
[    1.237151] hub 1-1:1.0: USB hub found
[    1.238022] hub 1-1:1.0: 4 ports detected
[    1.576565] systemd[1]: System time before build time, advancing clock.
[    1.666164] NET: Registered protocol family 10
[    1.668095] Segment Routing with IPv6
[    1.700780] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    1.704509] systemd[1]: Detected architecture arm.
[    1.717895] systemd[1]: Set hostname to <ROBOT>.
[    1.725971] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument
[    1.995329] systemd[1]: File /lib/systemd/system/systemd-journald.service:12 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
[    1.997587] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.)
[    2.172352] systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.
[    2.339001] random: systemd: uninitialized urandom read (16 bytes read)
[    2.352290] random: systemd: uninitialized urandom read (16 bytes read)
[    2.353714] systemd[1]: Listening on udev Control Socket.
[    2.375787] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[    2.377497] random: systemd: uninitialized urandom read (16 bytes read)
[    2.378884] systemd[1]: Listening on Syslog Socket.
[    2.507747] i2c /dev entries driver
[    2.862168] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    2.972789] systemd-journald[106]: Received request to flush runtime journal from PID 1
[    3.482575] argon-mem feb00000.hevc-decoder: argon-hevcmem initialised: Registers at 0xfeb00000 length 0x0000ffff
[    3.482896] argon-mem feb10000.argon-local-intc: argon-intcmem initialised: Registers at 0xfeb10000 length 0x00000fff
[    3.483192] argon-mem feb20000.h264-decoder: argon-h264mem initialised: Registers at 0xfeb20000 length 0x0000ffff
[    3.483502] argon-mem feb30000.vp9-decoder: argon-vp9mem initialised: Registers at 0xfeb30000 length 0x0000ffff
[    3.513035] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    3.515041] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    3.515058] [vc_sm_connected_init]: start
[    3.527327] [vc_sm_connected_init]: installed successfully
[    3.580607] media: Linux media interface: v0.10
[    3.600530] videodev: Linux video capture interface: v2.00
[    3.656344] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    3.656349] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    3.665169] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    3.674564] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    3.674577] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    3.681920] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    3.681933] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    3.687017] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    3.691907] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    3.691921] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    3.746374] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    3.802634] bcm2835_audio soc:audio: card created with 8 channels
[    3.985962] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    4.058998] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0
[    4.079431] vc4-drm soc:gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4])
[    4.079450] checking generic (3eb64000 96000) vs hw (0 ffffffffffffffff)
[    4.079460] fb: switching to vc4drmfb from simple
[    4.079582] Console: switching to colour dummy device 80x30
[    4.091342] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 1
[    4.091357] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    4.091366] [drm] No driver support for vblank timestamp query.
[    4.091375] [drm] Setting vblank_disable_immediate to false because get_vblank_timestamp == NULL
[    4.093528] vc4-drm soc:gpu: HDMI-A-1: EDID is invalid:
[    4.093548]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093563]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093576]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093587]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093600]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093613]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093626]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.093635]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.101854] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    4.196513] brcmfmac: F1 signature read @0x18000000=0x15264345
[    4.206280] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    4.207071] usbcore: registered new interface driver brcmfmac
[    4.251657] Console: switching to colour frame buffer device 80x30
[    4.272038] vc4-drm soc:gpu: fb0: DRM emulated frame buffer device
[    4.398745] rpi-sense 1-0046: Raspberry Pi Sense HAT firmware version 0
[    4.427392] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    4.441188] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
[    4.503500] input: Raspberry Pi Sense HAT Joystick as /devices/virtual/input/input0
[    4.509082] fb1: RPi-Sense FB frame buffer device
[    4.796673] Adding 2107388k swap on /dev/mmcblk0p4.  Priority:-2 extents:1 across:2107388k SSFS
[    5.024766] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
[    5.849486] random: crng init done
[    5.849499] random: 7 urandom warning(s) missed due to ratelimiting
[    6.000693] 8021q: 802.1Q VLAN Support v1.8
[    6.007949] uart-pl011 fe201000.serial: no DMA platform data
[    6.337318] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    6.337334] brcmfmac: power management disabled
[    6.579346] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    6.802074] bcmgenet fd580000.genet: configuring instance for external RGMII (no delay)
[    6.802341] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    7.831643] bcmgenet fd580000.genet eth0: Link is Down
[   12.041643] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   12.612553] Bluetooth: Core ver 2.22
[   12.612635] NET: Registered protocol family 31
[   12.612645] Bluetooth: HCI device and connection manager initialized
[   12.614496] Bluetooth: HCI socket layer initialized
[   12.614519] Bluetooth: L2CAP socket layer initialized
[   12.614583] Bluetooth: SCO socket layer initialized
[   12.628833] Bluetooth: HCI UART driver ver 2.3
[   12.628847] Bluetooth: HCI UART protocol H4 registered
[   12.628928] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   12.629166] Bluetooth: HCI UART protocol Broadcom registered
[   12.877016] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.877022] Bluetooth: BNEP filters: protocol multicast
[   12.877034] Bluetooth: BNEP socket layer initialized

Output from "dmesg" in case the USB Ethernet devices are recognized and pinging the second one fails:

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.58-v7l+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1245 SMP Fri Jul 12 17:31:45 BST 2019
[    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.1
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 256 MiB at 0x000000001ec00000
[    0.000000] On node 0 totalpages: 999424
[    0.000000]   DMA zone: 1728 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 196608 pages, LIFO batch:63
[    0.000000]   HighMem zone: 802816 pages, LIFO batch:63
[    0.000000] random: get_random_bytes called from start_kernel+0xc0/0x4e8 with crng_init=0
[    0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632
[    0.000000] pcpu-alloc: s39488 r8192 d21952 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: 997696
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M cma=256M video=HDMI-A-1:640x480@60 smsc95xx.macaddr=DC:A6:32:0D:A3:94 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    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: 3682812K/3997696K available (8192K kernel code, 658K rwdata, 2340K rodata, 2048K init, 850K bss, 52740K reserved, 262144K cma-reserved, 3211264K highmem)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xf0800000 - 0xff800000   ( 240 MB)
                   lowmem  : 0xc0000000 - 0xf0000000   ( 768 MB)
                   pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                   modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                     .text : 0x(ptrval) - 0x(ptrval)   (10208 kB)
                     .init : 0x(ptrval) - 0x(ptrval)   (2048 kB)
                     .data : 0x(ptrval) - 0x(ptrval)   ( 659 kB)
                      .bss : 0x(ptrval) - 0x(ptrval)   ( 851 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 27981 entries in 83 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000006] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000022] Switching to timer-based delay loop, resolution 18ns
[    0.000248] Console: colour dummy device 80x30
[    0.000717] console [tty1] enabled
[    0.000769] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[    0.000812] pid_max: default: 32768 minimum: 301
[    0.001087] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001120] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001876] CPU: Testing write buffer coherency: ok
[    0.002300] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.002941] Setting up static identity map for 0x200000 - 0x20003c
[    0.003114] rcu: Hierarchical SRCU implementation.
[    0.003985] smp: Bringing up secondary CPUs ...
[    0.004889] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.005900] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.006876] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007008] smp: Brought up 1 node, 4 CPUs
[    0.007076] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[    0.007100] CPU: All CPU(s) started in HYP mode.
[    0.007120] CPU: Virtualization extensions available.
[    0.007900] devtmpfs: initialized
[    0.018138] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[    0.018384] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.018426] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.025727] pinctrl core: initialized pinctrl subsystem
[    0.026581] NET: Registered protocol family 16
[    0.029441] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.030850] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.030882] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.031085] Serial: AMBA PL011 UART driver
[    0.034142] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.070449] bcm2835-dma fe007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.072788] vgaarb: loaded
[    0.073174] SCSI subsystem initialized
[    0.073377] usbcore: registered new interface driver usbfs
[    0.073449] usbcore: registered new interface driver hub
[    0.073559] usbcore: registered new device driver usb
[    0.090397] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-07-09 14:40, variant start_x
[    0.100106] raspberrypi-firmware soc:firmware: Firmware hash is d2b1b7fb01475cb3914b2086299e32d724e832f1
[    0.111556] clocksource: Switched to clocksource arch_sys_counter
[    0.188867] VFS: Disk quotas dquot_6.6.0
[    0.188962] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.189126] FS-Cache: Loaded
[    0.189314] CacheFiles: Loaded
[    0.189860] simple-framebuffer 3eb64000.framebuffer: framebuffer at 0x3eb64000, 0x96000 bytes, mapped to 0x(ptrval)
[    0.189897] simple-framebuffer 3eb64000.framebuffer: format=r5g6b5, mode=640x480x16, linelength=1280
[    0.191347] Console: switching to colour frame buffer device 80x30
[    0.193360] simple-framebuffer 3eb64000.framebuffer: fb0: simplefb registered!
[    0.203731] NET: Registered protocol family 2
[    0.205120] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[    0.206609] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.207447] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.208299] TCP: Hash tables configured (established 8192 bind 8192)
[    0.209198] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.210034] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.211150] NET: Registered protocol family 1
[    0.212557] RPC: Registered named UNIX socket transport module.
[    0.213376] RPC: Registered udp transport module.
[    0.214159] RPC: Registered tcp transport module.
[    0.214913] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.215670] PCI: CLS 0 bytes, default 64
[    0.218610] Initialise system trusted keyrings
[    0.219527] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[    0.228932] FS-Cache: Netfs 'nfs' registered for caching
[    0.230173] NFS: Registering the id_resolver key type
[    0.230957] Key type id_resolver registered
[    0.231757] Key type id_legacy registered
[    0.232488] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.235414] Key type asymmetric registered
[    0.236130] Asymmetric key parser 'x509' registered
[    0.236925] bounce: pool size: 64 pages
[    0.237636] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.239142] io scheduler noop registered
[    0.239831] io scheduler deadline registered (default)
[    0.240640] io scheduler cfq registered
[    0.241287] io scheduler mq-deadline registered (default)
[    0.241967] io scheduler kyber registered
[    0.271218] brcm-pcie fd500000.pcie: dmabounce: initialised - 32768 kB, threshold 0x00000000c0000000
[    0.272534] brcm-pcie fd500000.pcie: could not get clock
[    0.273254] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    0.273936] brcm-pcie fd500000.pcie:   MEM 0x600000000..0x603ffffff -> 0xf8000000
[    0.331585] brcm-pcie fd500000.pcie: link up, 5.0 Gbps x1 (!SSC)
[    0.332525] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    0.333214] pci_bus 0000:00: root bus resource [bus 00-01]
[    0.333895] pci_bus 0000:00: root bus resource [mem 0x600000000-0x603ffffff] (bus address [0xf8000000-0xfbffffff])
[    0.335240] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    0.335375] pci 0000:00:00.0: PME# supported from D0 D3hot
[    0.338194] PCI: bus0: Fast back to back transfers disabled
[    0.338886] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    0.340409] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    0.340469] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    0.340637] pci 0000:01:00.0: PME# supported from D0 D3cold
[    0.343394] PCI: bus1: Fast back to back transfers disabled
[    0.344112] pci_bus 0000:01: busn_res: [bus 01] end is updated to 01
[    0.344158] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    0.344891] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    0.346283] pci 0000:00:00.0: PCI bridge to [bus 01]
[    0.346982] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    0.347741] pci 0000:00:00.0: enabling device (0140 -> 0142)
[    0.348461] pci 0000:01:00.0: enabling device (0140 -> 0142)
[    0.352387] iproc-rng200 fe104000.rng: hwrng registered
[    0.353312] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.355200] vc-sm: Videocore shared memory driver
[    0.356290] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    0.367585] brd: module loaded
[    0.377736] loop: module loaded
[    0.379170] Loading iSCSI transport class v2.0-870.
[    0.381494] libphy: Fixed MDIO Bus: probed
[    0.382654] bcmgenet fd580000.genet: failed to get enet clock
[    0.383359] bcmgenet fd580000.genet: GENET 5.0 EPHY: 0x0000
[    0.384059] bcmgenet fd580000.genet: failed to get enet-wol clock
[    0.384742] bcmgenet fd580000.genet: failed to get enet-eee clock
[    0.385630] unimac-mdio unimac-mdio.-19: DMA mask not set
[    0.401595] libphy: bcmgenet MII bus: probed
[    0.442077] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus at 0x(ptrval)
[    0.444174] usbcore: registered new interface driver r8152
[    0.444894] usbcore: registered new interface driver lan78xx
[    0.445568] usbcore: registered new interface driver smsc95xx
[    0.446428] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    0.447062] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    0.450002] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000001000000890
[    0.451435] genirq: irq_chip Brcm_MSI did not update eff. affinity mask of irq 56
[    0.453367] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.454705] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.456096] usb usb1: Product: xHCI Host Controller
[    0.456823] usb usb1: Manufacturer: Linux 4.19.58-v7l+ xhci-hcd
[    0.457554] usb usb1: SerialNumber: 0000:01:00.0
[    0.458780] hub 1-0:1.0: USB hub found
[    0.459547] hub 1-0:1.0: 1 port detected
[    0.460664] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    0.461421] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    0.462933] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    0.464012] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19
[    0.465483] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.467039] usb usb2: Product: xHCI Host Controller
[    0.467847] usb usb2: Manufacturer: Linux 4.19.58-v7l+ xhci-hcd
[    0.468659] usb usb2: SerialNumber: 0000:01:00.0
[    0.469935] hub 2-0:1.0: USB hub found
[    0.470754] hub 2-0:1.0: 4 ports detected
[    0.472610] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.498921] dwc_otg fe980000.usb: base=(ptrval)
[    0.699968] Core Release: 2.80a
[    0.700681] Setting default values for core params
[    0.701390] Finished setting default values for core params
[    0.902410] Using Buffer DMA mode
[    0.903074] Periodic Transfer Interrupt Enhancement - disabled
[    0.903745] Multiprocessor Interrupt Enhancement - disabled
[    0.904421] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.905133] Dedicated Tx FIFOs mode
[    0.906176] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = ded30000 dma = 0x00000000ded30000 len=9024
[    0.907586] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.910870] dwc_otg: Microframe scheduler enabled
[    0.910935] WARN::hcd_init_fiq:457: FIQ on core 1
[    0.911583] WARN::hcd_init_fiq:458: FIQ ASM at c07ae224 length 36
[    0.912208] WARN::hcd_init_fiq:497: MPHI regs_base at f0810200
[    0.912844] dwc_otg fe980000.usb: DWC OTG Controller
[    0.913477] dwc_otg fe980000.usb: new USB bus registered, assigned bus number 3
[    0.914703] dwc_otg fe980000.usb: irq 37, io mem 0x00000000
[    0.915392] Init: Port Power? op_state=1
[    0.916027] Init: Power Port (0)
[    0.916905] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.918189] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.919512] usb usb3: Product: DWC OTG Controller
[    0.920191] usb usb3: Manufacturer: Linux 4.19.58-v7l+ dwc_otg_hcd
[    0.920878] usb usb3: SerialNumber: fe980000.usb
[    0.922101] hub 3-0:1.0: USB hub found
[    0.922820] hub 3-0:1.0: 1 port detected
[    0.924052] dwc_otg: FIQ enabled
[    0.924062] dwc_otg: NAK holdoff enabled
[    0.924071] dwc_otg: FIQ split-transaction FSM enabled
[    0.924084] Module dwc_common_port init
[    0.924302] usbcore: registered new interface driver uas
[    0.925056] usbcore: registered new interface driver usb-storage
[    0.925854] mousedev: PS/2 mouse device common for all mice
[    0.927665] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    0.928549] bcm2835-cpufreq: min=600000 max=1500000
[    0.929805] sdhci: Secure Digital Host Controller Interface driver
[    0.930481] sdhci: Copyright(c) Pierre Ossman
[    0.931509] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
[    0.932599] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.936235] ledtrig-cpu: registered to indicate activity on CPUs
[    0.937081] hidraw: raw HID events driver (C) Jiri Kosina
[    0.937944] usbcore: registered new interface driver usbhid
[    0.938630] usbhid: USB HID core driver
[    0.940013] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    0.942282] [vc_sm_connected_init]: start
[    0.950630] [vc_sm_connected_init]: end - returning 0
[    0.952428] Initializing XFRM netlink socket
[    0.953115] NET: Registered protocol family 17
[    0.953836] Key type dns_resolver registered
[    0.954772] Registering SWP/SWPB emulation handler
[    0.955956] registered taskstats version 1
[    0.956580] Loading compiled-in X.509 certificates
[    0.964987] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    0.965695] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 33, base_baud = 0) is a PL011 rev2
[    0.969965] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    0.971860] brcmstb_thermal fd5d2200.thermal: registered AVS TMON of-sensor driver
[    0.973852] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    0.974586] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[    1.001291] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.1
[    1.019999] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.022461] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.024750] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.028282] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.030524] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.031584] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
[    1.035545] of_cfs_init
[    1.036287] of_cfs_init: OK
[    1.037617] Waiting for root device /dev/mmcblk0p2...
[    1.061607] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.083709] random: fast init done
[    1.136082] mmc0: new ultra high speed DDR50 SDXC card at address e624
[    1.138806] mmcblk0: mmc0:e624 SN64G 59.5 GiB
[    1.141298]  mmcblk0: p1 p2 p3 p4
[    1.142935] mmc1: new high speed SDIO card at address 0001
[    1.160664] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.162032] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.167749] devtmpfs: mounted
[    1.174861] Freeing unused kernel memory: 2048K
[    1.201817] Run /sbin/init as init process
[    1.242978] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.20
[    1.244293] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.244962] usb 1-1: Product: USB2.0 Hub
[    1.247466] hub 1-1:1.0: USB hub found
[    1.248328] hub 1-1:1.0: 4 ports detected
[    1.569383] systemd[1]: System time before build time, advancing clock.
[    1.658038] NET: Registered protocol family 10
[    1.659964] Segment Routing with IPv6
[    1.692537] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    1.696163] systemd[1]: Detected architecture arm.
[    1.709300] systemd[1]: Set hostname to <ROBOT>.
[    1.717522] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument
[    2.001425] systemd[1]: File /lib/systemd/system/systemd-journald.service:12 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
[    2.003857] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.)
[    2.178644] systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.
[    2.345676] random: systemd: uninitialized urandom read (16 bytes read)
[    2.358599] random: systemd: uninitialized urandom read (16 bytes read)
[    2.359995] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    2.363550] random: systemd: uninitialized urandom read (16 bytes read)
[    2.364899] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    2.368130] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    2.551786] i2c /dev entries driver
[    2.886096] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    3.015429] systemd-journald[108]: Received request to flush runtime journal from PID 1
[    3.473992] argon-mem feb00000.hevc-decoder: argon-hevcmem initialised: Registers at 0xfeb00000 length 0x0000ffff
[    3.474444] argon-mem feb10000.argon-local-intc: argon-intcmem initialised: Registers at 0xfeb10000 length 0x00000fff
[    3.477012] argon-mem feb20000.h264-decoder: argon-h264mem initialised: Registers at 0xfeb20000 length 0x0000ffff
[    3.479056] argon-mem feb30000.vp9-decoder: argon-vp9mem initialised: Registers at 0xfeb30000 length 0x0000ffff
[    3.585465] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    3.592690] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    3.592716] [vc_sm_connected_init]: start
[    3.596331] media: Linux media interface: v0.10
[    3.604460] [vc_sm_connected_init]: installed successfully
[    3.641169] videodev: Linux video capture interface: v2.00
[    3.651134] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    3.679654] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    3.681788] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    3.688050] bcm2835_audio soc:audio: card created with 8 channels
[    3.688955] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    3.691640] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    3.993104] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    4.036401] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0
[    4.105981] vc4-drm soc:gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4])
[    4.106006] checking generic (3eb64000 96000) vs hw (0 ffffffffffffffff)
[    4.106017] fb: switching to vc4drmfb from simple
[    4.106147] Console: switching to colour dummy device 80x30
[    4.111524] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 1
[    4.111539] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    4.111602] [drm] No driver support for vblank timestamp query.
[    4.111612] [drm] Setting vblank_disable_immediate to false because get_vblank_timestamp == NULL
[    4.113541] vc4-drm soc:gpu: HDMI-A-1: EDID is invalid:
[    4.113558]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113568]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113577]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113587]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113596]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113605]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113614]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.113623]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.115899] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    4.165842] brcmfmac: F1 signature read @0x18000000=0x15264345
[    4.177936] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    4.178734] usbcore: registered new interface driver brcmfmac
[    4.284506] Console: switching to colour frame buffer device 80x30
[    4.304333] vc4-drm soc:gpu: fb0: DRM emulated frame buffer device
[    4.321695] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    4.321708] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    4.330292] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    4.330306] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    4.338502] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    4.338521] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    4.407722] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    4.421270] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
[    4.490241] rpi-sense 1-0046: Raspberry Pi Sense HAT firmware version 0
[    4.513947] fb1: RPi-Sense FB frame buffer device
[    4.517177] input: Raspberry Pi Sense HAT Joystick as /devices/virtual/input/input0
[    4.882964] Adding 2107388k swap on /dev/mmcblk0p4.  Priority:-2 extents:1 across:2107388k SSFS
[    5.108825] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
[    5.938359] uart-pl011 fe201000.serial: no DMA platform data
[    5.945720] random: crng init done
[    5.945734] random: 7 urandom warning(s) missed due to ratelimiting
[    5.994375] 8021q: 802.1Q VLAN Support v1.8
[    6.347294] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    6.347309] brcmfmac: power management disabled
[    6.593100] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    6.862206] bcmgenet fd580000.genet: configuring instance for external RGMII (no delay)
[    6.862682] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    7.911663] bcmgenet fd580000.genet eth0: Link is Down
[    9.991604] usb 1-1.1: new high-speed USB device number 3 using xhci_hcd
[   10.371862] usb 1-1.1: device descriptor read/64, error -71
[   11.391858] usb 1-1.1: device descriptor read/64, error -71
[   11.611600] usb 1-1.1: new high-speed USB device number 4 using xhci_hcd
[   11.742577] usb 1-1.1: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[   11.742592] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   11.742605] usb 1-1.1: Product: RNDIS/Ethernet Gadget
[   11.742616] usb 1-1.1: Manufacturer: Linux 4.19.37+ with 20980000.usb
[   11.816649] cdc_subset: probe of 1-1.1:1.0 failed with error -22
[   11.819858] cdc_subset 1-1.1:1.1 usb0: register 'cdc_subset' at usb-0000:01:00.0-1.1, Linux Device, 92:a7:3c:c9:85:ec
[   11.820034] usbcore: registered new interface driver cdc_subset
[   11.820139] cdc_ether: probe of 1-1.1:1.0 failed with error -16
[   11.820237] usbcore: registered new interface driver cdc_ether
[   11.979264] br0: port 1(usb0) entered blocking state
[   11.979270] br0: port 1(usb0) entered disabled state
[   11.979443] device usb0 entered promiscuous mode
[   11.979523] br0: port 1(usb0) entered blocking state
[   11.979528] br0: port 1(usb0) entered forwarding state
[   12.041610] usb 1-1.2: new high-speed USB device number 5 using xhci_hcd
[   12.056688] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   12.182705] usb 1-1.2: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[   12.182712] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[   12.182717] usb 1-1.2: Product: RNDIS/Ethernet Gadget
[   12.182722] usb 1-1.2: Manufacturer: Linux 4.19.37+ with 20980000.usb
[   12.185403] cdc_subset: probe of 1-1.2:1.0 failed with error -22
[   12.187311] cdc_ether 1-1.2:1.0 usb1: register 'cdc_ether' at usb-0000:01:00.0-1.2, CDC Ethernet Device, 62:35:4c:93:cb:9b
[   12.321827] br0: port 2(usb1) entered blocking state
[   12.321833] br0: port 2(usb1) entered disabled state
[   12.322079] device usb1 entered promiscuous mode
[   12.322128] br0: port 2(usb1) entered blocking state
[   12.322133] br0: port 2(usb1) entered forwarding state
[   12.538799] Bluetooth: Core ver 2.22
[   12.538837] NET: Registered protocol family 31
[   12.538842] Bluetooth: HCI device and connection manager initialized
[   12.538852] Bluetooth: HCI socket layer initialized
[   12.538859] Bluetooth: L2CAP socket layer initialized
[   12.538879] Bluetooth: SCO socket layer initialized
[   12.547859] Bluetooth: HCI UART driver ver 2.3
[   12.547865] Bluetooth: HCI UART protocol H4 registered
[   12.547900] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   12.548002] Bluetooth: HCI UART protocol Broadcom registered
[   12.812874] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.812883] Bluetooth: BNEP filters: protocol multicast
[   12.812896] Bluetooth: BNEP socket layer initialized
[   13.031627] br0: port 2(usb1) entered disabled state
[   24.372888] br0: port 2(usb1) entered blocking state
[   24.372902] br0: port 2(usb1) entered forwarding state
[   42.071558] ------------[ cut here ]------------
[   42.071602] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x294/0x298
[   42.071618] NETDEV WATCHDOG: usb1 (cdc_ether): transmit queue 0 timed out
[   42.071639] Modules linked in: bnep hci_uart btbcm serdev bluetooth ecdh_generic cdc_ether cdc_subset bridge nft_chain_nat_ipv6 ip6t_MASQUERADE 8021q garp nf_nat_ipv6 stp llc nft_counter nft_chain_nat_ipv4 ipt_MASQUERADE nf_nat_ipv4 xt_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink evdev rpisense_fb rpisense_js rpisense_core brcmfmac brcmutil vc4 sha256_generic v3d drm_kms_helper gpu_sched cfg80211 rfkill drm raspberrypi_hwmon hwmon drm_panel_orientation_quirks snd_soc_core bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) v4l2_common videobuf2_dma_contig snd_compress videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_pcm_dmaengine snd_bcm2835(C) videobuf2_common snd_pcm snd_timer syscopyarea sysfillrect sysimgblt fb_sys_fops videodev
[   42.072819]  snd media vc_sm_cma(C) i2c_bcm2835 argon_mem uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6
[   42.073040] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G         C        4.19.58-v7l+ #1245
[   42.073050] Hardware name: BCM2835
[   42.073078] [<c0212c8c>] (unwind_backtrace) from [<c020d49c>] (show_stack+0x20/0x24)
[   42.073098] [<c020d49c>] (show_stack) from [<c09763e0>] (dump_stack+0xd4/0x118)
[   42.073123] [<c09763e0>] (dump_stack) from [<c0222270>] (__warn+0x104/0x11c)
[   42.073140] [<c0222270>] (__warn) from [<c02222e0>] (warn_slowpath_fmt+0x58/0x74)
[   42.073160] [<c02222e0>] (warn_slowpath_fmt) from [<c089d280>] (dev_watchdog+0x294/0x298)
[   42.073184] [<c089d280>] (dev_watchdog) from [<c029a4b0>] (call_timer_fn+0x3c/0x198)
[   42.073202] [<c029a4b0>] (call_timer_fn) from [<c029a6f8>] (expire_timers+0xec/0x14c)
[   42.073216] [<c029a6f8>] (expire_timers) from [<c029a810>] (run_timer_softirq+0xb8/0x1ec)
[   42.073234] [<c029a810>] (run_timer_softirq) from [<c0202410>] (__do_softirq+0x190/0x3f0)
[   42.073255] [<c0202410>] (__do_softirq) from [<c0228244>] (irq_exit+0xfc/0x120)
[   42.073276] [<c0228244>] (irq_exit) from [<c0280d58>] (__handle_domain_irq+0x70/0xc4)
[   42.073293] [<c0280d58>] (__handle_domain_irq) from [<c0202244>] (gic_handle_irq+0x4c/0x88)
[   42.073310] [<c0202244>] (gic_handle_irq) from [<c02019bc>] (__irq_svc+0x5c/0x7c)
[   42.073327] Exception stack(0xc1001ed8 to 0xc1001f20)
[   42.073338] 1ec0:                                                       c0209a84 00000000
[   42.073350] 1ee0: 40000093 40000093 c1004dbc c1000000 c1004e04 00000001 c10957ca c10a4a00
[   42.073362] 1f00: c0e67a38 c1001f34 c10051c4 c1001f28 00000000 c0209a88 40000013 ffffffff
[   42.073381] [<c02019bc>] (__irq_svc) from [<c0209a88>] (arch_cpu_idle+0x34/0x4c)
[   42.073404] [<c0209a88>] (arch_cpu_idle) from [<c09935a4>] (default_idle_call+0x34/0x48)
[   42.073426] [<c09935a4>] (default_idle_call) from [<c025423c>] (do_idle+0xec/0x17c)
[   42.073445] [<c025423c>] (do_idle) from [<c025458c>] (cpu_startup_entry+0x28/0x2c)
[   42.073461] [<c025458c>] (cpu_startup_entry) from [<c098cc80>] (rest_init+0xbc/0xc0)
[   42.073477] [<c098cc80>] (rest_init) from [<c0e00fe4>] (start_kernel+0x4b8/0x4e8)
[   42.073493] ---[ end trace 823697e2090bfb7d ]---
JamesH65 commented 4 years ago

This issue will be closed within 30 days unless further interactions are posted. If you wish this issue to remain open, please add a comment. A closed issue may be reopened if requested.

soxrok2212 commented 4 years ago

I'm seeing this issue present itself again as well in kernel 5.4.58. Using an AX88179 and RTL8153. Only see this issue on Pi 3B+, Pi 4 is fine.

[  427.419620] usb 1-1.3: New USB device found, idVendor=0b95, idProduct=1790, bcdDevice= 1.00
[  427.419639] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  427.419654] usb 1-1.3: Product: AX88179
[  427.419670] usb 1-1.3: Manufacturer: ASIX Elec. Corp.
[  427.419683] usb 1-1.3: SerialNumber: 0000249B1492B1
[  427.755446] ax88179_178a 1-1.3:1.0 eth2: register 'ax88179_178a' at usb-3f980000.usb-1.3, ASIX AX88179 USB 3.0 Gigabit Ethernet, 00:24:9b:14:92:b1
[  468.095594] ax88179_178a 1-1.3:1.0 eth2: ax88179 - Link status is: 1
[  468.103957] IPv6: ADDRCONF(NETDEV_CHANGE): eth2: link becomes ready
[  468.106292] ERROR::assign_and_init_hc:1437: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case

I can get a DHCP IP address on one interface (in this case, the RTL8153 device), but the other does not send or receive any packets. Configuring a manual/static address does not work either. Eventually, the Pi will freeze and require a reboot.

pelwell commented 4 years ago

Have you tried with dtoverlay=dwc2 in config.txt? Be aware that a single gigabit Ethernet link can easily saturate the USB bus on Pis before the 4B, so don't expect great performance with two external Ethernet dongles.

soxrok2212 commented 4 years ago

Hi, I managed to get it working by adding coherent_pool=4M to my boot config and it's now able to get a DHCP address and appears to be working.

Also, I am aware that I won't see gigabit speeds... I'll be using significantly less bandwidth ;)