Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
m1027 opened this issue Apr 8, 2019 · 35 comments
Open

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

m1027 opened this issue Apr 8, 2019 · 35 comments
Labels
Close within 30 days Issue will be closed within 30 days unless requested to stay open

Comments

@m1027
Copy link

m1027 commented Apr 8, 2019

No issues with kernel-4.14.98.

Tested setup:

  • kernel-4.19.30 to 4.19.32 and according firmware
  • rpi 3b or 3b+
  • booting from HDD via USB SATA adapter, no sd-card
  • 1x onboard ethernet connected (short cable)
  • 2x USB ethernet via 0b95:772b ASIX Electronics Corp. AX88772B
  • alternatively tested: 2x USB ethernet via 0b95:1790 ASIX Electronics Corp.
    AX88179 Gigabit Ethernet
  • ethernet cables to the 2x USB adapters quite long (approx. 20m each)
  • tested with other/new cables (1 short at usb, 2 long at usb/onboard)
  • 2.5 A current

To trigger the kernel crash:

  • fresh boot with all devices plugged into the rpi but one ethernet cable
    not yet connected to USB adapter
  • then connect ethernet cable to USB adapter: crash soon after adapter is
    broad up

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
Copy link
Contributor

P33M commented Apr 9, 2019

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
Copy link
Author

m1027 commented Apr 14, 2019

Thanks for your reply.

Here the full dmesg. You'll see:

  • fresh boot
  • memory alloc failed
  • then my interactive login, just to be prepared for shutdown later
  • then the kernel crash
  • then I issue: systemctl poweroff
  • powerdown still works if I do not wait for more crashs

[ 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
Copy link

mkosch commented Apr 27, 2019

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

Tested setup:

  • Kernel 4.19.23 and newer
  • Two "slave" Raspberry Pi Zero W (each with camera module) setup as USB Ethernet gadget (g_ether) with USB connection to a "main" Raspberry Pi 3B+
  • All Raspberry Pis boot without GUI using SD card
  • No Ethernet cable connected to main Raspberry Pi, instead using WLAN
  • Radio devices of both slave Raspberry Pis are disabled
  • Main Raspberry Pi powered with Pichler's BEC BOY (UBEC 3A) from Mignon batteries or 6A power adapter
  • Both slave Raspberry Pis powered with USB from main Raspberry Pi
  • SSH connection to main Raspberry Pi

What happens:

  • When only one slave Raspberry Pi is connected to main Raspberry Pi, then the Ethernet connection seems fine and I can ping the slave Raspberry Pi from the main Raspberry Pi
  • When both slave Raspberry Pis are connected to main Raspberry Pi, then no Ethernet connection seems to be possible to at least one of the slave Raspberry Pis. It may be possible to ping the other slave Raspberry Pi, possibly with packet loss. I didn't explore this extensively.
  • No crash occurs.

Test case:

  • I start the main Raspberry Pi without slave Raspberry Pis connected.
  • After connecting the first slave Raspberry Pi I get the following "dmesg" messages:
[  291.844239] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
[  292.224254] usb 1-1.3: device descriptor read/64, error -71
[  292.664253] usb 1-1.3: device descriptor read/64, error -71
[  292.884238] usb 1-1.3: new high-speed USB device number 6 using dwc_otg
[  293.015142] usb 1-1.3: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[  293.015155] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  293.015165] usb 1-1.3: Product: RNDIS/Ethernet Gadget
[  293.015175] usb 1-1.3: Manufacturer: Linux 4.19.27+ with 20980000.usb
[  293.071965] cdc_ether 1-1.3:1.0 usb0: register 'cdc_ether' at usb-3f980000.usb-1.3, CDC Ethernet Device, 76:a0:f6:6a:35:7f
[  293.072195] usbcore: registered new interface driver cdc_ether
[  293.072287] usbcore: registered new interface driver cdc_subset
[  293.149633] br0: port 1(usb0) entered blocking state
[  293.149646] br0: port 1(usb0) entered disabled state
[  293.150034] device usb0 entered promiscuous mode
[  293.158377] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
[  293.158398] br0: port 1(usb0) entered blocking state
[  293.158408] br0: port 1(usb0) entered forwarding state
[  294.154416] br0: port 1(usb0) entered disabled state
[  306.071431] IPv6: ADDRCONF(NETDEV_CHANGE): usb0: link becomes ready
[  306.071577] br0: port 1(usb0) entered blocking state
[  306.071587] br0: port 1(usb0) entered forwarding state
  • After connecting the second slave Raspberry Pi I get the following "dmesg" messages:
