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

Linux kernel 4.9 wl18xx wlan0 interface isn't created. Debian stretch. #110

Closed
kenaaker opened this issue Jan 3, 2017 · 8 comments
Closed

Comments

@kenaaker
Copy link

kenaaker commented Jan 3, 2017

I've gotten the Debian Stretch system installed and booting on two Beaglebone Green Wireless boards, but when I switch the kernel from 4.4.26-ti-r59 to 4.9.0-ti-rt-r13 the wl18xx module doesn't materialize any interface.

The modules seem to get loaded, but I don't see any messages from the wl modules in dmesg. I've looked at the device tree a bit, but I don't know exactly what I'm looking for and there are many differences. Here's the uname-a and dmesg output.

By the way, I had some trouble getting Stretch to work until I changed the install root file ownership back to root (it was something like 110, if I remember correctly).

Linux beagle-green-2 4.9.0-ti-rt-r13 #1 SMP PREEMPT RT Thu Dec 29 05:59:47 UTC 2016 armv7l GNU/Linux
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.9.0-ti-rt-r13 (root@b2-omap5-uevm-2gb) (gcc version 6.2.1 20161124 (Debian 6.2.1-5) ) #1 SMP PREEMPT RT Thu Dec 29 05:59:47 UTC 2016
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt:Machine model: TI AM335x BeagleBone Green Wireless
[    0.000000] cma: Reserved 48 MiB at 0x9c800000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 130560
[    0.000000] free_area_init_node: node 0, pgdat c13e07c0, node_mem_map df961000
[    0.000000]   Normal zone: 1152 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 130560 pages, LIFO batch:31
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (sgx neon)
[    0.000000] percpu: Embedded 16 pages/cpu @df92b000 s33376 r8192 d23968 u65536
[    0.000000] pcpu-alloc: s33376 r8192 d23968 u65536 alloc=16*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 129408
[    0.000000] Kernel command line: console=ttyO0,115200n8 root=UUID=d2f545ad-6a18-4716-a6d0-e5551bbf07a2 ro rootfstype=ext4 rootwait coherent_pool=1M quiet
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 441592K/522240K available (12288K kernel code, 1009K rwdata, 4116K rodata, 1024K init, 791K bss, 31496K reserved, 49152K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xe0800000 - 0xff800000   ( 496 MB)
                   lowmem  : 0xc0000000 - 0xe0000000   ( 512 MB)
                   pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                   modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                     .text : 0xc0008000 - 0xc0d00000   (13280 kB)
                     .init : 0xc1200000 - 0xc1300000   (1024 kB)
                     .data : 0xc1300000 - 0xc13fc6c0   (1010 kB)
                      .bss : 0xc13fe000 - 0xc14c3f48   ( 792 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 32.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz
[    0.000013] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000028] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000035] OMAP clocksource: timer1 at 24000000 Hz
[    0.001184] clocksource_probe: no matching clocksources found
[    0.001400] Console: colour dummy device 80x30
[    0.001449] WARNING: Your 'console=ttyO0' has been replaced by 'ttyS0'
[    0.001452] This ensures that you still see kernel messages. Please
[    0.001455] update your kernel commandline.
[    0.046727] Calibrating delay loop... 995.32 BogoMIPS (lpj=1990656)
[    0.046748] pid_max: default: 32768 minimum: 301
[    0.047021] Security Framework initialized
[    0.047029] Yama: becoming mindful.
[    0.047063] AppArmor: AppArmor disabled by boot time parameter
[    0.047259] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.047267] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.048602] CPU: Testing write buffer coherency: ok
[    0.048613] ftrace: allocating 36693 entries in 108 pages
[    0.160773] CPU0: thread -1, cpu 0, socket -1, mpidr 0
[    0.160850] Setting up static identity map for 0x80100000 - 0x80100060
[    0.222788] Brought up 1 CPUs
[    0.222809] SMP: Total of 1 processors activated (995.32 BogoMIPS).
[    0.222816] CPU: All CPU(s) started in SVC mode.
[    0.224520] devtmpfs: initialized
[    0.247180] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.247807] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.251739] xor: measuring software checksum speed
[    0.290821]    arm4regs  :  1218.000 MB/sec
[    0.330764]    8regs     :  1091.000 MB/sec
[    0.370760]    32regs    :  1088.000 MB/sec
[    0.410758]    neon      :  1661.000 MB/sec
[    0.410767] xor: using function: neon (1661.000 MB/sec)
[    0.410785] pinctrl core: initialized pinctrl subsystem
[    0.413086] NET: Registered protocol family 16
[    0.418631] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.444172] omap_hwmod: debugss: _wait_target_disable failed
[    0.498308] cpuidle: using governor ladder
[    0.498353] cpuidle: using governor menu
[    0.508037] OMAP GPIO hardware version 0.1
[    0.516495] GPIO line 112 (MCASP0_AXR0) hogged as output/low
[    0.530165] No ATAGs?
[    0.530188] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.530461] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[    0.530471] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.630980] raid6: int32x1  gen()   258 MB/s
[    0.698860] raid6: int32x1  xor()   229 MB/s
[    0.766885] raid6: int32x2  gen()   323 MB/s
[    0.834780] raid6: int32x2  xor()   283 MB/s
[    0.902953] raid6: int32x4  gen()   329 MB/s
[    0.970826] raid6: int32x4  xor()   267 MB/s
[    1.038912] raid6: int32x8  gen()   300 MB/s
[    1.106821] raid6: int32x8  xor()   233 MB/s
[    1.174766] raid6: neonx1   gen()  1452 MB/s
[    1.242781] raid6: neonx1   xor()   843 MB/s
[    1.310789] raid6: neonx2   gen()  1918 MB/s
[    1.378782] raid6: neonx2   xor()  1190 MB/s
[    1.446768] raid6: neonx4   gen()  1090 MB/s
[    1.514759] raid6: neonx4   xor()   789 MB/s
[    1.582787] raid6: neonx8   gen()  1034 MB/s
[    1.650793] raid6: neonx8   xor()   754 MB/s
[    1.650801] raid6: using algorithm neonx2 gen() 1918 MB/s
[    1.650807] raid6: .... xor() 1190 MB/s, rmw enabled
[    1.650813] raid6: using intx1 recovery algorithm
[    1.663220] edma 49000000.edma: TI EDMA DMA engine driver
[    1.668707] SCSI subsystem initialized
[    1.670992] libata version 3.00 loaded.
[    1.671413] usbcore: registered new interface driver usbfs
[    1.671501] usbcore: registered new interface driver hub
[    1.671640] usbcore: registered new device driver usb
[    1.672348] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[    1.672404] omap_i2c 4819c000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c2_pins, deferring probe
[    1.672529] media: Linux media interface: v0.10
[    1.672611] Linux video capture interface: v2.00
[    1.672707] pps_core: LinuxPPS API ver. 1 registered
[    1.672714] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>
[    1.672739] PTP clock support registered
[    1.673445] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[    1.675251] NetLabel: Initializing
[    1.675267] NetLabel:  domain hash size = 128
[    1.675271] NetLabel:  protocols = UNLABELED CIPSOv4
[    1.675351] NetLabel:  unlabeled traffic allowed by default
[    1.679220] clocksource: Switched to clocksource timer1
[    1.851397] VFS: Disk quotas dquot_6.6.0
[    1.851529] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.869309] NET: Registered protocol family 2
[    1.870402] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    1.870468] TCP bind hash table entries: 4096 (order: 4, 114688 bytes)
[    1.870669] TCP: Hash tables configured (established 4096 bind 4096)
[    1.870754] UDP hash table entries: 256 (order: 2, 16384 bytes)
[    1.870795] UDP-Lite hash table entries: 256 (order: 2, 16384 bytes)
[    1.871098] NET: Registered protocol family 1
[    1.880277] RPC: Registered named UNIX socket transport module.
[    1.880290] RPC: Registered udp transport module.
[    1.880295] RPC: Registered tcp transport module.
[    1.880301] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.881069] Unpacking initramfs...
[    2.339609] Freeing initrd memory: 5592K (cfa8a000 - d0000000)
[    2.340165] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    2.343597] futex hash table entries: 256 (order: 2, 16384 bytes)
[    2.343741] audit: initializing netlink subsys (disabled)
[    2.343837] audit: type=2000 audit(2.268:1): initialized
[    2.349591] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    2.362514] zbud: loaded
[    2.371767] NFS: Registering the id_resolver key type
[    2.371822] Key type id_resolver registered
[    2.371829] Key type id_legacy registered
[    2.371849] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.372265] fuse init (API version 7.26)
[    2.373603] orangefs_debugfs_init: called with debug mask: :none: :0:
[    2.373950] orangefs_init: module version upstream loaded
[    2.373960] SGI XFS with ACLs, security attributes, realtime, no debug enabled
[    2.398459] Key type asymmetric registered
[    2.398476] Asymmetric key parser 'x509' registered
[    2.398909] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    2.403385] io scheduler noop registered
[    2.403396] io scheduler deadline registered
[    2.404005] io scheduler cfq registered (default)
[    2.405789] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    2.409713] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[    2.411741] Serial: 8250/16550 driver, 6 ports, IRQ sharing disabled
[    2.416005] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 158, base_baud = 3000000) is a 8250
[    2.428860] console [ttyS0] enabled
[    2.430211] 481a6000.serial: ttyS3 at MMIO 0x481a6000 (irq = 159, base_baud = 3000000) is a 8250
[    2.432140] [drm] Initialized
[    2.436825] libphy: Fixed MDIO Bus: probed
[    2.439737] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    2.439785] ehci-platform: EHCI generic platform driver
[    2.439999] ehci-omap: OMAP-EHCI Host Controller driver
[    2.440546] usbcore: registered new interface driver usb-storage
[    2.443070] 47401300.usb-phy supply vcc not found, using dummy regulator
[    2.449902] 47401b00.usb-phy supply vcc not found, using dummy regulator
[    2.454528] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[    2.454577] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
[    2.454909] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.454920] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.454928] usb usb1: Product: MUSB HDRC host driver
[    2.454935] usb usb1: Manufacturer: Linux 4.9.0-ti-rt-r13 musb-hcd
[    2.454942] usb usb1: SerialNumber: musb-hdrc.1.auto
[    2.456225] hub 1-0:1.0: USB hub found
[    2.456297] hub 1-0:1.0: 1 port detected
[    2.469731] mousedev: PS/2 mouse device common for all mice
[    2.472011] omap_rtc 44e3e000.rtc: already running
[    2.472634] omap_rtc 44e3e000.rtc: rtc core: registered 44e3e000.rtc as rtc0
[    2.474291] i2c /dev entries driver
[    2.476488] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    2.478050] cpuidle: enable-method property 'ti,am3352' found operations
[    2.479503] omap_hsmmc 48060000.mmc: Got CD GPIO
[    2.608690] mmc1: new high speed MMC card at address 0001
[    2.614060] mmcblk1: mmc1:0001 Q2J54A 3.64 GiB 
[    2.618759] mmcblk1boot0: mmc1:0001 Q2J54A partition 1 2.00 MiB
[    2.623606] mmcblk1boot1: mmc1:0001 Q2J54A partition 2 2.00 MiB
[    2.625617]  mmcblk1: p1
[    2.681083] hidraw: raw HID events driver (C) Jiri Kosina
[    2.683587] usbcore: registered new interface driver usbhid
[    2.683598] usbhid: USB HID core driver
[    2.686128] ashmem: initialized
[    2.686529]  remoteproc0: wkup_m3 is available
[    2.686540]  remoteproc0: Note: remoteproc is still under development and considered experimental.
[    2.686546]  remoteproc0: THE BINARY FORMAT IS NOT YET FINALIZED, and backward compatibility isn't yet guaranteed.
[    2.687748] omap_hsmmc 47810000.mmc: card claims to support voltages below defined range
[    2.691164] NET: Registered protocol family 10
[    2.697521] mip6: Mobile IPv6
[    2.697550] NET: Registered protocol family 17
[    2.697704] Key type dns_resolver registered
[    2.697712] mpls_gso: MPLS GSO support
[    2.698108] omap_voltage_late_init: Voltage driver support not added
[    2.703283] mmc2: new high speed SDIO card at address 0001
[    2.711420] PM: Cannot get wkup_m3_ipc handle
[    2.715971] ThumbEE CPU extension supported.
[    2.716002] Registering SWP/SWPB emulation handler
[    2.717261] registered taskstats version 1
[    2.717407] zswap: loaded using pool lzo/zbud
[    2.724882] Btrfs loaded, crc32c=crc32c-generic
[    2.758871] Key type encrypted registered
[    2.796104] random: fast init done
[    2.805633] input: tps65217_pwr_but as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0024/tps65217-pwrbutton/input/input0
[    2.806181] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[    2.806734] at24 0-0050: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.806803] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    2.809053] at24 2-0054: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.809502] at24 2-0055: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.809924] at24 2-0056: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.810324] at24 2-0057: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.810379] omap_i2c 4819c000.i2c: bus 2 rev0.11 at 100 kHz
[    2.812319]  remoteproc0: powering up wkup_m3
[    2.812344]  remoteproc0: Booting fw image am335x-pm-firmware.elf, size 217148
[    2.812644]  remoteproc0: remote processor wkup_m3 is now up
[    2.812719] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x192
[    2.818486] bone_capemgr bone_capemgr: Baseboard: 'A335BNLT,GW1A,BBGW16053793'
[    2.818518] bone_capemgr bone_capemgr: compatible-baseboard=ti,beaglebone-black - #slots=4
[    2.844385] bone_capemgr bone_capemgr: slot #0: No cape found
[    2.855277] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    2.875899] bone_capemgr bone_capemgr: slot #1: No cape found
[    2.908816] bone_capemgr bone_capemgr: slot #2: No cape found
[    2.940044] bone_capemgr bone_capemgr: slot #3: No cape found
[    2.945951] bone_capemgr bone_capemgr: initialized OK.
[    2.949027] PM: bootloader does not support rtc-only!
[    2.950156] omap_rtc 44e3e000.rtc: setting system clock to 2017-01-03 17:06:51 UTC (1483463211)
[    2.950171] of_cfs_init
[    2.950343] of_cfs_init: OK
[    2.950869] PM: Hibernation image not present or could not be loaded.
[    2.951020] wlan-en-regulator: disabling
[    2.954256] Freeing unused kernel memory: 1024K (c1200000 - c1300000)
[    2.997381] usb 1-1: New USB device found, idVendor=05e3, idProduct=0610
[    2.997399] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    2.997407] usb 1-1: Product: USB2.0 Hub
[    2.998819] hub 1-1:1.0: USB hub found
[    2.999532] hub 1-1:1.0: 4 ports detected
[    4.701736] EXT4-fs (mmcblk1p1): mounted filesystem with ordered data mode. Opts: (null)
[    5.249796] ip_tables: (C) 2000-2006 Netfilter Core Team
[    5.293995] 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)
[    5.294848] systemd[1]: Detected architecture arm.
[    5.296498] systemd[1]: Set hostname to <beagle-green-2>.
[    5.933902] systemd[1]: Listening on udev Kernel Socket.
[    5.934982] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    5.935989] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    5.936169] systemd[1]: Reached target Paths.
[    5.936662] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    5.936819] systemd[1]: Reached target Swap.
[    5.937154] systemd[1]: Listening on fsck to fsckd communication Socket.
[    6.458056] EXT4-fs (mmcblk1p1): re-mounted. Opts: errors=remount-ro
[    8.105570] systemd-journald[184]: Received request to flush runtime journal from PID 1
[   12.774164] using random self ethernet address
[   12.774187] using random host ethernet address
[   12.774202] using host ethernet address: 88:C2:55:56:04:BB
[   12.774210] using self ethernet address: 88:C2:55:56:04:BC
[   12.778741] usb0: HOST MAC 88:c2:55:56:04:bb
[   12.779051] usb0: MAC 88:c2:55:56:04:bc
[   12.779105] using random self ethernet address
[   12.779113] using random host ethernet address
[   12.781876] g_ether gadget: Ethernet Gadget, version: Memorial Day 2008
[   12.781894] g_ether gadget: g_ether ready
[   13.209259] g_ether gadget: high-speed config #1: CDC Ethernet (ECM)
[   15.638177] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20
[   16.482007] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
[   16.561499] omap-aes 53500000.aes: will run requests pump with realtime priority
[   16.619646] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[   18.467689] random: crng init done
[   22.124823] openafs: loading out-of-tree module taints kernel.
[   22.124850] openafs: module license 'http://www.openafs.org/dl/license10.html' taints kernel.
[   22.124856] Disabling lock debugging due to kernel taint
[   22.164677] Key type afs_pag registered
[   22.288840] enabling dynamically allocated vcaches
[   22.288859] Starting AFS cache scan...
[   25.190781] found 23 non-empty cache files (0%).
@RobertCNelson
Copy link
Member

