search

balena-os / balena-beaglebone

Balena support for Beaglebone boards
https://www.balena.io/os/
Apache License 2.0
20 stars 18 forks source link

mmc errors #25

Closed floion closed 8 years ago

floion commented 8 years ago

Observed while deploying an app on the beaglebone black:

root@beaglebone:~# [ 533.797044] mmcqd/1: page allocation failure: order:2, mode:0x2204020 [ 533.803549] CPU: 0 PID: 94 Comm: mmcqd/1 Not tainted 4.4.9+ #1 [ 533.809407] Hardware name: Generic AM33XX (Flattened Device Tree) [ 533.815568] from [ 533.823357] from [ 533.830629] from [ 533.838588] from [ 533.847688] from [ 533.856867] from [ 533.864910] from [ 533.872875] from [ 533.881712] from [ 533.890455] from [ 533.899282] from [ 533.907586] from [ 533.915976] from [ 533.924714] from [ 533.933110] from [ 533.940724] from [ 533.947975] Mem-Info: [ 533.950268] active_anon:44582 inactive_anon:2101 isolated_anon:0 [ 533.950268] active_file:32754 inactive_file:33078 isolated_file:0 [ 533.950268] unevictable:0 dirty:2406 writeback:4010 unstable:0 [ 533.950268] slab_reclaimable:7715 slab_unreclaimable:1871 [ 533.950268] mapped:6584 shmem:2140 pagetables:334 bounce:0 [ 533.950268] free:883 free_pcp:47 free_cma:0 [ 533.983803] Normal free:3532kB min:2824kB low:3528kB high:4236kB active_anon:178328kB inactive_anon:8404kB active_file:131016kB inactive_file:132312kB unevictable:0kB isolated(anon):0kB isolated(file):0kB pro [ 534.029776] lowmem_reserve[]: 0 0 0 [ 534.033303] Normal: 273_4kB (UE) 305_8kB (U) 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB 0_8192kB = 3532kB [ 534.045543] 67977 total pagecache pages [ 534.049398] 0 pages in swap cache [ 534.052725] Swap cache stats: add 0, delete 0, find 0/0 [ 534.057968] Free swap = 0kB [ 534.060856] Total swap = 0kB [ 534.063745] 130560 pages RAM [ 534.066633] 0 pages HighMem/MovableOnly [ 534.070480] 5628 pages reserved [ 534.073630] 6144 pages cma reserved [ 534.077345] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor [ 534.085083] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed [ 534.090701] omap_hsmmc 481d8000.mmc: MMC start dma failure [ 534.565156] mmcblk0: unknown error -1 sending read/write command, card status 0x900 [ 534.573018] blk_update_request: I/O error, dev mmcblk0, sector 2946304 [ 534.579617] blk_update_request: I/O error, dev mmcblk0, sector 2946312 [ 534.586263] blk_update_request: I/O error, dev mmcblk0, sector 2946320 [ 534.592861] blk_update_request: I/O error, dev mmcblk0, sector 2946328 [ 534.599439] blk_update_request: I/O error, dev mmcblk0, sector 2946336 [ 534.606035] blk_update_request: I/O error, dev mmcblk0, sector 2946344 [ 534.612629] blk_update_request: I/O error, dev mmcblk0, sector 2946352 [ 534.619206] blk_update_request: I/O error, dev mmcblk0, sector 2946360 [ 534.625797] blk_update_request: I/O error, dev mmcblk0, sector 2946368 [ 534.632389] blk_update_request: I/O error, dev mmcblk0, sector 2946376 [ 534.641574] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 1, rd 0, flush 0, corrupt 0, gen 0 [ 534.652128] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 2, rd 0, flush 0, corrupt 0, gen 0 [ 534.662821] mmcqd/1: page allocation failure: order:2, mode:0x2204020 [ 534.669302] CPU: 0 PID: 94 Comm: mmcqd/1 Not tainted 4.4.9+ #1 [ 534.675157] Hardware name: Generic AM33XX (Flattened Device Tree) [ 534.681315] from [ 534.689103] from [ 534.696376] from [ 534.704336] from [ 534.713436] from [ 534.722614] from [ 534.730658] from [ 534.738621] from [ 534.747459] from [ 534.756201] from [ 534.765028] from [ 534.773333] from [ 534.781810] from [ 534.790549] from [ 534.798945] from [ 534.806558] from [ 534.813810] Mem-Info: [ 534.816105] active_anon:44587 inactive_anon:2101 isolated_anon:0 [ 534.816105] active_file:32736 inactive_file:32781 isolated_file:0 [ 534.816105] unevictable:0 dirty:1493 writeback:4638 unstable:0 [ 534.816105] slab_reclaimable:7714 slab_unreclaimable:1871 [ 534.816105] mapped:6571 shmem:2140 pagetables:335 bounce:0 [ 534.816105] free:1193 free_pcp:36 free_cma:22 [ 534.849813] Normal free:4772kB min:2824kB low:3528kB high:4236kB active_anon:178348kB inactive_anon:8404kB active_file:130944kB inactive_file:131124kB unevictable:0kB isolated(anon):0kB isolated(file):0kB pro [ 534.895876] lowmem_reserve[]: 0 0 0 [ 534.899403] Normal: 457_4kB (UMEC) 368_8kB (UMC) 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB 0_8192kB = 4772kB [ 534.911988] 67675 total pagecache pages [ 534.915843] 0 pages in swap cache [ 534.919170] Swap cache stats: add 0, delete 0, find 0/0 [ 534.924413] Free swap = 0kB [ 534.927301] Total swap = 0kB [ 534.930189] 130560 pages RAM [ 534.933078] 0 pages HighMem/MovableOnly [ 534.936925] 5628 pages reserved [ 534.940075] 6144 pages cma reserved [ 534.943702] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor [ 534.951430] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed [ 534.957028] omap_hsmmc 481d8000.mmc: MMC start dma failure [ 535.467044] mmcblk0: unknown error -1 sending read/write command, card status 0x900 [ 535.476300] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 3, rd 0, flush 0, corrupt 0, gen 0 [ 535.486659] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 4, rd 0, flush 0, corrupt 0, gen 0 [ 535.496759] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 5, rd 0, flush 0, corrupt 0, gen 0 [ 535.506690] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 6, rd 0, flush 0, corrupt 0, gen 0 [ 535.516568] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 7, rd 0, flush 0, corrupt 0, gen 0 [ 535.526413] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 8, rd 0, flush 0, corrupt 0, gen 0 [ 535.536247] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 9, rd 0, flush 0, corrupt 0, gen 0 [ 535.546222] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 10, rd 0, flush 0, corrupt 0, gen 0 [ 535.712747] mmcqd/1: page allocation failure: order:2, mode:0x2204020 [ 535.719249] CPU: 0 PID: 94 Comm: mmcqd/1 Not tainted 4.4.9+ #1 [ 535.725106] Hardware name: Generic AM33XX (Flattened Device Tree) [ 535.731266] from [ 535.739053] from [ 535.746325] from [ 535.754285] from [ 535.763386] from [ 535.772564] from [ 535.780608] from [ 535.788573] from [ 535.797410] from [ 535.806152] from [ 535.814980] from [ 535.823284] from [ 535.831673] from [ 535.840412] from [ 535.848809] from [ 535.856422] from [ 535.863674] Mem-Info: [ 535.865968] active_anon:44587 inactive_anon:2101 isolated_anon:0 [ 535.865968] active_file:32735 inactive_file:33101 isolated_file:0 [ 535.865968] unevictable:0 dirty:1863 writeback:4159 unstable:0 [ 535.865968] slab_reclaimable:7714 slab_unreclaimable:1874 [ 535.865968] mapped:6598 shmem:2140 pagetables:335 bounce:0 [ 535.865968] free:883 free_pcp:38 free_cma:0 [ 535.899502] Normal free:3532kB min:2824kB low:3528kB high:4236kB active_anon:178348kB inactive_anon:8404kB active_file:130940kB inactive_file:132404kB unevictable:0kB isolated(anon):0kB isolated(file):0kB pro [ 535.945476] lowmem_reserve[]: 0 0 0 [ 535.949002] Normal: 281_4kB (UE) 301_8kB (U) 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB 0_8192kB = 3532kB [ 535.961239] 67984 total pagecache pages [ 535.965095] 0 pages in swap cache [ 535.968421] Swap cache stats: add 0, delete 0, find 0/0 [ 535.973664] Free swap = 0kB [ 535.976552] Total swap = 0kB [ 535.979441] 130560 pages RAM [ 535.982329] 0 pages HighMem/MovableOnly [ 535.986176] 5628 pages reserved [ 535.989326] 6144 pages cma reserved [ 535.993019] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor [ 536.000720] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed [ 536.006350] omap_hsmmc 481d8000.mmc: MMC start dma failure [ 536.400034] mmcblk0: unknown error -1 sending read/write command, card status 0x900