[  433.941518] usb 1-1.3: USB disconnect, device number 6
[  433.941760] cdc_ether 1-1.3:1.0 usb0: unregister 'cdc_ether' usb-3f980000.usb-1.3, CDC Ethernet Device
[  433.967139] br0: port 1(usb0) entered disabled state
[  433.980661] device usb0 left promiscuous mode
[  433.980678] br0: port 1(usb0) entered disabled state
[  442.364891] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
[  442.495651] usb 1-1.3: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[  442.495666] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  442.495676] usb 1-1.3: Product: RNDIS/Ethernet Gadget
[  442.495688] usb 1-1.3: Manufacturer: Linux 4.19.27+ with 20980000.usb
[  442.505158] cdc_ether 1-1.3:1.0 usb0: register 'cdc_ether' at usb-3f980000.usb-1.3, CDC Ethernet Device, 76:a0:f6:6a:35:7f
[  442.609940] br0: port 1(usb0) entered blocking state
[  442.609955] br0: port 1(usb0) entered disabled state
[  442.610337] device usb0 entered promiscuous mode
[  442.615784] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
[  442.615804] br0: port 1(usb0) entered blocking state
[  442.615813] br0: port 1(usb0) entered forwarding state
[  442.616160] br0: port 1(usb0) entered disabled state
[  442.814795] usb 1-1.1.2: new high-speed USB device number 8 using dwc_otg
[  442.945540] usb 1-1.1.2: New USB device found, idVendor=0525, idProduct=a4a2, bcdDevice= 4.19
[  442.945551] usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  442.945556] usb 1-1.1.2: Product: RNDIS/Ethernet Gadget
[  442.945563] usb 1-1.1.2: Manufacturer: Linux 4.19.27+ with 20980000.usb
[  442.947450] 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
[  443.015159] br0: port 2(usb1) entered blocking state
[  443.015167] br0: port 2(usb1) entered disabled state
[  443.015389] device usb1 entered promiscuous mode
[  443.018449] IPv6: ADDRCONF(NETDEV_UP): usb1: link is not ready
[  443.018464] br0: port 2(usb1) entered blocking state
[  443.018470] br0: port 2(usb1) entered forwarding state
[  443.624931] br0: port 2(usb1) entered disabled state
[  455.896434] IPv6: ADDRCONF(NETDEV_CHANGE): usb0: link becomes ready
[  455.896635] br0: port 1(usb0) entered blocking state
[  455.896645] br0: port 1(usb0) entered forwarding state
[  456.442427] IPv6: ADDRCONF(NETDEV_CHANGE): usb1: link becomes ready
[  456.442568] br0: port 2(usb1) entered blocking state
[  456.442578] br0: port 2(usb1) entered forwarding state
[  456.494909] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[  474.074909] ------------[ cut here ]------------
[  474.074953] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:461 dev_watchdog+0x294/0x298
[  474.074974] NETDEV WATCHDOG: usb1 (cdc_ether): transmit queue 0 timed out
[  474.074987] Modules linked in: cdc_subset cdc_ether rfcomm bnep hci_uart btbcm serdev bluetooth ecdh_generic 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 sysfillrect rpisense_js sysimgblt fb_sys_fops rpisense_core brcmfmac brcmutil sha256_generic cfg80211 snd_bcm2835(C) snd_pcm rfkill bcm2835_v4l2(C) bcm2835_codec(C) raspberrypi_hwmon snd_timer hwmon v4l2_mem2mem snd bcm2835_mmal_vchiq(C) v4l2_common videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common i2c_bcm2835 videodev media vc_sm_cma(C) fixed uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6
[  474.075780] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G         C        4.19.36-v7+ #1212
[  474.075798] Hardware name: BCM2835
[  474.075836] [<80111e90>] (unwind_backtrace) from [<8010d414>] (show_stack+0x20/0x24)
[  474.075855] [<8010d414>] (show_stack) from [<807edd60>] (dump_stack+0xd4/0x118)
[  474.075873] [<807edd60>] (dump_stack) from [<80120638>] (__warn+0x104/0x11c)
[  474.075897] [<80120638>] (__warn) from [<801206a8>] (warn_slowpath_fmt+0x58/0x74)
[  474.075921] [<801206a8>] (warn_slowpath_fmt) from [<80714f5c>] (dev_watchdog+0x294/0x298)
[  474.075946] [<80714f5c>] (dev_watchdog) from [<80195de4>] (call_timer_fn+0x3c/0x198)
[  474.075966] [<80195de4>] (call_timer_fn) from [<8019602c>] (expire_timers+0xec/0x14c)
[  474.075984] [<8019602c>] (expire_timers) from [<80196144>] (run_timer_softirq+0xb8/0x1ec)
[  474.076009] [<80196144>] (run_timer_softirq) from [<80102388>] (__do_softirq+0x190/0x3f0)
[  474.076032] [<80102388>] (__do_softirq) from [<80126384>] (irq_exit+0xfc/0x120)
[  474.076056] [<80126384>] (irq_exit) from [<8017e7ac>] (__handle_domain_irq+0x70/0xc4)
[  474.076075] [<8017e7ac>] (__handle_domain_irq) from [<801021b4>] (bcm2836_arm_irqchip_handle_irq+0x60/0xa4)
[  474.076090] [<801021b4>] (bcm2836_arm_irqchip_handle_irq) from [<801019bc>] (__irq_svc+0x5c/0x7c)
[  474.076105] Exception stack(0x80d01ee8 to 0x80d01f30)
[  474.076121] 1ee0:                   80109a04 00000000 40000093 40000093 80d04d70 80d00000
[  474.076134] 1f00: 80d04db8 00000001 80d8b83d b77ffa00 80c62a38 80d01f44 80d0517c 80d01f38
[  474.076142] 1f20: 00000000 80109a08 40000013 ffffffff
[  474.076159] [<801019bc>] (__irq_svc) from [<80109a08>] (arch_cpu_idle+0x34/0x4c)
[  474.076176] [<80109a08>] (arch_cpu_idle) from [<8080a93c>] (default_idle_call+0x34/0x48)
[  474.076194] [<8080a93c>] (default_idle_call) from [<80151d4c>] (do_idle+0xec/0x17c)
[  474.076213] [<80151d4c>] (do_idle) from [<8015209c>] (cpu_startup_entry+0x28/0x2c)
[  474.076239] [<8015209c>] (cpu_startup_entry) from [<808044c4>] (rest_init+0xbc/0xc0)
[  474.076264] [<808044c4>] (rest_init) from [<80c00f94>] (start_kernel+0x468/0x498)
[  474.076283] ---[ end trace 942e31fc8eb373d9 ]---
[  474.077115] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[  524.075895] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[  629.036245] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[  729.036718] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[  889.037570] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[  964.406130] ERROR::assign_and_init_hc:1390: assign_and_init_hc: Failed to allocate memory to handle non-dword aligned buffer case
[ 1001.517575] lan78xx 1-1.1.1:1.0 eth0: Failed to read register index 0x00000120. ret = -110