@kenaaker

That's odd, double check that you have "bb-wl18xx-firmware" installed (since v4.4.x worked, it probally was).. BTW, what change did you do to stretch to make it work?

Well, it's working on jessie, wonder if it's a gcc bug in stretch or something else..

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.9.0-ti-r13 (root@a1-imx6q-wandboard-2gb) (gcc version 4.9.2 (Debian 4.9.2-10) ) #1 SMP Thu Dec 29 06:39:50 UTC 2016
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt:Machine model: TI AM335x BeagleBone Green Wireless
[    0.000000] cma: Reserved 48 MiB at 0x9c800000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 130560
[    0.000000] free_area_init_node: node 0, pgdat c13db600, node_mem_map df961000
[    0.000000]   Normal zone: 1152 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 130560 pages, LIFO batch:31
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (sgx neon)
[    0.000000] percpu: Embedded 15 pages/cpu @df92c000 s31680 r8192 d21568 u61440
[    0.000000] pcpu-alloc: s31680 r8192 d21568 u61440 alloc=15*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 129408
[    0.000000] Kernel command line: console=ttyO0,115200n8 root=UUID=145e17fc-7427-4ceb-bc73-30e2b3066572 ro rootfstype=ext4 rootwait coherent_pool=1M quiet cape_universal=enable
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 442256K/522240K available (12288K kernel code, 1079K rwdata, 4080K rodata, 1024K init, 735K bss, 30832K reserved, 49152K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xe0800000 - 0xff800000   ( 496 MB)
    lowmem  : 0xc0000000 - 0xe0000000   ( 512 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0xc0008000 - 0xc0d00000   (13280 kB)
      .init : 0xc1200000 - 0xc1300000   (1024 kB)
      .data : 0xc1300000 - 0xc140dd64   (1080 kB)
       .bss : 0xc140f000 - 0xc14c6db4   ( 736 kB)
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 32.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz
[    0.000015] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000031] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000039] OMAP clocksource: timer1 at 24000000 Hz
[    0.001263] clocksource_probe: no matching clocksources found
[    0.001719] Console: colour dummy device 80x30
[    0.001743] WARNING: Your 'console=ttyO0' has been replaced by 'ttyS0'
[    0.001748] This ensures that you still see kernel messages. Please
[    0.001751] update your kernel commandline.
[    0.001771] Calibrating delay loop... 995.32 BogoMIPS (lpj=1990656)
[    0.046773] pid_max: default: 32768 minimum: 301
[    0.047055] Security Framework initialized
[    0.047065] Yama: becoming mindful.
[    0.047102] AppArmor: AppArmor disabled by boot time parameter
[    0.047307] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.047315] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.048462] CPU: Testing write buffer coherency: ok
[    0.048529] ftrace: allocating 36867 entries in 109 pages
[    0.151738] CPU0: thread -1, cpu 0, socket -1, mpidr 0
[    0.151802] Setting up static identity map for 0x80100000 - 0x80100060
[    0.156293] Brought up 1 CPUs
[    0.156311] SMP: Total of 1 processors activated (995.32 BogoMIPS).
[    0.156316] CPU: All CPU(s) started in SVC mode.
[    0.157888] devtmpfs: initialized
[    0.176189] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.176695] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.180464] xor: measuring software checksum speed
[    0.218780]    arm4regs  :  1218.000 MB/sec
[    0.258767]    8regs     :  1091.000 MB/sec
[    0.298768]    32regs    :  1089.000 MB/sec
[    0.338767]    neon      :  1752.000 MB/sec
[    0.338773] xor: using function: neon (1752.000 MB/sec)
[    0.338789] pinctrl core: initialized pinctrl subsystem
[    0.340748] NET: Registered protocol family 16
[    0.344182] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.363995] omap_hwmod: debugss: _wait_target_disable failed
[    0.404976] cpuidle: using governor ladder
[    0.404988] cpuidle: using governor menu
[    0.412538] OMAP GPIO hardware version 0.1
[    0.418947] GPIO line 112 (MCASP0_AXR0) hogged as output/low
[    0.429972] No ATAGs?
[    0.429992] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.430274] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[    0.430281] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.510869] raid6: int32x1  gen()   233 MB/s
[    0.578774] raid6: int32x1  xor()   175 MB/s
[    0.646974] raid6: int32x2  gen()   304 MB/s
[    0.714860] raid6: int32x2  xor()   199 MB/s
[    0.782861] raid6: int32x4  gen()   283 MB/s
[    0.850773] raid6: int32x4  xor()   202 MB/s
[    0.918833] raid6: int32x8  gen()   286 MB/s
[    0.986883] raid6: int32x8  xor()   187 MB/s
[    1.054785] raid6: neonx1   gen()  1465 MB/s
[    1.090764] random: fast init done
[    1.122799] raid6: neonx1   xor()   846 MB/s
[    1.190784] raid6: neonx2   gen()  1895 MB/s
[    1.258774] raid6: neonx2   xor()  1181 MB/s
[    1.326794] raid6: neonx4   gen()  1929 MB/s
[    1.394766] raid6: neonx4   xor()  1204 MB/s
[    1.462774] raid6: neonx8   gen()  1188 MB/s
[    1.530791] raid6: neonx8   xor()   844 MB/s
[    1.530796] raid6: using algorithm neonx4 gen() 1929 MB/s
[    1.530800] raid6: .... xor() 1204 MB/s, rmw enabled
[    1.530804] raid6: using intx1 recovery algorithm
[    1.540295] edma 49000000.edma: TI EDMA DMA engine driver
[    1.545092] SCSI subsystem initialized
[    1.545536] libata version 3.00 loaded.
[    1.545870] usbcore: registered new interface driver usbfs
[    1.545944] usbcore: registered new interface driver hub
[    1.546048] usbcore: registered new device driver usb
[    1.546596] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[    1.546641] omap_i2c 4819c000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c2_pins, deferring probe
[    1.546734] media: Linux media interface: v0.10
[    1.546890] Linux video capture interface: v2.00
[    1.546986] pps_core: LinuxPPS API ver. 1 registered
[    1.546991] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>
[    1.547013] PTP clock support registered
[    1.547601] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[    1.548942] NetLabel: Initializing
[    1.548951] NetLabel:  domain hash size = 128
[    1.548955] NetLabel:  protocols = UNLABELED CIPSOv4
[    1.549033] NetLabel:  unlabeled traffic allowed by default
[    1.549920] clocksource: Switched to clocksource timer1
[    1.663080] VFS: Disk quotas dquot_6.6.0
[    1.663190] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.676932] NET: Registered protocol family 2
[    1.677900] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    1.678038] TCP bind hash table entries: 4096 (order: 3, 32768 bytes)
[    1.678095] TCP: Hash tables configured (established 4096 bind 4096)
[    1.678167] UDP hash table entries: 256 (order: 1, 8192 bytes)
[    1.678184] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
[    1.678390] NET: Registered protocol family 1
[    1.679103] RPC: Registered named UNIX socket transport module.
[    1.679112] RPC: Registered udp transport module.
[    1.679115] RPC: Registered tcp transport module.
[    1.679119] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.679709] Unpacking initramfs...
[    2.068151] Freeing initrd memory: 5176K (cfaf2000 - d0000000)
[    2.068789] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    2.071554] futex hash table entries: 256 (order: 2, 16384 bytes)
[    2.071663] audit: initializing netlink subsys (disabled)
[    2.071752] audit: type=2000 audit(2.000:1): initialized
[    2.073151] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    2.073315] zbud: loaded
[    2.074537] NFS: Registering the id_resolver key type
[    2.074585] Key type id_resolver registered
[    2.074590] Key type id_legacy registered
[    2.074606] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.074959] fuse init (API version 7.26)
[    2.075386] orangefs_debugfs_init: called with debug mask: :none: :0:
[    2.075645] orangefs_init: module version upstream loaded
[    2.075651] SGI XFS with ACLs, security attributes, realtime, no debug enabled
[    2.082317] Key type asymmetric registered
[    2.082329] Asymmetric key parser 'x509' registered
[    2.082454] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    2.082693] io scheduler noop registered
[    2.082700] io scheduler deadline registered
[    2.082787] io scheduler cfq registered (default)
[    2.084228] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    2.086761] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[    2.087834] Serial: 8250/16550 driver, 6 ports, IRQ sharing disabled
[    2.091367] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 158, base_baud = 3000000) is a 8250
[    2.104276] console [ttyS0] enabled
[    2.105320] 481a6000.serial: ttyS3 at MMIO 0x481a6000 (irq = 159, base_baud = 3000000) is a 8250
[    2.106850] [drm] Initialized
[    2.110309] libphy: Fixed MDIO Bus: probed
[    2.112334] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    2.112374] ehci-platform: EHCI generic platform driver
[    2.112535] ehci-omap: OMAP-EHCI Host Controller driver
[    2.112969] usbcore: registered new interface driver usb-storage
[    2.115264] 47401300.usb-phy supply vcc not found, using dummy regulator
[    2.120692] 47401b00.usb-phy supply vcc not found, using dummy regulator
[    2.124369] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[    2.124409] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
[    2.124719] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.124730] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.124736] usb usb1: Product: MUSB HDRC host driver
[    2.124743] usb usb1: Manufacturer: Linux 4.9.0-ti-r13 musb-hcd
[    2.124749] usb usb1: SerialNumber: musb-hdrc.1.auto
[    2.125704] hub 1-0:1.0: USB hub found
[    2.125770] hub 1-0:1.0: 1 port detected
[    2.136282] mousedev: PS/2 mouse device common for all mice
[    2.137815] omap_rtc 44e3e000.rtc: already running
[    2.138419] omap_rtc 44e3e000.rtc: rtc core: registered 44e3e000.rtc as rtc0
[    2.139290] i2c /dev entries driver
[    2.140884] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    2.142259] cpuidle: enable-method property 'ti,am3352' found operations
[    2.143219] omap_hsmmc 48060000.mmc: Got CD GPIO
[    2.271029] mmc1: new high speed MMC card at address 0001
[    2.272085] mmcblk1: mmc1:0001 Q2J54A 3.64 GiB 
[    2.272560] mmcblk1boot0: mmc1:0001 Q2J54A partition 1 2.00 MiB
[    2.273005] mmcblk1boot1: mmc1:0001 Q2J54A partition 2 2.00 MiB
[    2.274837]  mmcblk1: p1
[    2.343740] ledtrig-cpu: registered to indicate activity on CPUs
[    2.343979] hidraw: raw HID events driver (C) Jiri Kosina
[    2.347854] usbcore: registered new interface driver usbhid
[    2.347861] usbhid: USB HID core driver
[    2.348182] ashmem: initialized
[    2.348527]  remoteproc0: wkup_m3 is available
[    2.348535]  remoteproc0: Note: remoteproc is still under development and considered experimental.
[    2.348540]  remoteproc0: THE BINARY FORMAT IS NOT YET FINALIZED, and backward compatibility isn't yet guaranteed.
[    2.350530] omap_hsmmc 47810000.mmc: card claims to support voltages below defined range
[    2.350814] NET: Registered protocol family 10
[    2.352203] mip6: Mobile IPv6
[    2.352272] NET: Registered protocol family 17
[    2.352393] Key type dns_resolver registered
[    2.352399] mpls_gso: MPLS GSO support
[    2.352764] omap_voltage_late_init: Voltage driver support not added
[    2.359880] PM: Cannot get wkup_m3_ipc handle
[    2.364503] ThumbEE CPU extension supported.
[    2.364527] Registering SWP/SWPB emulation handler
[    2.365619] registered taskstats version 1
[    2.365786] zswap: loaded using pool lzo/zbud
[    2.367839] Btrfs loaded, crc32c=crc32c-generic
[    2.374247] mmc2: new high speed SDIO card at address 0001
[    2.397309] Key type encrypted registered
[    2.438255] input: tps65217_pwr_but as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0024/tps65217-pwrbutton/input/input0
[    2.438788] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[    2.439311] at24 0-0050: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.439361] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    2.441123] at24 2-0054: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.441481] at24 2-0055: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.441817] at24 2-0056: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.442274] at24 2-0057: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.442315] omap_i2c 4819c000.i2c: bus 2 rev0.11 at 100 kHz
[    2.443509]  remoteproc0: powering up wkup_m3
[    2.443574]  remoteproc0: Booting fw image am335x-pm-firmware.elf, size 217148
[    2.443831]  remoteproc0: remote processor wkup_m3 is now up
[    2.443850] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x192
[    2.449567] bone_capemgr bone_capemgr: Baseboard: 'A335BNLT,GW1A,BBGW16054886'
[    2.449594] bone_capemgr bone_capemgr: compatible-baseboard=ti,beaglebone-black - #slots=4
[    2.475011] bone_capemgr bone_capemgr: slot #0: No cape found
[    2.506154] bone_capemgr bone_capemgr: slot #1: No cape found
[    2.525941] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    2.538885] bone_capemgr bone_capemgr: slot #2: No cape found
[    2.569962] bone_capemgr bone_capemgr: slot #3: No cape found
[    2.575856] bone_capemgr bone_capemgr: initialized OK.
[    2.578287] PM: bootloader does not support rtc-only!
[    2.579191] omap_rtc 44e3e000.rtc: setting system clock to 2017-01-02 18:40:12 UTC (1483382412)
[    2.579202] of_cfs_init
[    2.579362] of_cfs_init: OK
[    2.579882] PM: Hibernation image not present or could not be loaded.
[    2.579989] wlan-en-regulator: disabling
[    2.581756] Freeing unused kernel memory: 1024K (c1200000 - c1300000)
[    2.727618] usb 1-1: New USB device found, idVendor=05e3, idProduct=0610
[    2.727634] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    2.727640] usb 1-1: Product: USB2.0 Hub
[    2.729030] hub 1-1:1.0: USB hub found
[    2.729402] hub 1-1:1.0: 4 ports detected
[    6.057755] EXT4-fs (mmcblk1p1): mounted filesystem with ordered data mode. Opts: (null)
[    6.488791] systemd[1]: Failed to insert module 'kdbus': Function not implemented
[    6.522350] systemd[1]: systemd 230 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    6.523110] systemd[1]: Detected architecture arm.
[    6.528748] systemd[1]: Set hostname to <test-bbgw-12>.
[    7.142734] systemd[1]: sysinit.target: Found ordering cycle on sysinit.target/start
[    7.142764] systemd[1]: sysinit.target: Found dependency on rpcbind.service/start
[    7.142787] systemd[1]: sysinit.target: Found dependency on network-online.target/start
[    7.142802] systemd[1]: sysinit.target: Found dependency on network.target/start
[    7.142817] systemd[1]: sysinit.target: Found dependency on connman.service/start
[    7.142831] systemd[1]: sysinit.target: Found dependency on dbus.service/start
[    7.142845] systemd[1]: sysinit.target: Found dependency on basic.target/start
[    7.478101] EXT4-fs (mmcblk1p1): re-mounted. Opts: errors=remount-ro
[    8.372514] systemd-journald[534]: Received request to flush runtime journal from PID 1
[   13.790749] random: crng init done
[   15.256550] using random self ethernet address
[   15.256566] using random host ethernet address
[   15.256584] using host ethernet address: 88:C2:55:56:23:D0
[   15.256591] using self ethernet address: 88:C2:55:56:23:D1
[   15.315352] Mass Storage Function, version: 2009/09/11
[   15.315371] LUN: removable file: (no medium)
[   15.315585] LUN: removable read only file: /var/cache/doc-seeed-bbgw-getting-started/beaglebone-getting-started-2016-05-11.img
[   15.315594] Number of LUNs=1
[   15.323385] usb0: HOST MAC 88:c2:55:56:23:d0
[   15.324091] usb0: MAC 88:c2:55:56:23:d1
[   15.334265] g_multi gadget: Multifunction Composite Gadget
[   15.334284] g_multi gadget: g_multi ready
[   16.010196] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
[   30.483792] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20
[   32.664581] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[   32.819577] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
[   32.826265] omap-aes 53500000.aes: will run requests pump with realtime priority
[   38.107377] wlcore: wl18xx HW: 183x or 180x, PG 2.2 (ROM 0x11)
[   38.232614] wlcore: loaded
[   38.702544] wlcore: PHY firmware version: Rev 8.2.0.0.236
[   38.746574] wlcore: firmware booted (Rev 8.9.0.0.69)
[   38.760835] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   40.230683] wlan0: authenticate with 14:cc:20:1d:b6:f6
[   40.245102] wlan0: send auth to 14:cc:20:1d:b6:f6 (try 1/3)
[   40.274318] wlan0: authenticated
[   40.279513] wlan0: associate with 14:cc:20:1d:b6:f6 (try 1/3)
[   40.284125] wlan0: RX AssocResp from 14:cc:20:1d:b6:f6 (capab=0x411 status=0 aid=1)
[   40.299883] wlan0: associated
[   40.300146] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   40.509637] wlcore: Association completed.
[   40.986378] Bluetooth: Core ver 2.22
[   40.986626] NET: Registered protocol family 31
[   40.986633] Bluetooth: HCI device and connection manager initialized
[   40.986659] Bluetooth: HCI socket layer initialized
[   40.986672] Bluetooth: L2CAP socket layer initialized
[   40.986719] Bluetooth: SCO socket layer initialized
[   41.008295] Bluetooth: HCI UART driver ver 2.3
[   41.008314] Bluetooth: HCI UART protocol H4 registered
[   41.008319] Bluetooth: HCI UART protocol BCSP registered
[   41.008323] Bluetooth: HCI UART protocol LL registered
[   41.008327] Bluetooth: HCI UART protocol ATH3K registered
[   41.008332] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   41.008619] Bluetooth: HCI UART protocol Broadcom registered
[   41.008625] Bluetooth: HCI UART protocol QCA registered
[   41.506210] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   41.506223] Bluetooth: BNEP filters: protocol multicast
[   41.506259] Bluetooth: BNEP socket layer initialized