agherzan commented 8 years ago

@floion Could this be the same issue we experience on other boards?

floion commented 8 years ago

Can you link me to the other issue you are referring to @agherzan ?

floion commented 8 years ago

Also, today when trying to deploy an app, I got this:

[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Initializing cgroup subsys cpuacct [ 0.000000] Linux version 4.4.9+ (builder@b5d3d6d5eaa8) (gcc version 5.2.0 (GCC) ) #1 SMP Wed Aug 31 15:10:07 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] Machine model: TI AM335x BeagleBone Black [ 0.000000] cma: Reserved 24 MiB at 0x9e000000 [ 0.000000] Memory policy: Data cache writeback [ 0.000000] On node 0 totalpages: 130560 [ 0.000000] free_area_init_node: node 0, pgdat c1065c80, node_mem_map df96d000 [ 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 13 pages/cpu @df924000 s24192 r8192 d20864 u53248 [ 0.000000] pcpu-alloc: s24192 r8192 d20864 u53248 alloc=13_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=PARTUUID=c63c0048-02 rw rootfstype=ext4 rootwait [ 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: 474416K/522240K available (11265K kernel code, 960K rwdata, 3924K rodata, 736K init, 909K bss, 23248K reserved, 24576K 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 - 0xc0edd77c (15190 kB) .init : 0xc0ede000 - 0xc0f96000 ( 736 kB) .data : 0xc0f96000 - 0xc1086158 ( 961 kB) .bss : 0xc1089000 - 0xc116c7d0 ( 910 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.000037] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns [ 0.000048] OMAP clocksource: timer1 at 24000000 Hz [ 0.000375] Console: colour dummy device 80x30 [ 0.000402] WARNING: Your 'console=ttyO0' has been replaced by 'ttyS0' [ 0.000410] This ensures that you still see kernel messages. Please [ 0.000416] update your kernel commandline. [ 0.000437] Calibrating delay loop... 996.14 BogoMIPS (lpj=4980736) [ 0.088912] pid_max: default: 32768 minimum: 301 [ 0.089036] Security Framework initialized [ 0.089049] Yama: becoming mindful. [ 0.089090] AppArmor: AppArmor disabled by boot time parameter [ 0.089262] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes) [ 0.089274] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes) [ 0.090114] Initializing cgroup subsys io [ 0.090146] Initializing cgroup subsys memory [ 0.090186] Initializing cgroup subsys devices [ 0.090204] Initializing cgroup subsys freezer [ 0.090227] Initializing cgroup subsys net_cls [ 0.090242] Initializing cgroup subsys perf_event [ 0.090256] Initializing cgroup subsys net_prio [ 0.090309] CPU: Testing write buffer coherency: ok [ 0.090369] ftrace: allocating 36144 entries in 106 pages [ 0.192703] CPU0: thread -1, cpu 0, socket -1, mpidr 0 [ 0.192830] Setting up static identity map for 0x80008280 - 0x800082d8 [ 0.197723] Brought up 1 CPUs [ 0.197749] SMP: Total of 1 processors activated (996.14 BogoMIPS). [ 0.197757] CPU: All CPU(s) started in SVC mode. [ 0.199394] devtmpfs: initialized [ 0.215955] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3 [ 0.235225] omap_hwmod: debugss: _wait_target_disable failed [ 0.290743] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.293117] xor: measuring software checksum speed [ 0.388879] arm4regs : 1220.000 MB/sec [ 0.488874] 8regs : 1092.800 MB/sec [ 0.588873] 32regs : 1086.800 MB/sec [ 0.688873] neon : 1718.400 MB/sec [ 0.688881] xor: using function: neon (1718.400 MB/sec) [ 0.689029] pinctrl core: initialized pinctrl subsystem [ 0.691160] NET: Registered protocol family 16 [ 0.693558] DMA: preallocated 256 KiB pool for atomic coherent allocations [ 0.700198] OMAP GPIO hardware version 0.1 [ 0.712424] No ATAGs? [ 0.712459] hw-breakpoint: debug architecture 0x4 unsupported. [ 0.713067] omap4_sram_init:Unable to allocate sram needed to handle errata I688 [ 0.713082] omap4_sram_init:Unable to get sram pool needed to handle errata I688 [ 0.889109] raid6: int32x1 gen() 233 MB/s [ 1.058922] raid6: int32x1 xor() 176 MB/s [ 1.228950] raid6: int32x2 gen() 291 MB/s [ 1.398929] raid6: int32x2 xor() 199 MB/s [ 1.569063] raid6: int32x4 gen() 281 MB/s [ 1.738940] raid6: int32x4 xor() 203 MB/s [ 1.908971] raid6: int32x8 gen() 283 MB/s [ 2.078897] raid6: int32x8 xor() 182 MB/s [ 2.248900] raid6: neonx1 gen() 1451 MB/s [ 2.418902] raid6: neonx1 xor() 848 MB/s [ 2.588896] raid6: neonx2 gen() 1934 MB/s [ 2.758873] raid6: neonx2 xor() 1206 MB/s [ 2.928892] raid6: neonx4 gen() 1138 MB/s [ 3.098886] raid6: neonx4 xor() 928 MB/s [ 3.268923] raid6: neonx8 gen() 948 MB/s [ 3.438887] raid6: neonx8 xor() 795 MB/s [ 3.438894] raid6: using algorithm neonx2 gen() 1934 MB/s [ 3.438901] raid6: .... xor() 1206 MB/s, rmw enabled [ 3.438908] raid6: using intx1 recovery algorithm [ 3.447231] edma 49000000.edma: TI EDMA DMA engine driver [ 3.451897] vgaarb: loaded [ 3.452609] SCSI subsystem initialized [ 3.452976] libata version 3.00 loaded. [ 3.453304] usbcore: registered new interface driver usbfs [ 3.453377] usbcore: registered new interface driver hub [ 3.453447] usbcore: registered new device driver usb [ 3.454058] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe [ 3.454113] omap_i2c 4819c000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c2_pins, deferring probe [ 3.454270] pps_core: LinuxPPS API ver. 1 registered [ 3.454278] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti giometti@linux.it [ 3.454306] PTP clock support registered [ 3.455105] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400 [ 3.455809] Advanced Linux Sound Architecture Driver Initialized. [ 3.456550] NetLabel: Initializing [ 3.456561] NetLabel: domain hash size = 128 [ 3.456567] NetLabel: protocols = UNLABELED CIPSOv4 [ 3.456628] NetLabel: unlabeled traffic allowed by default [ 3.456984] clocksource: Switched to clocksource timer1 [ 3.561604] NET: Registered protocol family 2 [ 3.562390] TCP established hash table entries: 4096 (order: 2, 16384 bytes) [ 3.562441] TCP bind hash table entries: 4096 (order: 3, 32768 bytes) [ 3.562500] TCP: Hash tables configured (established 4096 bind 4096) [ 3.562575] UDP hash table entries: 256 (order: 1, 8192 bytes) [ 3.562596] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes) [ 3.562804] NET: Registered protocol family 1 [ 3.563461] RPC: Registered named UNIX socket transport module. [ 3.563479] RPC: Registered udp transport module. [ 3.563486] RPC: Registered tcp transport module. [ 3.563493] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 3.563530] PCI: CLS 0 bytes, default 64 [ 3.564468] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available [ 3.566852] futex hash table entries: 256 (order: 2, 16384 bytes) [ 3.567103] audit: initializing netlink subsys (disabled) [ 3.567192] audit: type=2000 audit(3.500:1): initialized [ 3.568938] VFS: Disk quotas dquot_6.6.0 [ 3.569026] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 3.569696] NFS: Registering the id_resolver key type [ 3.569763] Key type id_resolver registered [ 3.569771] Key type id_legacy registered [ 3.569798] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 3.570148] fuse init (API version 7.23) [ 3.570423] SGI XFS with ACLs, security attributes, realtime, no debug enabled [ 3.576146] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) [ 3.576350] io scheduler noop registered [ 3.576366] io scheduler deadline registered [ 3.576407] io scheduler cfq registered (default) [ 3.578055] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568 [ 3.579657] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle [ 3.581115] Serial: 8250/16550 driver, 6 ports, IRQ sharing disabled [ 3.584120] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 158, base_baud = 3000000) is a 8250 [ 4.427074] console [ttyS0] enabled [ 4.432135] [drm] Initialized drm 1.1.0 20060810 [ 4.436877] usbcore: registered new interface driver udl [ 4.445329] tun: Universal TUN/TAP device driver, 1.6 [ 4.450499] tun: (C) 1999-2004 Max Krasnyansky maxk@qualcomm.com [ 4.516990] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6 [ 4.523130] davinci_mdio 4a101000.mdio: detected phy mask fffffffe [ 4.529714] davinci_mdio: dt: updated phy_id[0] from phy_mask[fffffffe] [ 4.537749] libphy: 4a101000.mdio: probed [ 4.541797] davinci_mdio 4a101000.mdio: phy[0]: device 4a101000.mdio:00, driver SMSC LAN8710/LAN8720 [ 4.551773] cpsw 4a100000.ethernet: Detected MACID = d0:5f:b8:b3:b8:d8 [ 4.560743] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 4.567434] ehci-pci: EHCI PCI platform driver [ 4.571995] ehci-platform: EHCI generic platform driver [ 4.577527] ehci-omap: OMAP-EHCI Host Controller driver [ 4.584738] 47401300.usb-phy supply vcc not found, using dummy regulator [ 4.593728] musb-hdrc: ConfigData=0xde (UTMI-8, dyn FIFOs, bulk combine, bulk split, HB-ISO Rx, HB-ISO Tx, SoftConn) [ 4.593745] musb-hdrc: MHDRC RTL version 2.0 [ 4.593754] musb-hdrc: setup fifo_mode 4 [ 4.593774] musb-hdrc: 28/31 max ep, 16384/16384 memory [ 4.594843] 47401b00.usb-phy supply vcc not found, using dummy regulator [ 4.603748] musb-hdrc: ConfigData=0xde (UTMI-8, dyn FIFOs, bulk combine, bulk split, HB-ISO Rx, HB-ISO Tx, SoftConn) [ 4.603763] musb-hdrc: MHDRC RTL version 2.0 [ 4.603771] musb-hdrc: setup fifo_mode 4 [ 4.603786] musb-hdrc: 28/31 max ep, 16384/16384 memory [ 4.603926] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver [ 4.610243] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1 [ 4.618525] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002 [ 4.625347] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 4.632648] usb usb1: Product: MUSB HDRC host driver [ 4.637656] usb usb1: Manufacturer: Linux 4.4.9+ musb-hcd [ 4.643078] usb usb1: SerialNumber: musb-hdrc.1.auto [ 4.648949] hub 1-0:1.0: USB hub found [ 4.652773] hub 1-0:1.0: 1 port detected [ 4.666231] using random self ethernet address [ 4.670869] using random host ethernet address [ 4.676033] usb0: HOST MAC de:c1:fa:45:65:ac [ 4.680437] usb0: MAC 3a:04:3e:da:d6:24 [ 4.684327] using random self ethernet address [ 4.688821] using random host ethernet address [ 4.693388] g_ether gadget: Ethernet Gadget, version: Memorial Day 2008 [ 4.700063] g_ether gadget: g_ether ready [ 4.704841] mousedev: PS/2 mouse device common for all mice [ 4.712103] omap_rtc 44e3e000.rtc: rtc core: registered 44e3e000.rtc as rtc0 [ 4.720084] i2c /dev entries driver [ 4.725039] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec [ 4.732894] omap_hsmmc 48060000.mmc: Got CD GPIO [ 4.818359] ledtrig-cpu: registered to indicate activity on CPUs [ 4.824744] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2 [ 4.832427] omap-sham 53100000.sham: hw accel on OMAP rev 4.3 [ 4.839986] hidraw: raw HID events driver (C) Jiri Kosina [ 4.846565] usbcore: registered new interface driver usbhid [ 4.852253] usbhid: USB HID core driver [ 4.856456] ashmem: initialized [ 4.860736] remoteproc0: wkup_m3 is available [ 4.865212] remoteproc0: Note: remoteproc is still under development and considered experimental. [ 4.874278] remoteproc0: THE BINARY FORMAT IS NOT YET FINALIZED, and backward compatibility isn't yet guaranteed. [ 4.891654] oprofile: using arm/armv7 [ 4.895516] nf_conntrack version 0.5.0 (7796 buckets, 31184 max) [ 4.902739] ip_tables: (C) 2000-2006 Netfilter Core Team [ 4.908539] NET: Registered protocol family 10 [ 4.914466] mip6: Mobile IPv6 [ 4.917565] NET: Registered protocol family 17 [ 4.922113] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this. [ 4.934921] Key type dns_resolver registered [ 4.939243] mpls_gso: MPLS GSO support [ 4.943018] NET: Registered protocol family 41 [ 4.947801] omap_voltage_late_init: Voltage driver support not added [ 4.954988] PM: Cannot get wkup_m3_ipc handle [ 4.959537] ThumbEE CPU extension supported. [ 4.963850] Registering SWP/SWPB emulation handler [ 4.970626] registered taskstats version 1 [ 4.976524] zswap: default zpool zbud not available [ 4.981529] zswap: pool creation failed [ 4.988650] Btrfs loaded [ 4.992780] Key type encrypted registered [ 4.999621] input: tps65217_pwr_but as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0024/input/input0 [ 5.022888] mmc1: MAN_BKOPS_EN bit is not set [ 5.032583] mmc1: new high speed MMC card at address 0001 [ 5.039380] mmcblk0: mmc1:0001 MMC04G 3.60 GiB [ 5.044567] mmcblk0boot0: mmc1:0001 MMC04G partition 1 2.00 MiB [ 5.051487] mmcblk0boot1: mmc1:0001 MMC04G partition 2 2.00 MiB [ 5.060271] mmcblk0: p1 p2 p3 p4 < p5 p6 > [ 5.068938] tps65217 0-0024: TPS65217 ID 0xe version 1.2 [ 5.074826] at24 0-0050: 32768 byte 24c256 EEPROM, writable, 1 bytes/write [ 5.082204] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz [ 5.090546] at24 2-0054: 32768 byte 24c256 EEPROM, writable, 1 bytes/write [ 5.097960] at24 2-0055: 32768 byte 24c256 EEPROM, writable, 1 bytes/write [ 5.105216] at24 2-0056: 32768 byte 24c256 EEPROM, writable, 1 bytes/write [ 5.112563] at24 2-0057: 32768 byte 24c256 EEPROM, writable, 1 bytes/write [ 5.119543] omap_i2c 4819c000.i2c: bus 2 rev0.11 at 100 kHz [ 5.126550] remoteproc0: powering up wkup_m3 [ 5.131066] remoteproc0: Booting fw image am335x-pm-firmware.elf, size 219735 [ 5.138620] remoteproc0: remote processor wkup_m3 is now up [ 5.144318] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x191 [ 5.157631] bone_capemgr bone_capemgr: Baseboard: 'A335BNLT,00C0,3614BBBK7595' [ 5.164908] bone_capemgr bone_capemgr: compatible-baseboard=ti,beaglebone-black - #slots=4 [ 5.206972] usb 1-1: new high-speed USB device number 2 using musb-hdrc [ 5.226981] bone_capemgr bone_capemgr: slot #0: No cape found [ 5.286965] bone_capemgr bone_capemgr: slot #1: No cape found [ 5.347002] bone_capemgr bone_capemgr: slot #2: No cape found [ 5.355253] usb 1-1: New USB device found, idVendor=0a5c, idProduct=bd1e [ 5.362019] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [ 5.369208] usb 1-1: Product: Remote Download Wireless Adapter [ 5.375067] usb 1-1: Manufacturer: Broadcom [ 5.379286] usb 1-1: SerialNumber: 000000000001 [ 5.397013] bone_capemgr bone_capemgr: slot #3: No cape found [ 5.402865] bone_capemgr bone_capemgr: initialized OK. [ 5.409842] PM: bootloader does not support rtc-only! [ 5.415462] omap_rtc 44e3e000.rtc: setting system clock to 2000-01-01 00:00:01 UTC (946684801) [ 5.424230] of_cfs_init [ 5.426738] of_cfs_init: OK [ 5.434605] PM: Hibernation image not present or could not be loaded. [ 5.434762] ALSA device list: [ 5.437866] No soundcards found. [ 5.454077] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) [ 5.462378] VFS: Mounted root (ext4 filesystem) on device 179:2. [ 5.469151] devtmpfs: mounted [ 5.473106] Freeing unused kernel memory: 736K (c0ede000 - c0f96000) [ 5.676355] random: systemd urandom read with 21 bits of entropy available [ 5.699454] systemd[1]: systemd 225 running in system mode. (-PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT +GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN) [ 5.718412] systemd[1]: Detected architecture arm. [ 5.738084] systemd[1]: Set hostname to . [ 5.745775] systemd[1]: Initializing machine ID from random generator. [ 6.254104] systemd[1]: Reached target Swap. [ 6.278780] systemd[1]: Created slice Root Slice. [ 6.297554] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe. [ 6.327939] systemd[1]: Listening on Journal Audit Socket. [ 6.347712] systemd[1]: Listening on Journal Socket. [ 6.367593] systemd[1]: Listening on udev Control Socket. [ 6.387275] systemd[1]: Reached target Login Prompts. [ 6.407423] systemd[1]: Listening on Syslog Socket. [ 6.428198] systemd[1]: Created slice User and Session Slice. [ 6.447484] systemd[1]: Listening on udev Kernel Socket. [ 6.467518] systemd[1]: Listening on Journal Socket (/dev/log). [ 6.488198] systemd[1]: Created slice System Slice. [ 6.514272] systemd[1]: Starting Apply Kernel Variables... [ 6.551315] systemd[1]: Mounting POSIX Message Queue File System... [ 6.612219] systemd[1]: Mounting Temporary Directory... [ 6.651261] systemd[1]: Mounting FUSE Control File System... [ 6.687521] systemd[1]: Reached target Slices. [ 6.711407] systemd[1]: Mounting Configuration File System... [ 6.751508] systemd[1]: Mounting Debug File System... [ 6.798558] systemd[1]: Created slice system-resin\x2dinfo.slice. [ 6.821171] systemd[1]: Starting Remount Root and Kernel File Systems... [ 6.851660] systemd[1]: Starting Setup Virtual Console... [ 6.866736] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null) [ 6.901586] systemd[1]: Starting Journal Service... [ 6.970187] systemd[1]: Starting Create list of required static device nodes for the current kernel... [ 7.047868] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ 7.073269] systemd[1]: Mounted POSIX Message Queue File System. [ 7.117645] systemd[1]: Mounted Configuration File System. [ 7.130253] systemd[1]: Mounted Debug File System. [ 7.147557] systemd[1]: Mounted FUSE Control File System. [ 7.167564] systemd[1]: Mounted Temporary Directory. [ 7.188812] systemd[1]: Started Journal Service. [ 7.978454] systemd-journald[141]: Received request to flush runtime journal from PID 1 [ 13.657606] random: nonblocking pool is initialized [ 13.747253] tda998x 0-0070: found TDA19988 [ 13.760497] tilcdc 4830e000.lcdc: bound 0-0070 (ops tda998x_ops) [ 13.766563] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013). [ 13.773344] [drm] No driver support for vblank timestamp query. [ 13.912903] BTRFS: device label resin-data devid 1 transid 39 /dev/mmcblk0p6 [ 14.025512] tilcdc 4830e000.lcdc: No connectors reported connected with modes [ 14.032835] [drm] Cannot find any crtc or sizes - going 1024x768 [ 14.060154] usbcore: registered new interface driver brcmfmac [ 14.172607] Console: switching to colour frame buffer device 128x48 [ 14.365124] tilcdc 4830e000.lcdc: fb0: frame buffer device [ 14.370945] [drm] Initialized tilcdc 1.0.0 20121205 on minor 0 [ 14.379423] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20 [ 14.450708] asoc-simple-card sound: i2s-hifi <-> 48038000.mcasp mapping ok [ 14.471537] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Apr 3 2014 04:43:32 version 6.10.198.66 (r467479) FWID 01-32bd010e [ 14.522489] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code [ 15.236919] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code [ 15.243582] cfg80211: World regulatory domain updated: [ 15.248804] cfg80211: DFS Master region: unset [ 15.253181] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time) [ 15.262998] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A) [ 15.271059] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A) [ 15.279132] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A) [ 15.287196] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A) [ 15.296718] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s) [ 15.306260] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s) [ 15.314404] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A) [ 15.322461] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A) [ 16.764193] Bluetooth: Core ver 2.21 [ 16.768092] NET: Registered protocol family 31 [ 16.772559] Bluetooth: HCI device and connection manager initialized [ 16.779015] Bluetooth: HCI socket layer initialized [ 16.783924] Bluetooth: L2CAP socket layer initialized [ 16.789063] Bluetooth: SCO socket layer initialized [ 17.814450] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 17.820011] Bluetooth: BNEP filters: protocol multicast [ 17.825284] Bluetooth: BNEP socket layer initialized [ 17.988246] audit: type=1325 audit(1472069345.640:2): table=filter family=2 entries=0 [ 17.996181] audit: type=1325 audit(1472069345.640:2): table=nat family=2 entries=0 [ 18.005337] audit: type=1300 audit(1472069345.640:2): arch=40000028 syscall=337 per=800000 success=yes exit=0 a0=40000000 a1=b a2=40000040 a3=78 items=0 ppid=1 pid=519 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="(ostnamed)" exe="/lib/systemd/systemd" key=(null) [ 18.180461] audit: type=1327 audit(1472069345.640:2): proctitle="(ostnamed)" [ 18.666894] BTRFS info (device mmcblk0p6): disk space caching is enabled [ 18.673809] BTRFS: has skinny extents [ 18.880880] BTRFS: detected SSD devices, enabling SSD mode [ 18.907278] BTRFS: checking UUID tree [ 19.710293] BTRFS info (device mmcblk0p6): new size for /dev/mmcblk0p6 is 3414163456 [ 20.446510] audit: type=1325 audit(1472069348.100:3): table=filter family=2 entries=4 [ 20.454657] audit: type=1300 audit(1472069348.100:3): arch=40000028 syscall=294 per=800000 success=yes exit=0 a0=a a1=0 a2=40 a3=a102b8 items=0 ppid=1 pid=643 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="connmand" exe="/usr/sbin/connmand" key=(null) [ 20.669836] audit: type=1327 audit(1472069348.100:3): proctitle=2F7573722F7362696E2F636F6E6E6D616E64002D6E002D2D6E6F646E7370726F7879 [ 20.782907] audit: type=1325 audit(1472069348.440:4): table=mangle family=2 entries=0 [ 20.791080] audit: type=1325 audit(1472069348.440:4): table=mangle family=2 entries=0 [ 20.799115] audit: type=1300 audit(1472069348.440:4): arch=40000028 syscall=128 per=800000 success=yes exit=0 a0=b6a95008 a1=189c a2=28e28 a3=0 items=0 ppid=643 pid=666 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="modprobe" exe="/bin/kmod" key=(null) [ 21.353403] net eth0: initializing cpsw version 1.12 (0) [ 21.361317] net eth0: phy found : id is : 0x7c0f1 [ 21.446869] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 21.602503] brcmfmac: brcmf_add_if: ERROR: netdev:wlan0 already exists [ 21.609220] brcmfmac: brcmf_add_if: ignore IF event [ 21.622796] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 23.088242] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready [ 23.197790] Bridge firewalling registered [ 23.678376] audit_printk_skb: 39 callbacks suppressed [ 23.683531] audit: type=1325 audit(1472069351.340:9): table=nat family=2 entries=5 [ 23.691366] audit: type=1300 audit(1472069351.340:9): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=b86678 items=0 ppid=665 pid=703 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null) [ 23.726896] audit: type=1327 audit(1472069351.340:9): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4E00444F434B4552 [ 23.796415] audit: type=1325 audit(1472069351.450:10): table=filter family=2 entries=4 [ 23.804816] audit: type=1300 audit(1472069351.450:10): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=843568 items=0 ppid=665 pid=705 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null) [ 23.838464] audit: type=1327 audit(1472069351.450:10): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4E00444F434B4552 [ 23.909959] audit: type=1325 audit(1472069351.570:11): table=filter family=2 entries=6 [ 23.918295] audit: type=1300 audit(1472069351.570:11): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=41b728 items=0 ppid=665 pid=707 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-multi" key=(null) [ 23.972791] audit: type=1327 audit(1472069351.570:11): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4E00444F434B45522D49534F4C4154494F4E [ 24.074056] audit: type=1325 audit(1472069351.730:12): table=filter family=2 entries=8 [ 25.253882] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready [ 39.864901] BTRFS error (device mmcblk0p6): with mixed groups data and metadata balance options must be the same [ 54.844019] audit_printk_skb: 87 callbacks suppressed [ 54.849272] audit: type=1325 audit(1472706896.417:22): table=filter family=2 entries=14 [ 54.857457] audit: type=1300 audit(1472706896.417:22): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=1b08988 items=0 ppid=849 pid=850 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/sbin/xtables-multi" key=(null) [ 54.938107] audit: type=1327 audit(1472706896.417:22): proctitle=69707461626C6573002D4100494E505554002D7000746370002D2D64706F7274003438343834002D690074756E30002D6A00414343455054 [ 55.257143] audit: type=1325 audit(1472706896.827:23): table=filter family=2 entries=15 [ 55.265316] audit: type=1300 audit(1472706896.827:23): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=174fb48 items=0 ppid=853 pid=854 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/sbin/xtables-multi" key=(null) [ 55.342527] audit: type=1327 audit(1472706896.827:23): proctitle=69707461626C6573002D4100494E505554002D7000746370002D2D64706F7274003438343834002D6900646F636B657230002D6A00414343455054 [ 55.862860] audit: type=1325 audit(1472706897.437:24): table=filter family=2 entries=16 [ 55.871174] audit: type=1300 audit(1472706897.437:24): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=d45d08 items=0 ppid=857 pid=858 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/sbin/xtables-multi" key=(null) [ 55.903782] audit: type=1327 audit(1472706897.437:24): proctitle=69707461626C6573002D4100494E505554002D7000746370002D2D64706F7274003438343834002D69006C6F002D6A00414343455054 [ 56.101084] audit: type=1325 audit(1472706897.657:25): table=filter family=2 entries=17 [ 914.242098] audit_printk_skb: 6 callbacks suppressed [ 914.247170] audit: type=1130 audit(1472707755.784:26): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-journald" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 914.914217] audit: type=1130 audit(1472707756.454:27): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="kmod-static-nodes" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 915.064511] audit: type=1130 audit(1472707756.604:28): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-modules-load" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 915.188969] audit: type=1130 audit(1472707756.724:29): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-random-seed" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 915.397428] audit: type=1130 audit(1472707756.934:30): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="plymouth-read-write" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 915.598448] audit: type=1131 audit(1472707757.134:31): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="plymouth-read-write" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 915.819548] audit: type=1130 audit(1472707757.354:32): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-tmpfiles-setup" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 915.955625] audit: type=1130 audit(1472707757.494:33): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-udev-trigger" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 916.050895] systemd-journald[38]: Received request to flush runtime journal from PID 1 [ 916.103242] audit: type=1130 audit(1472707757.644:34): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-journal-flush" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 916.157013] audit: type=1131 audit(1472707757.694:35): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-journal-flush" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 916.891430] systemd-udevd[58]: starting version 215 [ 919.978235] audit_printk_skb: 42 callbacks suppressed [ 919.983517] audit: type=1130 audit(1472707761.513:50): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="plymouth-quit" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 920.677076] audit: type=1131 audit(1472707762.213:51): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="plymouth-quit" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 923.842644] audit: type=1131 audit(1472707765.383:52): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="launch" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 924.053327] audit: type=1130 audit(1472707765.593:53): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-rfkill@rfkill0" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 924.405900] audit: type=1129 audit(1472707765.943:54): pid=1561 uid=0 auid=4294967295 ses=4294967295 msg='old-level=N new-level=5 exe="/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success' [ 924.623047] audit: type=1130 audit(1472707766.163:55): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp-runlevel" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 924.683710] audit: type=1131 audit(1472707766.223:56): pid=1112 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp-runlevel" exe="/lib/systemd/systemd" hostname=? addr=? terminal=console res=success' [ 968.655859] audit: type=1325 audit(1472707810.192:57): table=filter family=2 entries=18 [ 968.664207] audit: type=1300 audit(1472707810.192:57): arch=40000028 syscall=294 per=c00000 success=yes exit=0 a0=4 a1=0 a2=40 a3=62cef8 items=0 ppid=1681 pid=1682 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/sbin/xtables-multi" key=(null) [ 968.753459] audit: type=1327 audit(1472707810.192:57): proctitle=69707461626C6573002D4300494E505554002D7000746370002D2D64706F7274003438343834002D6A0052454A454354 [ 3176.127818] mmcqd/1: page allocation failure: order:2, mode:0x2204020 [ 3176.134321] CPU: 0 PID: 94 Comm: mmcqd/1 Not tainted 4.4.9+ #1 [ 3176.140178] Hardware name: Generic AM33XX (Flattened Device Tree) [ 3176.146338] from [ 3176.154126] from [ 3176.161399] from [ 3176.169361] from [ 3176.178463] from [ 3176.187640] from [ 3176.195685] from [ 3176.203647] from [ 3176.212485] from [ 3176.221227] from [ 3176.230054] from [ 3176.238358] from [ 3176.246747] from [ 3176.255486] from [ 3176.263882] from [ 3176.271495] from [ 3176.278747] Mem-Info: [ 3176.281039] active_anon:38239 inactive_anon:2119 isolated_anon:0 active_file:33259 inactive_file:33753 isolated_file:0 unevictable:0 dirty:14 writeback:1280 unstable:0 slab_reclaimable:12285 slab_unreclaimable:2087 mapped:4927 shmem:2142 pagetables:319 bounce:0 free:1180 free_pcp:188 free_cma:154 [ 3176.314835] Normal free:4720kB min:2824kB low:3528kB high:4236kB active_anon:152956kB inactive_anon:8476kB active_file:133036kB inactive_file:135012kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:522240kB managed:499728kB mlocked:0kB dirty:56kB writeback:5120kB mapped:19708kB shmem:8568kB slab_reclaimable:49140kB slab_unreclaimable:8348kB kernel_stack:1200kB pagetables:1276kB unstable:0kB bounce:0kB free_pcp:752kB local_pcp:752kB free_cma:616kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [ 3176.360722] lowmem_reserve[]: 0 0 0 [ 3176.364249] Normal: 776_4kB (UMEC) 194_8kB (UMEC) 4_16kB (C) 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB 0_8192kB = 4720kB [ 3176.377277] 69151 total pagecache pages [ 3176.381131] 0 pages in swap cache [ 3176.384458] Swap cache stats: add 0, delete 0, find 0/0 [ 3176.389700] Free swap = 0kB [ 3176.392589] Total swap = 0kB [ 3176.395478] 130560 pages RAM [ 3176.398366] 0 pages HighMem/MovableOnly [ 3176.402213] 5628 pages reserved [ 3176.405363] 6144 pages cma reserved [ 3176.409137] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor [ 3176.416868] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed [ 3176.422487] omap_hsmmc 481d8000.mmc: MMC start dma failure [ 3176.584912] mmcblk0: unknown error -1 sending read/write command, card status 0x900 [ 3176.592791] blk_update_request: I/O error, dev mmcblk0, sector 2680832 [ 3176.599389] blk_update_request: I/O error, dev mmcblk0, sector 2680840 [ 3176.606056] blk_update_request: I/O error, dev mmcblk0, sector 2680848 [ 3176.612655] blk_update_request: I/O error, dev mmcblk0, sector 2680856 [ 3176.619232] blk_update_request: I/O error, dev mmcblk0, sector 2680864 [ 3176.625837] blk_update_request: I/O error, dev mmcblk0, sector 2680872 [ 3176.632431] blk_update_request: I/O error, dev mmcblk0, sector 2680880 [ 3176.639006] blk_update_request: I/O error, dev mmcblk0, sector 2680888 [ 3176.645600] blk_update_request: I/O error, dev mmcblk0, sector 2680896 [ 3176.652191] blk_update_request: I/O error, dev mmcblk0, sector 2680904 [ 3176.661342] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 1, rd 0, flush 0, corrupt 0, gen 0 [ 3176.771448] mmcqd/1: page allocation failure: order:2, mode:0x2204020 [ 3176.777949] CPU: 0 PID: 94 Comm: mmcqd/1 Not tainted 4.4.9+ #1 [ 3176.783806] Hardware name: Generic AM33XX (Flattened Device Tree) [ 3176.789966] from [ 3176.797753] from [ 3176.805026] from [ 3176.812985] from [ 3176.822085] from [ 3176.831262] from [ 3176.839306] from [ 3176.847270] from [ 3176.856108] from [ 3176.864850] from [ 3176.873677] from [ 3176.881981] from [ 3176.890370] from [ 3176.899108] from [ 3176.907504] from [ 3176.915118] from [ 3176.922368] Mem-Info: [ 3176.924660] active_anon:38240 inactive_anon:2119 isolated_anon:0 active_file:33158 inactive_file:33739 isolated_file:0 unevictable:0 dirty:9 writeback:1027 unstable:0 slab_reclaimable:12374 slab_unreclaimable:2085 mapped:4935 shmem:2142 pagetables:319 bounce:0 free:1239 free_pcp:155 free_cma:154 [ 3176.958369] Normal free:4956kB min:2824kB low:3528kB high:4236kB active_anon:152960kB inactive_anon:8476kB active_file:132632kB inactive_file:134956kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:522240kB managed:499728kB mlocked:0kB dirty:36kB writeback:4108kB mapped:19740kB shmem:8568kB slab_reclaimable:49496kB slab_unreclaimable:8340kB kernel_stack:1200kB pagetables:1276kB unstable:0kB bounce:0kB free_pcp:620kB local_pcp:620kB free_cma:616kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [ 3177.004255] lowmem_reserve[]: 0 0 0 [ 3177.007784] Normal: 816_4kB (UMEC) 204_8kB (UMEC) 4_16kB (C) 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB 0_8192kB = 4960kB [ 3177.020815] 69040 total pagecache pages [ 3177.024670] 0 pages in swap cache [ 3177.027996] Swap cache stats: add 0, delete 0, find 0/0 [ 3177.033239] Free swap = 0kB [ 3177.036127] Total swap = 0kB [ 3177.039015] 130560 pages RAM [ 3177.041904] 0 pages HighMem/MovableOnly [ 3177.045751] 5628 pages reserved [ 3177.048901] 6144 pages cma reserved [ 3177.052608] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor [ 3177.060309] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed [ 3177.065992] omap_hsmmc 481d8000.mmc: MMC start dma failure [ 3177.165428] mmcblk0: unknown error -1 sending read/write command, card status 0x900 [ 3177.176097] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 2, rd 0, flush 0, corrupt 0, gen 0 [ 3177.187401] mmcqd/1: page allocation failure: order:2, mode:0x2204020 [ 3177.193889] CPU: 0 PID: 94 Comm: mmcqd/1 Not tainted 4.4.9+ #1 [ 3177.199745] Hardware name: Generic AM33XX (Flattened Device Tree) [ 3177.205902] from [ 3177.213690] from [ 3177.220961] from [ 3177.228922] from [ 3177.238022] from [ 3177.247200] from [ 3177.255243] from [ 3177.263207] from [ 3177.272045] from [ 3177.280787] from [ 3177.289614] from [ 3177.297918] from [ 3177.306395] from [ 3177.315132] from [ 3177.323530] from [ 3177.331144] from [ 3177.338395] Mem-Info: [ 3177.340688] active_anon:38240 inactive_anon:2119 isolated_anon:0 active_file:33158 inactive_file:33717 isolated_file:0 unevictable:0 dirty:9 writeback:507 unstable:0 slab_reclaimable:12374 slab_unreclaimable:2085 mapped:4945 shmem:2142 pagetables:319 bounce:0 free:1237 free_pcp:178 free_cma:154 [ 3177.374309] Normal free:4948kB min:2824kB low:3528kB high:4236kB active_anon:152960kB inactive_anon:8476kB active_file:132632kB inactive_file:134868kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:522240kB managed:499728kB mlocked:0kB dirty:36kB writeback:2028kB mapped:19780kB shmem:8568kB slab_reclaimable:49496kB slab_unreclaimable:8340kB kernel_stack:1200kB pagetables:1276kB unstable:0kB bounce:0kB free_pcp:712kB local_pcp:712kB free_cma:616kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [ 3177.420196] lowmem_reserve[]: 0 0 0 [ 3177.423724] Normal: 874_4kB (UMEC) 175_8kB (UMEC) 4_16kB (C) 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB 0*8192kB = 4960kB [ 3177.436754] 69020 total pagecache pages [ 3177.440609] 0 pages in swap cache [ 3177.443935] Swap cache stats: add 0, delete 0, find 0/0 [ 3177.449178] Free swap = 0kB [ 3177.452066] Total swap = 0kB [ 3177.454955] 130560 pages RAM [ 3177.457844] 0 pages HighMem/MovableOnly [ 3177.461691] 5628 pages reserved [ 3177.464841] 6144 pages cma reserved [ 3177.468559] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor [ 3177.476295] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed [ 3177.481929] omap_hsmmc 481d8000.mmc: MMC start dma failure [ 3177.580859] mmcblk0: unknown error -1 sending read/write command, card status 0x900 [ 3177.591600] BTRFS error (device mmcblk0p6): bdev /dev/mmcblk0p6 errs: wr 3, rd 0, flush 0, corrupt 0, gen 0 [ 3177.694108] BTRFS: error (device mmcblk0p6) in btrfs_commit_transaction:2124: errno=-5 IO failure (Error while writing out transaction) [ 3177.706442] BTRFS info (device mmcblk0p6): forced readonly [ 3177.712009] BTRFS warning (device mmcblk0p6): Skipping commit of aborted transaction. [ 3177.719873] ------------[ cut here ]------------ [ 3177.724554] WARNING: CPU: 0 PID: 551 at /yocto/resin-board/build/tmp/work-shared/beaglebone/kernel-source/fs/btrfs/transaction.c:1746 btrfs_commit_transaction+0xa44/0xd60() [ 3177.740026] BTRFS: Transaction aborted (error -5) [ 3177.740034] Modules linked in: ipt_REJECT nf_reject_ipv4 br_netfilter xt_connmark iptable_mangle bnep bluetooth snd_soc_simple_card brcmfmac brcmutil cfg80211 omap_rng tilcdc rng_core rfkill snd_soc_davinci_mcasp snd_soc_edma spi_omap2_mcspi uio_pdrv_genirq uio sch_fq_codel [ 3177.764601] CPU: 0 PID: 551 Comm: btrfs-transacti Not tainted 4.4.9+ #1 [ 3177.771242] Hardware name: Generic AM33XX (Flattened Device Tree) [ 3177.777391] from [ 3177.785178] from [ 3177.792440] from [ 3177.800569] from [ 3177.809309] from [ 3177.818574] from [ 3177.828018] from [ 3177.835893] from [ 3177.843184] ---[ end trace 4d2d5d7e1314f23f ]--- [ 3177.847825] BTRFS: error (device mmcblk0p6) in cleanup_transaction:1746: errno=-5 IO failure [ 3177.856325] BTRFS info (device mmcblk0p6): delayed_refs has NO entry [ 3178.080128] BTRFS info (device mmcblk0p6): delayed_refs has NO entry

And in the device log:

Failed to download application 'registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0' due to 'Error pulling image (latest) from registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0, failed to register layer: rename /var/lib/docker/image/btrfs/layerdb/tmp/layer-218105302 /var/lib/docker/image/btrfs/layerdb/sha256/eb6c11b92c040eb052349ce00186d8d2509662ff4fb44be1a415e7dcdd2a13ff: directory not empty' 01.09.16 09:39:41 [+0300] Downloading application 'registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0' 01.09.16 09:46:06 [+0300] Failed to download application 'registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0' due to 'Error pulling image (latest) from registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0, failed to register layer: rename /var/lib/docker/image/btrfs/layerdb/tmp/layer-612867751 /var/lib/docker/image/btrfs/layerdb/sha256/eb6c11b92c040eb052349ce00186d8d2509662ff4fb44be1a415e7dcdd2a13ff: directory not empty'

floion commented 8 years ago

The exact problem in the device log was:

01.09.16 09:06:59 [+0300] Failed to install application 'registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0' due to 'chown /var/lib/docker/btrfs/subvolumes: read-only file system ' 01.09.16 09:06:59 [+0300] Failed to update application 'registry.resinstaging.io/beaglebone/812e037e4caa77e48e05bd8f8e6c14e18b3f04d0' due to 'chown /var/lib/docker/btrfs/subvolumes: read-only file system '

The above issue with the rename is after a reboot when btrfs is rw as it should be and is tries to redownload the app

agherzan commented 8 years ago

Looks very similar to what @shaunmulligan saw a couple of days ago. Seems like the btrfs partition gets mounted ro.

floion commented 8 years ago

Is there an issue already opened on this? Where was he experiencing it? Staging or production? What host OS version?

The latest errors I have pasted today have been on staging, host OS 1.11.0

shaunmulligan commented 8 years ago

@floion this is the issue we had previously: https://github.com/resin-io/hq/issues/295