@m1027
Copy link
Author

m1027 commented Apr 29, 2019

Updates:

(1) The issue (summary)

  • Rpi 3 or 3b+
  • 3x ethernet connected (2 additional USB/ethernet adapters)
  • kernel 4.19 crash soon after "ERROR::assign_and_init_hc:1391 ..."
  • No issue with kenel 4.14 or when leaving out one USB connector

(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
Copy link
Contributor

P33M commented Apr 29, 2019

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

@P33M
Copy link
Contributor

P33M commented Apr 29, 2019

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:

  • usbnet has always been allocating misaligned buffers, such that for every network packet received or transmitted there's an additional memcpy to or from dwc_otg's align_buf
  • the maximum number of these sorts of buffers that you can align is severely restricted, probably because we're doing what's essentially dma_alloc_coherent() in an atomic context

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
Copy link
Contributor

P33M commented Apr 29, 2019

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

@6by9
Copy link
Contributor

6by9 commented Apr 29, 2019

4.20 gains 1ee5c23 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
Copy link
Author

m1027 commented Apr 29, 2019

@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
Copy link

mkosch commented Apr 29, 2019

@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
Copy link
Contributor

P33M commented Apr 30, 2019

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
Copy link
Contributor

P33M commented Apr 30, 2019

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
Copy link
Contributor

#2599 Is this related?

@P33M
Copy link
Contributor

P33M commented Apr 30, 2019

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
Copy link
Contributor

P33M commented Apr 30, 2019

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
Copy link
Contributor

P33M commented Apr 30, 2019

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 pushed a commit to P33M/linux that referenced this issue May 1, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: raspberrypi#2924
P33M pushed a commit to P33M/linux that referenced this issue May 1, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: raspberrypi#2924
pelwell pushed a commit that referenced this issue May 1, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
P33M pushed a commit to P33M/linux that referenced this issue May 1, 2019
dwc_otg requires a 32-bit aligned buffer start address, otherwise
expensive bounce buffers are used. The LAN951x hardware can skip up to
3 bytes between the TX header and the start of frame data, which can
be used to force alignment of the URB passed to dwc_otg.

As found in raspberrypi#2924
P33M pushed a commit to P33M/linux that referenced this issue May 1, 2019
dwc_otg requires a 32-bit aligned buffer start address, otherwise
expensive bounce buffers are used. The LAN951x hardware can skip up to
3 bytes between the TX header and the start of frame data, which can
be used to force alignment of the URB passed to dwc_otg.

As found in raspberrypi#2924
pelwell pushed a commit that referenced this issue May 1, 2019
dwc_otg requires a 32-bit aligned buffer start address, otherwise
expensive bounce buffers are used. The LAN951x hardware can skip up to
3 bytes between the TX header and the start of frame data, which can
be used to force alignment of the URB passed to dwc_otg.

As found in #2924
popcornmix added a commit to raspberrypi/firmware that referenced this issue May 2, 2019
popcornmix added a commit to Hexxeh/rpi-firmware that referenced this issue May 2, 2019
@P33M
Copy link
Contributor

P33M commented May 2, 2019

Please retest with latest rpi-update firmware.

@mkosch
Copy link

mkosch commented May 2, 2019

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
Copy link
Contributor

pelwell commented May 2, 2019

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
Copy link
Author

m1027 commented May 2, 2019

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

@mkosch
Copy link

mkosch commented Aug 15, 2019

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 ]---