@kenaaker
Copy link
Author

kenaaker commented Jan 3, 2017

Well, you got one problem on the first go. I didn't have bb-wl18xx-firmware installed. So, I fixed that. The behavior changed a bit, the Bluetooth: facility showed up. But, still no wlan, and no messages from wlcore.

As far as making Stretch work, I don't remember exactly. These days, I can try so many things so quickly, they all blur together and I have trouble remembering what the last thing I did was.

But, with blurry memory and all, I think that I was getting all sorts of odd behavior (that I don't remember the details of either) from Stretch until I looked at the ownership and permissions of the root directory "/" and found that on my sd card it was owned by 110 and not 0. Once I changed the ownership of "/" to 0, the system started to behave.

I want to suspect something in the wl* module initial probe, but I haven't been able to get any messages of any sort to show up from the wl* modules.

Here's the pertinent output from lsmod | grep -i wl. And also the new dmesg output

wl18xx                100443  0
wlcore                228577  1 wl18xx
mac80211              695363  2 wl18xx,wlcore
cfg80211              590551  3 wl18xx,wlcore,mac80211
wlcore_sdio             8971  0

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.9.0-ti-rt-r13 (root@b2-omap5-uevm-2gb) (gcc version 6.2.1 20161124 (Debian 6.2.1-5) ) #1 SMP PREEMPT RT Thu Dec 29 05:59:47 UTC 2016
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt:Machine model: TI AM335x BeagleBone Green Wireless
[    0.000000] cma: Reserved 48 MiB at 0x9c800000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 130560
[    0.000000] free_area_init_node: node 0, pgdat c13e07c0, node_mem_map df961000
[    0.000000]   Normal zone: 1152 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 130560 pages, LIFO batch:31
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (sgx neon)
[    0.000000] percpu: Embedded 16 pages/cpu @df92b000 s33376 r8192 d23968 u65536
[    0.000000] pcpu-alloc: s33376 r8192 d23968 u65536 alloc=16*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 129408
[    0.000000] Kernel command line: console=ttyO0,115200n8 root=UUID=d2f545ad-6a18-4716-a6d0-e5551bbf07a2 ro rootfstype=ext4 rootwait coherent_pool=1M quiet
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 441592K/522240K available (12288K kernel code, 1009K rwdata, 4116K rodata, 1024K init, 791K bss, 31496K reserved, 49152K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xe0800000 - 0xff800000   ( 496 MB)
                   lowmem  : 0xc0000000 - 0xe0000000   ( 512 MB)
                   pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                   modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                     .text : 0xc0008000 - 0xc0d00000   (13280 kB)
                     .init : 0xc1200000 - 0xc1300000   (1024 kB)
                     .data : 0xc1300000 - 0xc13fc6c0   (1010 kB)
                      .bss : 0xc13fe000 - 0xc14c3f48   ( 792 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 32.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz
[    0.000015] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000029] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000038] OMAP clocksource: timer1 at 24000000 Hz
[    0.001186] clocksource_probe: no matching clocksources found
[    0.001400] Console: colour dummy device 80x30
[    0.001448] WARNING: Your 'console=ttyO0' has been replaced by 'ttyS0'
[    0.001451] This ensures that you still see kernel messages. Please
[    0.001454] update your kernel commandline.
[    0.046720] Calibrating delay loop... 995.32 BogoMIPS (lpj=1990656)
[    0.046741] pid_max: default: 32768 minimum: 301
[    0.047012] Security Framework initialized
[    0.047019] Yama: becoming mindful.
[    0.047054] AppArmor: AppArmor disabled by boot time parameter
[    0.047247] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.047255] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.048586] CPU: Testing write buffer coherency: ok
[    0.048598] ftrace: allocating 36693 entries in 108 pages
[    0.160754] CPU0: thread -1, cpu 0, socket -1, mpidr 0
[    0.160827] Setting up static identity map for 0x80100000 - 0x80100060
[    0.222782] Brought up 1 CPUs
[    0.222804] SMP: Total of 1 processors activated (995.32 BogoMIPS).
[    0.222811] CPU: All CPU(s) started in SVC mode.
[    0.224512] devtmpfs: initialized
[    0.247167] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.247800] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.251701] xor: measuring software checksum speed
[    0.290819]    arm4regs  :  1218.000 MB/sec
[    0.330759]    8regs     :  1091.000 MB/sec
[    0.370752]    32regs    :  1088.000 MB/sec
[    0.410752]    neon      :  1657.000 MB/sec
[    0.410760] xor: using function: neon (1657.000 MB/sec)
[    0.410777] pinctrl core: initialized pinctrl subsystem
[    0.413067] NET: Registered protocol family 16
[    0.418609] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.444161] omap_hwmod: debugss: _wait_target_disable failed
[    0.498266] cpuidle: using governor ladder
[    0.498319] cpuidle: using governor menu
[    0.507976] OMAP GPIO hardware version 0.1
[    0.516406] GPIO line 112 (MCASP0_AXR0) hogged as output/low
[    0.530085] No ATAGs?
[    0.530108] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.530381] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[    0.530390] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.630926] raid6: int32x1  gen()   258 MB/s
[    0.698847] raid6: int32x1  xor()   229 MB/s
[    0.766778] raid6: int32x2  gen()   322 MB/s
[    0.834780] raid6: int32x2  xor()   283 MB/s
[    0.902781] raid6: int32x4  gen()   328 MB/s
[    0.970823] raid6: int32x4  xor()   267 MB/s
[    1.038908] raid6: int32x8  gen()   300 MB/s
[    1.106807] raid6: int32x8  xor()   233 MB/s
[    1.174781] raid6: neonx1   gen()  1452 MB/s
[    1.242776] raid6: neonx1   xor()   843 MB/s
[    1.310763] raid6: neonx2   gen()  1917 MB/s
[    1.378757] raid6: neonx2   xor()  1192 MB/s
[    1.446770] raid6: neonx4   gen()  1086 MB/s
[    1.514761] raid6: neonx4   xor()   787 MB/s
[    1.582779] raid6: neonx8   gen()  1034 MB/s
[    1.650782] raid6: neonx8   xor()   754 MB/s
[    1.650789] raid6: using algorithm neonx2 gen() 1917 MB/s
[    1.650795] raid6: .... xor() 1192 MB/s, rmw enabled
[    1.650801] raid6: using intx1 recovery algorithm
[    1.663181] edma 49000000.edma: TI EDMA DMA engine driver
[    1.668682] SCSI subsystem initialized
[    1.670982] libata version 3.00 loaded.
[    1.671405] usbcore: registered new interface driver usbfs
[    1.671493] usbcore: registered new interface driver hub
[    1.671629] usbcore: registered new device driver usb
[    1.672347] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[    1.672403] omap_i2c 4819c000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c2_pins, deferring probe
[    1.672527] media: Linux media interface: v0.10
[    1.672610] Linux video capture interface: v2.00
[    1.672705] pps_core: LinuxPPS API ver. 1 registered
[    1.672712] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[email protected]>
[    1.672737] PTP clock support registered
[    1.673446] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[    1.675249] NetLabel: Initializing
[    1.675264] NetLabel:  domain hash size = 128
[    1.675268] NetLabel:  protocols = UNLABELED CIPSOv4
[    1.675347] NetLabel:  unlabeled traffic allowed by default
[    1.679214] clocksource: Switched to clocksource timer1
[    1.851494] VFS: Disk quotas dquot_6.6.0
[    1.851615] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.869386] NET: Registered protocol family 2
[    1.870471] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    1.870537] TCP bind hash table entries: 4096 (order: 4, 114688 bytes)
[    1.870737] TCP: Hash tables configured (established 4096 bind 4096)
[    1.870832] UDP hash table entries: 256 (order: 2, 16384 bytes)
[    1.870873] UDP-Lite hash table entries: 256 (order: 2, 16384 bytes)
[    1.871177] NET: Registered protocol family 1
[    1.880375] RPC: Registered named UNIX socket transport module.
[    1.880389] RPC: Registered udp transport module.
[    1.880395] RPC: Registered tcp transport module.
[    1.880400] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.881155] Unpacking initramfs...
[    2.339916] Freeing initrd memory: 5592K (cfa8a000 - d0000000)
[    2.340470] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    2.343914] futex hash table entries: 256 (order: 2, 16384 bytes)
[    2.344052] audit: initializing netlink subsys (disabled)
[    2.344148] audit: type=2000 audit(2.268:1): initialized
[    2.349893] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    2.362826] zbud: loaded
[    2.372065] NFS: Registering the id_resolver key type
[    2.372125] Key type id_resolver registered
[    2.372132] Key type id_legacy registered
[    2.372152] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.372573] fuse init (API version 7.26)
[    2.373908] orangefs_debugfs_init: called with debug mask: :none: :0:
[    2.374256] orangefs_init: module version upstream loaded
[    2.374265] SGI XFS with ACLs, security attributes, realtime, no debug enabled
[    2.398755] Key type asymmetric registered
[    2.398773] Asymmetric key parser 'x509' registered
[    2.399411] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    2.403764] io scheduler noop registered
[    2.403775] io scheduler deadline registered
[    2.404379] io scheduler cfq registered (default)
[    2.406151] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    2.410076] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[    2.412093] Serial: 8250/16550 driver, 6 ports, IRQ sharing disabled
[    2.416331] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 158, base_baud = 3000000) is a 8250
[    2.429223] console [ttyS0] enabled
[    2.430555] 481a6000.serial: ttyS3 at MMIO 0x481a6000 (irq = 159, base_baud = 3000000) is a 8250
[    2.432470] [drm] Initialized
[    2.437149] libphy: Fixed MDIO Bus: probed
[    2.440093] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    2.440143] ehci-platform: EHCI generic platform driver
[    2.440349] ehci-omap: OMAP-EHCI Host Controller driver
[    2.440890] usbcore: registered new interface driver usb-storage
[    2.443609] 47401300.usb-phy supply vcc not found, using dummy regulator
[    2.450241] 47401b00.usb-phy supply vcc not found, using dummy regulator
[    2.454871] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[    2.454920] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
[    2.455389] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.455400] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.455408] usb usb1: Product: MUSB HDRC host driver
[    2.455416] usb usb1: Manufacturer: Linux 4.9.0-ti-rt-r13 musb-hcd
[    2.455423] usb usb1: SerialNumber: musb-hdrc.1.auto
[    2.456585] hub 1-0:1.0: USB hub found
[    2.456655] hub 1-0:1.0: 1 port detected
[    2.470119] mousedev: PS/2 mouse device common for all mice
[    2.472395] omap_rtc 44e3e000.rtc: already running
[    2.473000] omap_rtc 44e3e000.rtc: rtc core: registered 44e3e000.rtc as rtc0
[    2.474661] i2c /dev entries driver
[    2.476934] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    2.478467] cpuidle: enable-method property 'ti,am3352' found operations
[    2.479982] omap_hsmmc 48060000.mmc: Got CD GPIO
[    2.608686] mmc1: new high speed MMC card at address 0001
[    2.614054] mmcblk1: mmc1:0001 Q2J54A 3.64 GiB 
[    2.618749] mmcblk1boot0: mmc1:0001 Q2J54A partition 1 2.00 MiB
[    2.623605] mmcblk1boot1: mmc1:0001 Q2J54A partition 2 2.00 MiB
[    2.625611]  mmcblk1: p1
[    2.681085] hidraw: raw HID events driver (C) Jiri Kosina
[    2.683577] usbcore: registered new interface driver usbhid
[    2.683589] usbhid: USB HID core driver
[    2.686105] ashmem: initialized
[    2.686511]  remoteproc0: wkup_m3 is available
[    2.686522]  remoteproc0: Note: remoteproc is still under development and considered experimental.
[    2.686528]  remoteproc0: THE BINARY FORMAT IS NOT YET FINALIZED, and backward compatibility isn't yet guaranteed.
[    2.687730] omap_hsmmc 47810000.mmc: card claims to support voltages below defined range
[    2.691156] NET: Registered protocol family 10
[    2.697518] mip6: Mobile IPv6
[    2.697546] NET: Registered protocol family 17
[    2.697702] Key type dns_resolver registered
[    2.697711] mpls_gso: MPLS GSO support
[    2.698100] omap_voltage_late_init: Voltage driver support not added
[    2.703369] mmc2: new high speed SDIO card at address 0001
[    2.711465] PM: Cannot get wkup_m3_ipc handle
[    2.716013] ThumbEE CPU extension supported.
[    2.716043] Registering SWP/SWPB emulation handler
[    2.717298] registered taskstats version 1
[    2.717446] zswap: loaded using pool lzo/zbud
[    2.724907] Btrfs loaded, crc32c=crc32c-generic
[    2.758567] Key type encrypted registered
[    2.796122] random: fast init done
[    2.805708] input: tps65217_pwr_but as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0024/tps65217-pwrbutton/input/input0
[    2.806260] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[    2.806810] at24 0-0050: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.806875] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    2.809109] at24 2-0054: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.809556] at24 2-0055: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.809978] at24 2-0056: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.810376] at24 2-0057: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    2.810431] omap_i2c 4819c000.i2c: bus 2 rev0.11 at 100 kHz
[    2.812367]  remoteproc0: powering up wkup_m3
[    2.812392]  remoteproc0: Booting fw image am335x-pm-firmware.elf, size 217148
[    2.812687]  remoteproc0: remote processor wkup_m3 is now up
[    2.812761] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x192
[    2.818468] bone_capemgr bone_capemgr: Baseboard: 'A335BNLT,GW1A,BBGW16053793'
[    2.818500] bone_capemgr bone_capemgr: compatible-baseboard=ti,beaglebone-black - #slots=4
[    2.844387] bone_capemgr bone_capemgr: slot #0: No cape found
[    2.855273] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    2.875901] bone_capemgr bone_capemgr: slot #1: No cape found
[    2.908815] bone_capemgr bone_capemgr: slot #2: No cape found
[    2.940041] bone_capemgr bone_capemgr: slot #3: No cape found
[    2.945943] bone_capemgr bone_capemgr: initialized OK.
[    2.949021] PM: bootloader does not support rtc-only!
[    2.950144] omap_rtc 44e3e000.rtc: setting system clock to 2017-01-03 18:09:16 UTC (1483466956)
[    2.950160] of_cfs_init
[    2.950334] of_cfs_init: OK
[    2.950858] PM: Hibernation image not present or could not be loaded.
[    2.951007] wlan-en-regulator: disabling
[    2.954232] Freeing unused kernel memory: 1024K (c1200000 - c1300000)
[    2.997286] usb 1-1: New USB device found, idVendor=05e3, idProduct=0610
[    2.997305] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    2.997313] usb 1-1: Product: USB2.0 Hub
[    2.998754] hub 1-1:1.0: USB hub found
[    2.999184] hub 1-1:1.0: 4 ports detected
[    4.765618] EXT4-fs (mmcblk1p1): mounted filesystem with ordered data mode. Opts: (null)
[    5.325230] ip_tables: (C) 2000-2006 Netfilter Core Team
[    5.369143] 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)
[    5.369992] systemd[1]: Detected architecture arm.
[    5.371597] systemd[1]: Set hostname to <beagle-green-2>.
[    6.014243] systemd[1]: Listening on Journal Socket.
[    6.015561] systemd[1]: Listening on Syslog Socket.
[    6.016449] systemd[1]: Listening on Journal Audit Socket.
[    6.018254] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    6.018673] systemd[1]: Listening on udev Kernel Socket.
[    6.020757] systemd[1]: Created slice System Slice.
[    6.029172] systemd[1]: Mounting /sys/kernel/debug...
[    6.510105] EXT4-fs (mmcblk1p1): re-mounted. Opts: errors=remount-ro
[    7.913296] systemd-journald[190]: Received request to flush runtime journal from PID 1
[   13.034120] using random self ethernet address
[   13.034142] using random host ethernet address
[   13.034156] using host ethernet address: 88:C2:55:56:04:BB
[   13.034164] using self ethernet address: 88:C2:55:56:04:BC
[   13.038531] usb0: HOST MAC 88:c2:55:56:04:bb
[   13.038847] usb0: MAC 88:c2:55:56:04:bc
[   13.038908] using random self ethernet address
[   13.038916] using random host ethernet address
[   13.039085] g_ether gadget: Ethernet Gadget, version: Memorial Day 2008
[   13.039095] g_ether gadget: g_ether ready
[   13.466784] g_ether gadget: high-speed config #1: CDC Ethernet (ECM)
[   16.315729] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20
[   17.111526] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[   17.219793] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
[   17.231358] omap-aes 53500000.aes: will run requests pump with realtime priority
[   18.812639] random: crng init done
[   20.608772] systemd[1]: apt-daily.timer: Adding 1h 3min 53.279122s random time.
[   22.013108] systemd[1]: apt-daily.timer: Adding 11h 28min 10.564665s random time.
[   22.879963] openafs: loading out-of-tree module taints kernel.
[   22.879989] openafs: module license 'http://www.openafs.org/dl/license10.html' taints kernel.
[   22.879995] Disabling lock debugging due to kernel taint
[   22.944675] Key type afs_pag registered
[   23.136349] enabling dynamically allocated vcaches
[   23.136368] Starting AFS cache scan...
[   27.047465] found 23 non-empty cache files (0%).
[   31.403953] Bluetooth: Core ver 2.22
[   31.404166] NET: Registered protocol family 31
[   31.404177] Bluetooth: HCI device and connection manager initialized
[   31.404208] Bluetooth: HCI socket layer initialized
[   31.404227] Bluetooth: L2CAP socket layer initialized
[   31.404350] Bluetooth: SCO socket layer initialized
[   31.428084] Bluetooth: HCI UART driver ver 2.3
[   31.428106] Bluetooth: HCI UART protocol H4 registered
[   31.428112] Bluetooth: HCI UART protocol BCSP registered
[   31.428118] Bluetooth: HCI UART protocol LL registered
[   31.428124] Bluetooth: HCI UART protocol ATH3K registered
[   31.428130] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   31.428453] Bluetooth: HCI UART protocol Broadcom registered
[   31.428462] Bluetooth: HCI UART protocol QCA registered
[   31.775615] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   31.775633] Bluetooth: BNEP filters: protocol multicast
[   31.775670] Bluetooth: BNEP socket layer initialized