popcornmix pushed a commit that referenced this issue Aug 28, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
popcornmix pushed a commit that referenced this issue Aug 28, 2019
See: #2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
popcornmix pushed a commit that referenced this issue Aug 30, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
popcornmix pushed a commit that referenced this issue Aug 30, 2019
See: #2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
jason77-wang pushed a commit to jason77-wang/eoan-rpi4 that referenced this issue Sep 1, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: raspberrypi/linux#2924
jason77-wang pushed a commit to jason77-wang/eoan-rpi4 that referenced this issue Sep 1, 2019
See: raspberrypi/linux#2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
popcornmix pushed a commit that referenced this issue Sep 6, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
popcornmix pushed a commit that referenced this issue Sep 6, 2019
See: #2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
popcornmix pushed a commit that referenced this issue Sep 17, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
popcornmix pushed a commit that referenced this issue Sep 17, 2019
See: #2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
mike-scott pushed a commit to mike-scott/linux that referenced this issue Sep 17, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: raspberrypi/linux#2924
Signed-off-by: Michael Scott <mike@foundries.io>
mike-scott pushed a commit to mike-scott/linux that referenced this issue Sep 17, 2019
See: raspberrypi/linux#2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
Signed-off-by: Michael Scott <mike@foundries.io>
anirbanray1981-zz pushed a commit to anirbanray1981-zz/ubuntu-disco that referenced this issue Sep 18, 2019
BugLink: https://bugs.launchpad.net/bugs/1831219