@kenaaker
Copy link
Author

kenaaker commented Jan 3, 2017

Just a bit of additional information. I'm switching between kernels by just editing the uname_r value in /boot/uEnv.txt. Everything else is untouched. Same stretch image. Could be problematical, but it seemed to minimize the failure possibilities.

And for the stretch image I started from. With the bone-debian-stretch-iot-armhf-2016-11-27-4gb.img mounted on a loopback, this is what I get for "ls -al ." I think the ownership and perms were causing trouble.

total 144
drwx------ 21  110  114  4096 Nov 27 08:47 .
drwxrwxrwt 43 root root 36864 Jan  3 14:26 ..
-rw-r--r--  1 root root    40 Nov 27 15:04 ID.txt
drwxr-xr-x  2 root root  4096 Nov 27 08:42 bin
drwxr-xr-x  4 root root  4096 Nov 27 15:05 boot
drwxr-xr-x  4 root root  4096 Nov 27 08:31 dev
drwxr-xr-x 72 root root  4096 Nov 27 08:47 etc
drwxr-xr-x  3 root root  4096 Nov 27 08:46 home
drwxr-xr-x 13 root root  4096 Nov 27 08:45 lib
drwx------  2 root root 16384 Nov 27 15:04 lost+found
drwxr-xr-x  2 root root  4096 Nov 27 08:31 media
drwxr-xr-x  2 root root  4096 Nov 27 08:31 mnt
-rw-r--r--  1 root root  1008 Nov 27 15:04 nfs-uEnv.txt
drwxr-xr-x  5 root root  4096 Nov 27 15:05 opt
drwxr-xr-x  2 root root  4096 Mar  4  2016 proc
drwx------  2 root root  4096 Nov 27 08:31 root
drwxr-xr-x  2 root root  4096 Mar  4  2016 run
drwxr-xr-x  2 root root  4096 Nov 27 08:44 sbin
drwxr-xr-x  2 root root  4096 Nov 27 08:31 srv
drwxr-xr-x  2 root root  4096 Mar  4  2016 sys
drwxrwxrwt  2 root root  4096 Nov 27 08:46 tmp
-rw-r--r--  1 root root  1179 Nov 27 15:04 uEnv.txt
drwxr-xr-x 10 root root  4096 Nov 27 08:31 usr
drwxr-xr-x 12 root root  4096 Nov 27 08:41 var

@kenaaker
Copy link
Author

kenaaker commented Jan 4, 2017

For variety, I decided to try the Jessie image again with the 4.9.0-ti-rt-r13 version.

I started with the bone-debian-8.6-iot-armhf-2016-12-18-4gb.img.xz image file, put it onto a fresh sd card, and booted it.

Once the fresh image was running, I ran through the connmanctl commands to configure the wlan0, so I could get the 4.9.0 image installed. Then did an apt-get update; and an

apt-get install linux-firmware-image-4.9.0-ti-rt-r13 linux-headers-4.9.0-ti-rt-r13 linux-image-4.9.0-ti-rt-r13

Once that was finished, I rebooted the system and got the same failure that I'm seeing on stretch. The wlan0 interface isn't created, no wl18xx or wlcore messages show up in dmesg, even though the modules are loaded.

Ken

@kenaaker
Copy link
Author

kenaaker commented Jan 6, 2017

Now, just to confuse things further. This morning I powered up the BBGW with stretch and the 4.9 kernel on it (after having been off all night) and the wl18xx wlan0 came up. Then, after I verified that it was running 4.9.0-ti-rt-r13, I powered it down and powered it back up again (pressed the power button on the board and waited for all the leds to go out). After the power cycle, the wl18xx wlan0 doesn't work again.