BugLink: https://bugs.launchpad.net/bugs/1825235

dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: raspberrypi/linux#2924
(cherry picked from commit 28ef4e7747ce21fedcb59033dc60d560ee04dbc8
https://github.com/raspberrypi/linux rpi-5.0.y)
Signed-off-by: Paolo Pisati <paolo.pisati@canonical.com>
Acked-by: Stefan Bader <stefan.bader@canonical.com>
Acked-by: Connor Kuehl <connor.kuehl@canonical.com>
Signed-off-by: Kleber Sacilotto de Souza <kleber.souza@canonical.com>
anirbanray1981-zz pushed a commit to anirbanray1981-zz/ubuntu-disco that referenced this issue Sep 18, 2019
BugLink: https://bugs.launchpad.net/bugs/1831219

BugLink: https://bugs.launchpad.net/bugs/1825235

See: raspberrypi/linux#2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
(cherry picked from commit 3dd83758048c9e812452636ca5a8144bcf2c9c7f
https://github.com/raspberrypi/linux rpi-5.0.y)
Signed-off-by: Paolo Pisati <paolo.pisati@canonical.com>
Acked-by: Stefan Bader <stefan.bader@canonical.com>
Acked-by: Connor Kuehl <connor.kuehl@canonical.com>
Signed-off-by: Kleber Sacilotto de Souza <kleber.souza@canonical.com>
shyam334 pushed a commit to shyam334/disco that referenced this issue Oct 1, 2019
BugLink: https://bugs.launchpad.net/bugs/1831219

BugLink: https://bugs.launchpad.net/bugs/1825235

dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: raspberrypi/linux#2924
(cherry picked from commit 28ef4e7747ce21fedcb59033dc60d560ee04dbc8
https://github.com/raspberrypi/linux rpi-5.0.y)
Signed-off-by: Paolo Pisati <paolo.pisati@canonical.com>
Acked-by: Stefan Bader <stefan.bader@canonical.com>
Acked-by: Connor Kuehl <connor.kuehl@canonical.com>
Signed-off-by: Kleber Sacilotto de Souza <kleber.souza@canonical.com>
shyam334 pushed a commit to shyam334/disco that referenced this issue Oct 1, 2019
BugLink: https://bugs.launchpad.net/bugs/1831219

BugLink: https://bugs.launchpad.net/bugs/1825235

See: raspberrypi/linux#2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
(cherry picked from commit 3dd83758048c9e812452636ca5a8144bcf2c9c7f
https://github.com/raspberrypi/linux rpi-5.0.y)
Signed-off-by: Paolo Pisati <paolo.pisati@canonical.com>
Acked-by: Stefan Bader <stefan.bader@canonical.com>
Acked-by: Connor Kuehl <connor.kuehl@canonical.com>
Signed-off-by: Kleber Sacilotto de Souza <kleber.souza@canonical.com>
popcornmix pushed a commit that referenced this issue Oct 4, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
popcornmix pushed a commit that referenced this issue Oct 4, 2019
See: #2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
popcornmix pushed a commit that referenced this issue Oct 11, 2019
dwc_otg allocates DMA-coherent buffers in atomic context for misaligned
transfer buffers. The pool that these allocations come from is set up
at boot-time but can be overridden by a commandline parameter -
increase this for now to prevent failures seen on 4.19 with multiple
USB Ethernet devices.

see: #2924
popcornmix pushed a commit that referenced this issue Oct 11, 2019
See: #2924

Signed-off-by: Phil Elwell <phil@raspberrypi.org>
@JamesH65 JamesH65 added the Close within 30 days Issue will be closed within 30 days unless requested to stay open label Feb 13, 2020
@JamesH65
Copy link
Contributor

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.

ED6E0F17 pushed a commit to ED6E0F17/linux that referenced this issue May 1, 2020
commit 61e713b upstream.

Christof Meerwald <cmeerw@cmeerw.org> writes:
> Hi,
>
> this is probably related to commit
> 7a0cf09 (signal: Correct namespace
> fixups of si_pid and si_uid).
>
> With a 5.6.5 kernel I am seeing SIGCHLD signals that don't include a
> properly set si_pid field - this seems to happen for multi-threaded
> child processes.
>
> A simple test program (based on the sample from the signalfd man page):
>
> #include <sys/signalfd.h>
> #include <signal.h>
> #include <unistd.h>
> #include <spawn.h>
> #include <stdlib.h>
> #include <stdio.h>
>
> #define handle_error(msg) \
>     do { perror(msg); exit(EXIT_FAILURE); } while (0)
>
> int main(int argc, char *argv[])
> {
>   sigset_t mask;
>   int sfd;
>   struct signalfd_siginfo fdsi;
>   ssize_t s;
>
>   sigemptyset(&mask);
>   sigaddset(&mask, SIGCHLD);
>
>   if (sigprocmask(SIG_BLOCK, &mask, NULL) == -1)
>     handle_error("sigprocmask");
>
>   pid_t chldpid;
>   char *chldargv[] = { "./sfdclient", NULL };
>   posix_spawn(&chldpid, "./sfdclient", NULL, NULL, chldargv, NULL);
>
>   sfd = signalfd(-1, &mask, 0);
>   if (sfd == -1)
>     handle_error("signalfd");
>
>   for (;;) {
>     s = read(sfd, &fdsi, sizeof(struct signalfd_siginfo));
>     if (s != sizeof(struct signalfd_siginfo))
>       handle_error("read");
>
>     if (fdsi.ssi_signo == SIGCHLD) {
>       printf("Got SIGCHLD %d %d %d %d\n",
>           fdsi.ssi_status, fdsi.ssi_code,
>           fdsi.ssi_uid, fdsi.ssi_pid);
>       return 0;
>     } else {
>       printf("Read unexpected signal\n");
>     }
>   }
> }
>
>
> and a multi-threaded client to test with:
>
> #include <unistd.h>
> #include <pthread.h>
>
> void *f(void *arg)
> {
>   sleep(100);
> }
>
> int main()
> {
>   pthread_t t[8];
>
>   for (int i = 0; i != 8; ++i)
>   {
>     pthread_create(&t[i], NULL, f, NULL);
>   }
> }
>
> I tried to do a bit of debugging and what seems to be happening is
> that
>
>   /* From an ancestor pid namespace? */
>   if (!task_pid_nr_ns(current, task_active_pid_ns(t))) {
>
> fails inside task_pid_nr_ns because the check for "pid_alive" fails.
>
> This code seems to be called from do_notify_parent and there we
> actually have "tsk != current" (I am assuming both are threads of the
> current process?)

I instrumented the code with a warning and received the following backtrace:
> WARNING: CPU: 0 PID: 777 at kernel/pid.c:501 __task_pid_nr_ns.cold.6+0xc/0x15
> Modules linked in:
> CPU: 0 PID: 777 Comm: sfdclient Not tainted 5.7.0-rc1userns+ raspberrypi#2924
> Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> RIP: 0010:__task_pid_nr_ns.cold.6+0xc/0x15
> Code: ff 66 90 48 83 ec 08 89 7c 24 04 48 8d 7e 08 48 8d 74 24 04 e8 9a b6 44 00 48 83 c4 08 c3 48 c7 c7 59 9f ac 82 e8 c2 c4 04 00 <0f> 0b e9 3fd
> RSP: 0018:ffffc9000042fbf8 EFLAGS: 00010046
> RAX: 000000000000000c RBX: 0000000000000000 RCX: ffffc9000042faf4
> RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff81193d29
> RBP: ffffc9000042fc18 R08: 0000000000000000 R09: 0000000000000001
> R10: 000000100f938416 R11: 0000000000000309 R12: ffff8880b941c140
> R13: 0000000000000000 R14: 0000000000000000 R15: ffff8880b941c140
> FS:  0000000000000000(0000) GS:ffff8880bca00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007f2e8c0a32e0 CR3: 0000000002e10000 CR4: 00000000000006f0
> Call Trace:
>  send_signal+0x1c8/0x310
>  do_notify_parent+0x50f/0x550
>  release_task.part.21+0x4fd/0x620
>  do_exit+0x6f6/0xaf0
>  do_group_exit+0x42/0xb0
>  get_signal+0x13b/0xbb0
>  do_signal+0x2b/0x670
>  ? __audit_syscall_exit+0x24d/0x2b0
>  ? rcu_read_lock_sched_held+0x4d/0x60
>  ? kfree+0x24c/0x2b0
>  do_syscall_64+0x176/0x640
>  ? trace_hardirqs_off_thunk+0x1a/0x1c
>  entry_SYSCALL_64_after_hwframe+0x49/0xb3

The immediate problem is as Christof noticed that "pid_alive(current) == false".
This happens because do_notify_parent is called from the last thread to exit
in a process after that thread has been reaped.

The bigger issue is that do_notify_parent can be called from any
process that manages to wait on a thread of a multi-threaded process
from wait_task_zombie.  So any logic based upon current for
do_notify_parent is just nonsense, as current can be pretty much
anything.

So change do_notify_parent to call __send_signal directly.

Inspecting the code it appears this problem has existed since the pid
namespace support started handling this case in 2.6.30.  This fix only
backports to 7a0cf09 ("signal: Correct namespace fixups of si_pid and si_uid")
where the problem logic was moved out of __send_signal and into send_signal.

Cc: stable@vger.kernel.org
Fixes: 6588c1e ("signals: SI_USER: Masquerade si_pid when crossing pid ns boundary")
Ref: 921cf9f ("signals: protect cinit from unblocked SIG_DFL signals")
Link: https://lore.kernel.org/lkml/20200419201336.GI22017@edge.cmeerw.net/
Reported-by: Christof Meerwald <cmeerw@cmeerw.org>
Acked-by: Oleg Nesterov <oleg@redhat.com>
Acked-by: Christian Brauner <christian.brauner@ubuntu.com>
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue May 4, 2020
commit 61e713b upstream.

Christof Meerwald <cmeerw@cmeerw.org> writes:
> Hi,
>
> this is probably related to commit
> 7a0cf09 (signal: Correct namespace
> fixups of si_pid and si_uid).
>
> With a 5.6.5 kernel I am seeing SIGCHLD signals that don't include a
> properly set si_pid field - this seems to happen for multi-threaded
> child processes.
>
> A simple test program (based on the sample from the signalfd man page):
>
> #include <sys/signalfd.h>
> #include <signal.h>
> #include <unistd.h>
> #include <spawn.h>
> #include <stdlib.h>
> #include <stdio.h>
>
> #define handle_error(msg) \
>     do { perror(msg); exit(EXIT_FAILURE); } while (0)
>
> int main(int argc, char *argv[])
> {
>   sigset_t mask;
>   int sfd;
>   struct signalfd_siginfo fdsi;
>   ssize_t s;
>
>   sigemptyset(&mask);
>   sigaddset(&mask, SIGCHLD);
>
>   if (sigprocmask(SIG_BLOCK, &mask, NULL) == -1)
>     handle_error("sigprocmask");
>
>   pid_t chldpid;
>   char *chldargv[] = { "./sfdclient", NULL };
>   posix_spawn(&chldpid, "./sfdclient", NULL, NULL, chldargv, NULL);
>
>   sfd = signalfd(-1, &mask, 0);
>   if (sfd == -1)
>     handle_error("signalfd");
>
>   for (;;) {
>     s = read(sfd, &fdsi, sizeof(struct signalfd_siginfo));
>     if (s != sizeof(struct signalfd_siginfo))
>       handle_error("read");
>
>     if (fdsi.ssi_signo == SIGCHLD) {
>       printf("Got SIGCHLD %d %d %d %d\n",
>           fdsi.ssi_status, fdsi.ssi_code,
>           fdsi.ssi_uid, fdsi.ssi_pid);
>       return 0;
>     } else {
>       printf("Read unexpected signal\n");
>     }
>   }
> }
>
>
> and a multi-threaded client to test with:
>
> #include <unistd.h>
> #include <pthread.h>
>
> void *f(void *arg)
> {
>   sleep(100);
> }
>
> int main()
> {
>   pthread_t t[8];
>
>   for (int i = 0; i != 8; ++i)
>   {
>     pthread_create(&t[i], NULL, f, NULL);
>   }
> }
>
> I tried to do a bit of debugging and what seems to be happening is
> that
>
>   /* From an ancestor pid namespace? */
>   if (!task_pid_nr_ns(current, task_active_pid_ns(t))) {
>
> fails inside task_pid_nr_ns because the check for "pid_alive" fails.
>
> This code seems to be called from do_notify_parent and there we
> actually have "tsk != current" (I am assuming both are threads of the
> current process?)

I instrumented the code with a warning and received the following backtrace:
> WARNING: CPU: 0 PID: 777 at kernel/pid.c:501 __task_pid_nr_ns.cold.6+0xc/0x15
> Modules linked in:
> CPU: 0 PID: 777 Comm: sfdclient Not tainted 5.7.0-rc1userns+ #2924
> Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> RIP: 0010:__task_pid_nr_ns.cold.6+0xc/0x15
> Code: ff 66 90 48 83 ec 08 89 7c 24 04 48 8d 7e 08 48 8d 74 24 04 e8 9a b6 44 00 48 83 c4 08 c3 48 c7 c7 59 9f ac 82 e8 c2 c4 04 00 <0f> 0b e9 3fd
> RSP: 0018:ffffc9000042fbf8 EFLAGS: 00010046
> RAX: 000000000000000c RBX: 0000000000000000 RCX: ffffc9000042faf4
> RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff81193d29
> RBP: ffffc9000042fc18 R08: 0000000000000000 R09: 0000000000000001
> R10: 000000100f938416 R11: 0000000000000309 R12: ffff8880b941c140
> R13: 0000000000000000 R14: 0000000000000000 R15: ffff8880b941c140
> FS:  0000000000000000(0000) GS:ffff8880bca00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007f2e8c0a32e0 CR3: 0000000002e10000 CR4: 00000000000006f0
> Call Trace:
>  send_signal+0x1c8/0x310
>  do_notify_parent+0x50f/0x550
>  release_task.part.21+0x4fd/0x620
>  do_exit+0x6f6/0xaf0
>  do_group_exit+0x42/0xb0
>  get_signal+0x13b/0xbb0
>  do_signal+0x2b/0x670
>  ? __audit_syscall_exit+0x24d/0x2b0
>  ? rcu_read_lock_sched_held+0x4d/0x60
>  ? kfree+0x24c/0x2b0
>  do_syscall_64+0x176/0x640
>  ? trace_hardirqs_off_thunk+0x1a/0x1c
>  entry_SYSCALL_64_after_hwframe+0x49/0xb3

The immediate problem is as Christof noticed that "pid_alive(current) == false".
This happens because do_notify_parent is called from the last thread to exit
in a process after that thread has been reaped.

The bigger issue is that do_notify_parent can be called from any
process that manages to wait on a thread of a multi-threaded process
from wait_task_zombie.  So any logic based upon current for
do_notify_parent is just nonsense, as current can be pretty much
anything.

So change do_notify_parent to call __send_signal directly.

Inspecting the code it appears this problem has existed since the pid
namespace support started handling this case in 2.6.30.  This fix only
backports to 7a0cf09 ("signal: Correct namespace fixups of si_pid and si_uid")
where the problem logic was moved out of __send_signal and into send_signal.

Cc: stable@vger.kernel.org
Fixes: 6588c1e ("signals: SI_USER: Masquerade si_pid when crossing pid ns boundary")
Ref: 921cf9f ("signals: protect cinit from unblocked SIG_DFL signals")
Link: https://lore.kernel.org/lkml/20200419201336.GI22017@edge.cmeerw.net/
Reported-by: Christof Meerwald <cmeerw@cmeerw.org>
Acked-by: Oleg Nesterov <oleg@redhat.com>
Acked-by: Christian Brauner <christian.brauner@ubuntu.com>
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
@soxrok2212
Copy link

soxrok2212 commented Aug 21, 2020

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
Copy link
Contributor

pelwell commented Aug 21, 2020

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
Copy link

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 ;)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Close within 30 days Issue will be closed within 30 days unless requested to stay open
Projects
None yet
Development

No branches or pull requests

8 participants