While I was thinking about that I installed 4.9.0-ti-rt-r13 on the other BBGW I have (stretch too) and power cycled that board. That one works through multiple power cycles.

One of the biggest disappointments in my life was when I figured out that computers aren't deterministic.

Ken

@kenaaker
Copy link
Author

Well, I've tracked the failure fairly deep into the bowels of the system, but I still haven't found the fundamental cause. wlcore is where the failure shows up, seemingly a timeout in a call to wl12xx_sdio_power_restore() which calls mmc_sdio_init_card() which calls mmc_select_card().
The mmc_select_card() call seems to be the operation that times out, but I don't know why yet.

And the second BBGW still is flawless. It comes up every time.

@kenaaker
Copy link
Author

I have a bit of an update. No resolution through... On the BBGW that generally works, I've captured a failure where the entire adapter goes down. So far, I haven't researched recovery options. If I reboot the BBGW, the adapter comes up again and works for a while. The failure generally occurs after some hours or days. There isn't a lot of traffic on the interface. (In the latest manifestation, 10Mb had been received and 1.3Mb had been transmitted). The failing messages from the system log are

[128218.147550] wl1271_sdio mmc2:0001:2: sdio write failed (-110)
[128218.394977] wlcore: ERROR firmware boot failed despite 3 retries

Here is an additional set of messages from dmesg output after the failure.
[128218.146498] ------------[ cut here ]------------
[128218.146557] WARNING: CPU: 0 PID: 620 at drivers/net/wireless/ti/wlcore/sdio.c:145 wl12xx_sdio_raw_write+0xf4/0x1c8 [wlcore_sdio]
[128218.146564] Modules linked in: joydev sg st sr_mod cdrom cmac bnep hci_uart btbcm btqca bluetooth arc4 wl18xx wlcore mac80211 pru_rproc pruss_intc cfg80211 pruss rfkill omap_aes_driver crypto_engine omap_sham pruss_soc_bus openafs(PO) omap_rng rng_core cdc_acm wlcore_sdio evdev tps65217_charger usb_f_ecm g_ether usb_f_rndis u_ether libcomposite uio_pdrv_genirq uio ip_tables x_tables
[128218.146666] CPU: 0 PID: 620 Comm: irq/54-s-wl18xx Tainted: P           O    4.9.13-ti-rt-r26 #1
[128218.146670] Hardware name: Generic AM33XX (Flattened Device Tree)
[128218.146710] [<c0113280>] (unwind_backtrace) from [<c010dda0>] (show_stack+0x20/0x24)
[128218.146729] [<c010dda0>] (show_stack) from [<c0751c30>] (dump_stack+0x80/0x94)
[128218.146743] [<c0751c30>] (dump_stack) from [<c013d6f0>] (__warn+0xf8/0x110)
[128218.146753] [<c013d6f0>] (__warn) from [<c013d820>] (warn_slowpath_null+0x30/0x38)
[128218.146766] [<c013d820>] (warn_slowpath_null) from [<bf06e2b8>] (wl12xx_sdio_raw_write+0xf4/0x1c8 [wlcore_sdio])
[128218.147031] [<bf06e2b8>] (wl12xx_sdio_raw_write [wlcore_sdio]) from [<bf39969c>] (wl1271_ps_elp_wakeup+0x160/0x250 [wlcore])
[128218.147186] [<bf39969c>] (wl1271_ps_elp_wakeup [wlcore]) from [<bf38a9ac>] (wlcore_irq_locked+0x74/0x7b0 [wlcore])
[128218.147323] [<bf38a9ac>] (wlcore_irq_locked [wlcore]) from [<bf38b3b0>] (wlcore_irq+0xd0/0x184 [wlcore])
[128218.147401] [<bf38b3b0>] (wlcore_irq [wlcore]) from [<c01adef0>] (irq_thread_fn+0x2c/0x64)
[128218.147412] [<c01adef0>] (irq_thread_fn) from [<c01ae248>] (irq_thread+0x154/0x22c)
[128218.147429] [<c01ae248>] (irq_thread) from [<c01629bc>] (kthread+0xfc/0x114)
[128218.147447] [<c01629bc>] (kthread) from [<c0109080>] (ret_from_fork+0x14/0x34)
[128218.147530] ---[ end trace 0000000000000002 ]---
[128218.147550] wl1271_sdio mmc2:0001:2: sdio write failed (-110)

And the output from uname -a
root@beagle-green-1:~# uname -a
Linux beagle-green-1 4.9.13-ti-rt-r26 #1 SMP PREEMPT RT Wed Mar 29 23:16:43 UTC 2017 armv7l GNU/Linux

Ken Aaker

RobertCNelson pushed a commit that referenced this issue Oct 25, 2017
Josef reported a HARDIRQ-safe -> HARDIRQ-unsafe lock order detected by
lockdep:

 [ 1270.472259] WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
 [ 1270.472783] 4.14.0-rc1-xfstests-12888-g76833e8 #110 Not tainted
 [ 1270.473240] -----------------------------------------------------
 [ 1270.473710] kworker/u5:2/5157 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
 [ 1270.474239]  (&(&lock->wait_lock)->rlock){+.+.}, at: [<ffffffff8da253d2>] __mutex_unlock_slowpath+0xa2/0x280
 [ 1270.474994]
 [ 1270.474994] and this task is already holding:
 [ 1270.475440]  (&pool->lock/1){-.-.}, at: [<ffffffff8d2992f6>] worker_thread+0x366/0x3c0
 [ 1270.476046] which would create a new lock dependency:
 [ 1270.476436]  (&pool->lock/1){-.-.} -> (&(&lock->wait_lock)->rlock){+.+.}
 [ 1270.476949]
 [ 1270.476949] but this new dependency connects a HARDIRQ-irq-safe lock:
 [ 1270.477553]  (&pool->lock/1){-.-.}
 ...
 [ 1270.488900] to a HARDIRQ-irq-unsafe lock:
 [ 1270.489327]  (&(&lock->wait_lock)->rlock){+.+.}
 ...
 [ 1270.494735]  Possible interrupt unsafe locking scenario:
 [ 1270.494735]
 [ 1270.495250]        CPU0                    CPU1
 [ 1270.495600]        ----                    ----
 [ 1270.495947]   lock(&(&lock->wait_lock)->rlock);
 [ 1270.496295]                                local_irq_disable();
 [ 1270.496753]                                lock(&pool->lock/1);
 [ 1270.497205]                                lock(&(&lock->wait_lock)->rlock);
 [ 1270.497744]   <Interrupt>
 [ 1270.497948]     lock(&pool->lock/1);

, which will cause a irq inversion deadlock if the above lock scenario
happens.

The root cause of this safe -> unsafe lock order is the
mutex_unlock(pool->manager_arb) in manage_workers() with pool->lock
held.

Unlocking mutex while holding an irq spinlock was never safe and this
problem has been around forever but it never got noticed because the
only time the mutex is usually trylocked while holding irqlock making
actual failures very unlikely and lockdep annotation missed the
condition until the recent b9c16a0 ("locking/mutex: Fix
lockdep_assert_held() fail").

Using mutex for pool->manager_arb has always been a bit of stretch.
It primarily is an mechanism to arbitrate managership between workers
which can easily be done with a pool flag.  The only reason it became
a mutex is that pool destruction path wants to exclude parallel
managing operations.

This patch replaces the mutex with a new pool flag POOL_MANAGER_ACTIVE
and make the destruction path wait for the current manager on a wait
queue.

v2: Drop unnecessary flag clearing before pool destruction as
    suggested by Boqun.

Signed-off-by: Tejun Heo <[email protected]>
Reported-by: Josef Bacik <[email protected]>
Reviewed-by: Lai Jiangshan <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Boqun Feng <[email protected]>
Cc: [email protected]
RobertCNelson pushed a commit that referenced this issue Nov 6, 2017
commit 692b482 upstream.

Josef reported a HARDIRQ-safe -> HARDIRQ-unsafe lock order detected by
lockdep:

 [ 1270.472259] WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
 [ 1270.472783] 4.14.0-rc1-xfstests-12888-g76833e8 #110 Not tainted
 [ 1270.473240] -----------------------------------------------------
 [ 1270.473710] kworker/u5:2/5157 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
 [ 1270.474239]  (&(&lock->wait_lock)->rlock){+.+.}, at: [<ffffffff8da253d2>] __mutex_unlock_slowpath+0xa2/0x280
 [ 1270.474994]
 [ 1270.474994] and this task is already holding:
 [ 1270.475440]  (&pool->lock/1){-.-.}, at: [<ffffffff8d2992f6>] worker_thread+0x366/0x3c0
 [ 1270.476046] which would create a new lock dependency:
 [ 1270.476436]  (&pool->lock/1){-.-.} -> (&(&lock->wait_lock)->rlock){+.+.}
 [ 1270.476949]
 [ 1270.476949] but this new dependency connects a HARDIRQ-irq-safe lock:
 [ 1270.477553]  (&pool->lock/1){-.-.}
 ...
 [ 1270.488900] to a HARDIRQ-irq-unsafe lock:
 [ 1270.489327]  (&(&lock->wait_lock)->rlock){+.+.}
 ...
 [ 1270.494735]  Possible interrupt unsafe locking scenario:
 [ 1270.494735]
 [ 1270.495250]        CPU0                    CPU1
 [ 1270.495600]        ----                    ----
 [ 1270.495947]   lock(&(&lock->wait_lock)->rlock);
 [ 1270.496295]                                local_irq_disable();
 [ 1270.496753]                                lock(&pool->lock/1);
 [ 1270.497205]                                lock(&(&lock->wait_lock)->rlock);
 [ 1270.497744]   <Interrupt>
 [ 1270.497948]     lock(&pool->lock/1);

, which will cause a irq inversion deadlock if the above lock scenario
happens.

The root cause of this safe -> unsafe lock order is the
mutex_unlock(pool->manager_arb) in manage_workers() with pool->lock
held.

Unlocking mutex while holding an irq spinlock was never safe and this
problem has been around forever but it never got noticed because the
only time the mutex is usually trylocked while holding irqlock making
actual failures very unlikely and lockdep annotation missed the
condition until the recent b9c16a0 ("locking/mutex: Fix
lockdep_assert_held() fail").

Using mutex for pool->manager_arb has always been a bit of stretch.
It primarily is an mechanism to arbitrate managership between workers
which can easily be done with a pool flag.  The only reason it became
a mutex is that pool destruction path wants to exclude parallel
managing operations.

This patch replaces the mutex with a new pool flag POOL_MANAGER_ACTIVE
and make the destruction path wait for the current manager on a wait
queue.

v2: Drop unnecessary flag clearing before pool destruction as
    suggested by Boqun.

Signed-off-by: Tejun Heo <[email protected]>
Reported-by: Josef Bacik <[email protected]>
Reviewed-by: Lai Jiangshan <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Boqun Feng <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
RobertCNelson pushed a commit that referenced this issue Jan 8, 2018
commit 692b482 upstream.

Josef reported a HARDIRQ-safe -> HARDIRQ-unsafe lock order detected by
lockdep:

 [ 1270.472259] WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
 [ 1270.472783] 4.14.0-rc1-xfstests-12888-g76833e8 #110 Not tainted
 [ 1270.473240] -----------------------------------------------------
 [ 1270.473710] kworker/u5:2/5157 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
 [ 1270.474239]  (&(&lock->wait_lock)->rlock){+.+.}, at: [<ffffffff8da253d2>] __mutex_unlock_slowpath+0xa2/0x280
 [ 1270.474994]
 [ 1270.474994] and this task is already holding:
 [ 1270.475440]  (&pool->lock/1){-.-.}, at: [<ffffffff8d2992f6>] worker_thread+0x366/0x3c0
 [ 1270.476046] which would create a new lock dependency:
 [ 1270.476436]  (&pool->lock/1){-.-.} -> (&(&lock->wait_lock)->rlock){+.+.}
 [ 1270.476949]
 [ 1270.476949] but this new dependency connects a HARDIRQ-irq-safe lock:
 [ 1270.477553]  (&pool->lock/1){-.-.}
 ...
 [ 1270.488900] to a HARDIRQ-irq-unsafe lock:
 [ 1270.489327]  (&(&lock->wait_lock)->rlock){+.+.}
 ...
 [ 1270.494735]  Possible interrupt unsafe locking scenario:
 [ 1270.494735]
 [ 1270.495250]        CPU0                    CPU1
 [ 1270.495600]        ----                    ----
 [ 1270.495947]   lock(&(&lock->wait_lock)->rlock);
 [ 1270.496295]                                local_irq_disable();
 [ 1270.496753]                                lock(&pool->lock/1);
 [ 1270.497205]                                lock(&(&lock->wait_lock)->rlock);
 [ 1270.497744]   <Interrupt>
 [ 1270.497948]     lock(&pool->lock/1);

, which will cause a irq inversion deadlock if the above lock scenario
happens.

The root cause of this safe -> unsafe lock order is the
mutex_unlock(pool->manager_arb) in manage_workers() with pool->lock
held.

Unlocking mutex while holding an irq spinlock was never safe and this
problem has been around forever but it never got noticed because the
only time the mutex is usually trylocked while holding irqlock making
actual failures very unlikely and lockdep annotation missed the
condition until the recent b9c16a0 ("locking/mutex: Fix
lockdep_assert_held() fail").

Using mutex for pool->manager_arb has always been a bit of stretch.
It primarily is an mechanism to arbitrate managership between workers
which can easily be done with a pool flag.  The only reason it became
a mutex is that pool destruction path wants to exclude parallel
managing operations.

This patch replaces the mutex with a new pool flag POOL_MANAGER_ACTIVE
and make the destruction path wait for the current manager on a wait
queue.

v2: Drop unnecessary flag clearing before pool destruction as
    suggested by Boqun.

Signed-off-by: Tejun Heo <[email protected]>
Reported-by: Josef Bacik <[email protected]>
Reviewed-by: Lai Jiangshan <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Boqun Feng <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
crow-misia pushed a commit to crow-misia/linux that referenced this issue Apr 22, 2019
[ Upstream commit 1da6c4d ]

syzkaller was able to generate the following UAF in bpf:

  BUG: KASAN: use-after-free in lookup_last fs/namei.c:2269 [inline]
  BUG: KASAN: use-after-free in path_lookupat.isra.43+0x9f8/0xc00 fs/namei.c:2318
  Read of size 1 at addr ffff8801c4865c47 by task syz-executor2/9423

  CPU: 0 PID: 9423 Comm: syz-executor2 Not tainted 4.20.0-rc1-next-20181109+
  beagleboard#110
  Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
  Google 01/01/2011
  Call Trace:
    __dump_stack lib/dump_stack.c:77 [inline]
    dump_stack+0x244/0x39d lib/dump_stack.c:113
    print_address_description.cold.7+0x9/0x1ff mm/kasan/report.c:256
    kasan_report_error mm/kasan/report.c:354 [inline]
    kasan_report.cold.8+0x242/0x309 mm/kasan/report.c:412
    __asan_report_load1_noabort+0x14/0x20 mm/kasan/report.c:430
    lookup_last fs/namei.c:2269 [inline]
    path_lookupat.isra.43+0x9f8/0xc00 fs/namei.c:2318
    filename_lookup+0x26a/0x520 fs/namei.c:2348
    user_path_at_empty+0x40/0x50 fs/namei.c:2608
    user_path include/linux/namei.h:62 [inline]
    do_mount+0x180/0x1ff0 fs/namespace.c:2980
    ksys_mount+0x12d/0x140 fs/namespace.c:3258
    __do_sys_mount fs/namespace.c:3272 [inline]
    __se_sys_mount fs/namespace.c:3269 [inline]
    __x64_sys_mount+0xbe/0x150 fs/namespace.c:3269
    do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
    entry_SYSCALL_64_after_hwframe+0x49/0xbe
  RIP: 0033:0x457569
  Code: fd b3 fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7
  48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff
  ff 0f 83 cb b3 fb ff c3 66 2e 0f 1f 84 00 00 00 00
  RSP: 002b:00007fde6ed96c78 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
  RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 0000000000457569
  RDX: 0000000020000040 RSI: 0000000020000000 RDI: 0000000000000000
  RBP: 000000000072bf00 R08: 0000000020000340 R09: 0000000000000000
  R10: 0000000000200000 R11: 0000000000000246 R12: 00007fde6ed976d4
  R13: 00000000004c2c24 R14: 00000000004d4990 R15: 00000000ffffffff

  Allocated by task 9424:
    save_stack+0x43/0xd0 mm/kasan/kasan.c:448
    set_track mm/kasan/kasan.c:460 [inline]
    kasan_kmalloc+0xc7/0xe0 mm/kasan/kasan.c:553
    __do_kmalloc mm/slab.c:3722 [inline]
    __kmalloc_track_caller+0x157/0x760 mm/slab.c:3737
    kstrdup+0x39/0x70 mm/util.c:49
    bpf_symlink+0x26/0x140 kernel/bpf/inode.c:356
    vfs_symlink+0x37a/0x5d0 fs/namei.c:4127
    do_symlinkat+0x242/0x2d0 fs/namei.c:4154
    __do_sys_symlink fs/namei.c:4173 [inline]
    __se_sys_symlink fs/namei.c:4171 [inline]
    __x64_sys_symlink+0x59/0x80 fs/namei.c:4171
    do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
    entry_SYSCALL_64_after_hwframe+0x49/0xbe

  Freed by task 9425:
    save_stack+0x43/0xd0 mm/kasan/kasan.c:448
    set_track mm/kasan/kasan.c:460 [inline]
    __kasan_slab_free+0x102/0x150 mm/kasan/kasan.c:521
    kasan_slab_free+0xe/0x10 mm/kasan/kasan.c:528
    __cache_free mm/slab.c:3498 [inline]
    kfree+0xcf/0x230 mm/slab.c:3817
    bpf_evict_inode+0x11f/0x150 kernel/bpf/inode.c:565
    evict+0x4b9/0x980 fs/inode.c:558
    iput_final fs/inode.c:1550 [inline]
    iput+0x674/0xa90 fs/inode.c:1576
    do_unlinkat+0x733/0xa30 fs/namei.c:4069
    __do_sys_unlink fs/namei.c:4110 [inline]
    __se_sys_unlink fs/namei.c:4108 [inline]
    __x64_sys_unlink+0x42/0x50 fs/namei.c:4108
    do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
    entry_SYSCALL_64_after_hwframe+0x49/0xbe

In this scenario path lookup under RCU is racing with the final
unlink in case of symlinks. As Linus puts it in his analysis:

  [...] We actually RCU-delay the inode freeing itself, but
  when we do the final iput(), the "evict()" function is called
  synchronously. Now, the simple fix would seem to just RCU-delay
  the kfree() of the symlink data in bpf_evict_inode(). Maybe
  that's the right thing to do. [...]

Al suggested to piggy-back on the ->destroy_inode() callback in
order to implement RCU deferral there which can then kfree() the
inode->i_link eventually right before putting inode back into
inode cache. By reusing free_inode_nonrcu() from there we can
avoid the need for our own inode cache and just reuse generic
one as we currently do.

And in-fact on top of all this we should just get rid of the
bpf_evict_inode() entirely. This means truncate_inode_pages_final()
and clear_inode() will then simply be called by the fs core via
evict(). Dropping the reference should really only be done when
inode is unhashed and nothing reachable anymore, so it's better
also moved into the final ->destroy_inode() callback.

Fixes: 0f98621 ("bpf, inode: add support for symlinks and fix mtime/ctime")
Reported-by: [email protected]
Reported-by: [email protected]
Reported-by: [email protected]
Suggested-by: Al Viro <[email protected]>
Analyzed-by: Linus Torvalds <[email protected]>
Signed-off-by: Daniel Borkmann <[email protected]>
Acked-by: Alexei Starovoitov <[email protected]>
Acked-by: Linus Torvalds <[email protected]>
Acked-by: Al Viro <[email protected]>
Link: https://lore.kernel.org/lkml/[email protected]/T/
Signed-off-by: Sasha Levin (Microsoft) <[email protected]>
@pdp7
Copy link
Contributor

pdp7 commented Jun 10, 2020

Please re-open if still an issue with our current Debian images:
https://github.com/beagleboard/Latest-Images

@pdp7 pdp7 closed this as completed Jun 10, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants