Troubleshooting BeagleBone Green Bluetooth

Hi,

I’m using a Beaglebone Green Wireless as a Bluetooth reader (2.47.1+rev2). It scans for BLE advertisements, parses the payload and sends the data to the cloud.

It works for ~2 days, but then the console output & cloud upload stop despite the fact that the app is still running.

The same code running on RPis 4s and 3s doesn’t have this issue. Some of them have been uploading for >3 weeks.

What is the best way to troubleshoot this? I looked at the logs, but they are largely empty (but I also don’t know where to look).

Thanks!

Hi there, the first thing to try, would be to run diagnostics on the device (from the dashboard) to check for all the obvious things. Ideally, run the diagnostics when the device is fresh and hopefully just around/before the time it fails. Hopefully it’s something simple like a hardware issue and we can take it from there…

ab77, thanks for your fast reply!

I ran the device diagnostics on the device not working, but found no errors. I also browsed over the (very extensive) log output from Device Diagnostics & Supervisor state, but could find anything wrong.

I do not think it is a hardware issue, because when I reboot the device everything will start working for ~2 days before getting into the same funky state.

No worries, I feel like the next step would be to check your memory footprint over time, since your board only has 512MB of memory. You could monitor it periodically using something like free -m to give an indication of available memory over time. OoM situations could certainly cause the behaviour like you are describing.

Sure. Will do. Free -m on the funky beaglebone shows:

             total       used       free     shared    buffers     cached
Mem:        497660     449304      48356      37756       5500     104388
-/+ buffers/cache:     339416     158244
Swap:            0          0          0

This is the output from top:

  783     1 root     S     997m 205%   2% /usr/bin/balenad --experimental --log-d
   91     2 root     SW       0   0%   2% [irq/32-44e0b000]
32048     2 root     IW       0   0%   2% [kworker/0:0]
  637     2 root     SW       0   0%   1% [irq/59-wl18xx]
  831   783 root     S     901m 185%   1% balena-engine-containerd --config /var/
 1268  1251 root     S     783m 161%   0% /usr/src/app/scout -i 2 -stats
28535     1 openvpn  S     5204   1%   0% /usr/sbin/openvpn --writepid /run/openv
 1667  1648 root     S     154m  32%   0% node /usr/src/app/dist/app.js
  770     1 root     S    70136  14%   0% /usr/sbin/NetworkManager --no-daemon

I omitted the other processes in the ~1% range. I was not able to find out the actual amount of used RAM of my ‘scout’ process except for what I saw in /proc/{PID}/smaps: ~130kB.

These are the initial values on a freshly booted BBG:

             total       used       free     shared    buffers     cached
Mem:        497660     393516     104144      21348      11140     203024
-/+ buffers/cache:     179352     318308
Swap:            0          0          0
  PID  PPID USER     STAT   VSZ %VSZ %CPU COMMAND
   75     2 root     IW       0   0%   2% [kworker/0:3]
   91     2 root     SW       0   0%   2% [irq/32-44e0b000]
  876     1 root     S     941m 194%   2% /usr/bin/balenad --experimental --log-d
  734     2 root     SW       0   0%   2% [irq/59-wl18xx]
  930   876 root     S     901m 185%   1% balena-engine-containerd --config /var/
 6463  6446 root     S     782m 161%   1% /usr/src/app/scout -i 2 -stats
 1559  1541 root     S     149m  31%   1% node /usr/src/app/dist/app.js

BTW, terrific project. I really love how easy it is to run apps & manage my fleet!

Hi

Some ideas on how we could go about debugging this -

  • The amount of RAM looks fine to me (although Pi3 has twice the amount than the BBG) - since we still have ~50MB and that should be good enough for most cases. Do you have one of the higher RAM versions of Beaglebone around? Maybe its a good idea to check if this works without a problem on those.
  • One other thing that is worth checking is the version of the bluez stack on both the Pi and the Beaglebone. If they are different, maybe it’s worth checking out if something has changed recently that might have an effect on this.
  • It would also help if you periodically wrote the output of the free command to a log file, that we can access later.

Thanks for the suggestions!
I was able to check out a few things:

  • The Bluez stack is 5.50 across all deployments (/usr/libexec/bluetooth/bluetoothd -v) and versions I’m running. The container runs a Go app, which uses GATT not relying on other external libs.
  • The BBGW were also disconnecting from the wireless network every once in a while. So I moved one closer to the Wifi router to see if the disconnects lead to an out-of-memory exception. My Go app only buffers 100 values in memory before I block my acquisition, but maybe the other daemons consume more memory when not connected.
  • My cloud deployments run on distroless containers. I wasn’t able to find one for Balena, but switching to Alpine Linux freed up some more memory now hovering at 202MB.

I will start collecting memory metrics ASAP. Please let me know if you have other ideas I can try.

I’m convinced now that this is a problem with the OS, chipset or bluetooth stack:

  • Changed to a more popular bluetooth golang lib, which uses the DBus interface directly.
  • Implemented a dead man switch to restart the container in case I have not seen any bluetooth devices for the last 10s (I usually see >50) while I’m scanning.
  • There is >100MB of available RAM.

After a container restart, the container still doesn’t see any bluetooth devices. This happens usually after ~2 days and can only be fixed by restarting the entire board.

So at this point, I pretty much have to abandon Balena unless someone has other ideas on how to address this issue.

Hi @enachb and welcome to our forums! I like your idea about the dead man switch. Can you share your dmesg logs, I am wondering if something enters sleep mode.

And since you get the same behaviour on balenaOS and Alpine then we can rule out the hypothesis that the issue is the OS maybe?

Mbalamat,

Here are the dmesg logs since the reboot:

[    0.000000] Linux version 4.14.53+ (oe-user@oe-host) (gcc version 8.2.0 (GCC)) #1 SMP PREEMPT Thu Mar 12 08:44:21 UTC 2020
[    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] Memory policy: Data cache writeback
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 48 MiB at 0x9c800000
[    0.000000] On node 0 totalpages: 130560
[    0.000000] free_area_init_node: node 0, pgdat c19d7540, node_mem_map df961000
[    0.000000]   Normal zone: 1148 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] random: get_random_bytes called from start_kernel+0xac/0x45c with crng_init=0
[    0.000000] percpu: Embedded 18 pages/cpu @df928000 s41612 r8192 d23924 u73728
[    0.000000] pcpu-alloc: s41612 r8192 d23924 u73728 alloc=18*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 129412
[    0.000000] Kernel command line: console=ttyO0,115200n8 root=PARTUUID=1bc5ffe8-02 ro rootfstype=ext4 rootwait console=null quiet splash vt.global_cursor_default=0 consoleblank=0
[    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: 441340K/522240K available (12288K kernel code, 1053K rwdata, 4204K rodata, 7168K init, 655K bss, 31748K reserved, 49152K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xe0000000 - 0xff800000   ( 504 MB)
                   lowmem  : 0xc0000000 - 0xdfe00000   ( 510 MB)
                   pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                   modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                     .text : 0xc0008000 - 0xc0d00000   (13280 kB)
                     .init : 0xc1200000 - 0xc1900000   (7168 kB)
                     .data : 0xc1900000 - 0xc1a07658   (1054 kB)
                      .bss : 0xc1a108e4 - 0xc1ab47a4   ( 656 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] ftrace: allocating 40355 entries in 119 pages
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000]  RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
[    0.000000]  Tasks RCU enabled.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 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.000032] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000041] OMAP clocksource: timer1 at 24000000 Hz
[    0.000775] timer_probe: no matching timers found
[    0.000997] Console: colour dummy device 80x30
[    0.001023] Calibrating delay loop... 995.32 BogoMIPS (lpj=1990656)
[    0.046928] pid_max: default: 32768 minimum: 301
[    0.047191] Security Framework initialized
[    0.047205] Yama: becoming mindful.
[    0.047244] AppArmor: AppArmor disabled by boot time parameter
[    0.047439] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.047453] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.048473] CPU: Testing write buffer coherency: ok
[    0.048965] CPU0: thread -1, cpu 0, socket -1, mpidr 0
[    0.063037] Setting up static identity map for 0x80100000 - 0x80100060
[    0.070947] Hierarchical SRCU implementation.
[    0.082871] EFI services will not be available.
[    0.090953] smp: Bringing up secondary CPUs ...
[    0.090968] smp: Brought up 1 node, 1 CPU
[    0.090979] SMP: Total of 1 processors activated (995.32 BogoMIPS).
[    0.090986] CPU: All CPU(s) started in SVC mode.
[    0.092626] devtmpfs: initialized
[    0.111281] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.111772] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.111798] futex hash table entries: 256 (order: 2, 16384 bytes)
[    0.115793] pinctrl core: initialized pinctrl subsystem
[    0.116616] DMI not present or invalid.
[    0.117047] NET: Registered protocol family 16
[    0.120214] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.146432] omap_hwmod: debugss: _wait_target_disable failed
[    0.187660] cpuidle: using governor menu
[    0.193675] OMAP GPIO hardware version 0.1
[    0.196599] GPIO line 112 (MCASP0_AXR0) hogged as output/low
[    0.206672] No ATAGs?
[    0.206689] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.207113] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[    0.207124] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.238312] edma 49000000.edma: TI EDMA DMA engine driver
[    0.242262] SCSI subsystem initialized
[    0.243111] libata version 3.00 loaded.
[    0.243445] usbcore: registered new interface driver usbfs
[    0.243502] usbcore: registered new interface driver hub
[    0.243619] usbcore: registered new device driver usb
[    0.244209] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[    0.245645] omap_i2c 4819c000.i2c: bus 2 rev0.11 at 100 kHz
[    0.245910] media: Linux media interface: v0.10
[    0.245981] Linux video capture interface: v2.00
[    0.246131] pps_core: LinuxPPS API ver. 1 registered
[    0.246138] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.246159] PTP clock support registered
[    0.246297] dmi: Firmware registration failed.
[    0.246750] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[    0.251268] Advanced Linux Sound Architecture Driver Initialized.
[    0.251964] NetLabel: Initializing
[    0.251974] NetLabel:  domain hash size = 128
[    0.251979] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.252063] NetLabel:  unlabeled traffic allowed by default
[    0.255418] clocksource: Switched to clocksource timer1
[    0.377739] VFS: Disk quotas dquot_6.6.0
[    0.377851] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.389973] NET: Registered protocol family 2
[    0.390851] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    0.390897] TCP bind hash table entries: 4096 (order: 3, 32768 bytes)
[    0.390956] TCP: Hash tables configured (established 4096 bind 4096)
[    0.391067] UDP hash table entries: 256 (order: 1, 8192 bytes)
[    0.391089] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
[    0.391298] NET: Registered protocol family 1
[    0.400320] RPC: Registered named UNIX socket transport module.
[    0.400330] RPC: Registered udp transport module.
[    0.400335] RPC: Registered tcp transport module.
[    0.400340] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.494694] hw perfevents: no interrupt-affinity property for /pmu, guessing.
[    0.494940] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    0.496876] audit: initializing netlink subsys (disabled)
[    0.498086] audit: type=2000 audit(0.496:1): state=initialized audit_enabled=0 res=1
[    0.498216] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    0.504651] zbud: loaded
[    0.511849] NFS: Registering the id_resolver key type
[    0.511909] Key type id_resolver registered
[    0.511915] Key type id_legacy registered
[    0.511933] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.512282] fuse init (API version 7.26)
[    0.513865] aufs 4.14-20180702
[    0.522332] Key type asymmetric registered
[    0.522347] Asymmetric key parser 'x509' registered
[    0.522479] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 244)
[    0.526806] io scheduler noop registered
[    0.526817] io scheduler deadline registered
[    0.527212] io scheduler cfq registered (default)
[    0.527223] io scheduler mq-deadline registered
[    0.529085] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    0.530205] gpio-of-helper ocp:cape-universal: ready
[    0.532699] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[    0.534318] omap_uart 44e09000.serial: no wakeirq for uart0
[    0.534553] 44e09000.serial: ttyO0 at MMIO 0x44e09000 (irq = 30, base_baud = 3000000) is a OMAP UART0
[    0.551712] console [ttyO0] enabled
[    0.552641] omap_uart 481a6000.serial: no wakeirq for uart3
[    0.552825] 481a6000.serial: ttyO3 at MMIO 0x481a6000 (irq = 31, base_baud = 3000000) is a OMAP UART3
[    0.554802] omap_rng 48310000.rng: Random Number Generator ver. 20
[    0.555943] [drm] Initialized vgem 1.0.0 20120112 for virtual device on minor 0
[    0.556047] usbcore: registered new interface driver udl
[    0.560179] at24 2-0054: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    0.560468] at24 2-0055: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    0.560701] at24 2-0056: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    0.560909] at24 2-0057: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    0.564182] libphy: Fixed MDIO Bus: probed
[    0.565035] tun: Universal TUN/TAP device driver, 1.6
[    0.565374] CAN device driver interface
[    0.567000] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.567036] ehci-platform: EHCI generic platform driver
[    0.567210] ehci-omap: OMAP-EHCI Host Controller driver
[    0.567911] usbcore: registered new interface driver usb-storage
[    0.570302] am335x-phy-driver 47401300.usb-phy: 47401300.usb-phy supply vcc not found, using dummy regulator
[    0.573123] am335x-phy-driver 47401b00.usb-phy: 47401b00.usb-phy supply vcc not found, using dummy regulator
[    0.577250] musb-hdrc musb-hdrc.1: MUSB HDRC host driver
[    0.577290] musb-hdrc musb-hdrc.1: new USB bus registered, assigned bus number 1
[    0.577601] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.577613] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.577621] usb usb1: Product: MUSB HDRC host driver
[    0.577629] usb usb1: Manufacturer: Linux 4.14.53+ musb-hcd
[    0.577636] usb usb1: SerialNumber: musb-hdrc.1
[    0.578472] hub 1-0:1.0: USB hub found
[    0.578537] hub 1-0:1.0: 1 port detected
[    0.589647] omap_rtc 44e3e000.rtc: registered as rtc0
[    0.590715] i2c /dev entries driver
[    0.593503] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    0.593934] softdog: initialized. soft_noboot=0 soft_margin=60 sec soft_panic=0 (nowayout=0)
[    0.595066] cpuidle: enable-method property 'ti,am3352' found operations
[    0.595688] sdhci: Secure Digital Host Controller Interface driver
[    0.595696] sdhci: Copyright(c) Pierre Ossman
[    0.596154] omap_hsmmc 48060000.mmc: Got CD GPIO
[    0.725282] mmc1: new high speed MMC card at address 0001
[    0.726201] mmcblk1: mmc1:0001 Q2J54A 3.64 GiB 
[    0.726634] mmcblk1boot0: mmc1:0001 Q2J54A partition 1 2.00 MiB
[    0.727006] mmcblk1boot1: mmc1:0001 Q2J54A partition 2 2.00 MiB
[    0.727365] mmcblk1rpmb: mmc1:0001 Q2J54A partition 3 512 KiB
[    0.730155]  mmcblk1: p1 p2 p3 p4 < p5 p6 >
[    0.795831] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.797581] ledtrig-cpu: registered to indicate activity on CPUs
[    0.799210] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
[    0.801563] omap-aes 53500000.aes: will run requests pump with realtime priority
[    0.802232] omap_hsmmc 47810000.mmc: card claims to support voltages below defined range
[    0.804000] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[    0.806263] random: fast init done
[    0.807281] hidraw: raw HID events driver (C) Jiri Kosina
[    0.808355] usbcore: registered new interface driver usbhid
[    0.808363] usbhid: USB HID core driver
[    0.808797] remoteproc remoteproc0: wkup_m3 is available
[    0.813119] nf_conntrack version 0.5.0 (8192 buckets, 32768 max)
[    0.813778] wireguard: WireGuard 0.0.20180625 loaded. See www.wireguard.com for information.
[    0.813787] wireguard: Copyright (C) 2015-2018 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[    0.814235] ip_tables: (C) 2000-2006 Netfilter Core Team
[    0.818418] mmc2: new high speed SDIO card at address 0001
[    0.820256] NET: Registered protocol family 10
[    0.825884] Segment Routing with IPv6
[    0.825968] mip6: Mobile IPv6
[    0.825984] NET: Registered protocol family 17
[    0.826056] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    0.826063] can: controller area network core (rev 20170425 abi 9)
[    0.826162] NET: Registered protocol family 29
[    0.826259] Key type dns_resolver registered
[    0.826266] mpls_gso: MPLS GSO support
[    0.826276] NET: Registered protocol family 44
[    0.826595] omap_voltage_late_init: Voltage driver support not added
[    0.833775] ThumbEE CPU extension supported.
[    0.833799] Registering SWP/SWPB emulation handler
[    0.834782] registered taskstats version 1
[    0.834923] zswap: loaded using pool lzo/zbud
[    0.836099] ima: No TPM chip found, activating TPM-bypass! (rc=-19)
[    0.836128] ima: Allocated hash algorithm: sha256
[    0.881193] input: tps65217_pwr_but as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0024/tps65217-pwrbutton/input/input0
[    0.881803] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[    0.882283] at24 0-0050: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[    0.882390] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    0.883944] remoteproc remoteproc0: powering up wkup_m3
[    0.883967] remoteproc remoteproc0: Booting fw image am335x-pm-firmware.elf, size 217168
[    0.884222] remoteproc remoteproc0: remote processor wkup_m3 is now up
[    0.884245] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x193
[    0.889954] bone_capemgr bone_capemgr: Baseboard: 'A335BNLT,GW1A,BBGW19120259'
[    0.889984] bone_capemgr bone_capemgr: compatible-baseboard=ti,beaglebone-black - #slots=4
[    0.916511] bone_capemgr bone_capemgr: slot #0: No cape found
[    0.943679] bone_capemgr bone_capemgr: slot #1: No cape found
[    0.972525] bone_capemgr bone_capemgr: slot #2: No cape found
[    0.987447] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    0.999491] bone_capemgr bone_capemgr: slot #3: No cape found
[    0.999569] bone_capemgr bone_capemgr: initialized OK.
[    1.006685] omap_rtc 44e3e000.rtc: setting system clock to 2000-01-01 00:00:01 UTC (946684801)
[    1.006705] of_cfs_init
[    1.006851] of_cfs_init: OK
[    1.007705] wlan-en-regulator: disabling
[    1.007725] ALSA device list:
[    1.007731]   No soundcards found.
[    1.019088] Freeing unused kernel memory: 7168K
[    1.137262] usb 1-1: New USB device found, idVendor=05e3, idProduct=0610
[    1.137279] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.137287] usb 1-1: Product: USB2.0 Hub
[    1.138392] hub 1-1:1.0: USB hub found
[    1.138761] hub 1-1:1.0: 4 ports detected
[    3.529188] CP437: Invalid argument
[    3.760099] fsck.fat 4.1 (2017-01-24)
               0x25: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
                Automatically removing dirty bit.
               Performing changes.
               /dev/disk/by-label/resin-boot: 17 files, 292/20431 clusters
[    3.810106] resin-rootA: recovering journal
[    3.871895] resin-rootA: clean, 7724/39936 files, 246827/319488 blocks

[    3.930951] resin-rootB: clean, 11/39936 files, 15349/319488 blocks

[    3.973391] resin-state: recovering journal
[    4.022898] resin-state: clean, 67/5136 files, 1902/20480 blocks

[    4.808348] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[    4.966543] EXT4-fs (mmcblk1p5): mounted filesystem with ordered data mode. Opts: (null)
[    5.688210] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[    5.715976] aufs au_opts_verify:1622:init[1]: dirperm1 breaks the protection by the permission bits on the lower branch
[    6.017767] systemd[1]: System time before build time, advancing clock.
[    9.997166] EXT4-fs (mmcblk1p6): mounted filesystem with ordered data mode. Opts: (null)
[   12.739593] random: crng init done
[   18.408769] wlcore: wl18xx HW: 183x or 180x, PG 2.2 (ROM 0x11)
[   18.421295] wlcore: WARNING Detected unconfigured mac address in nvs, derive from fuse instead.

[   18.421310] wlcore: WARNING This default nvs file can be removed from the file system

[   18.445085] wlcore: loaded
[   24.846259] Bluetooth: Core ver 2.22
[   24.846489] NET: Registered protocol family 31
[   24.846499] Bluetooth: HCI device and connection manager initialized
[   24.846530] Bluetooth: HCI socket layer initialized
[   24.846546] Bluetooth: L2CAP socket layer initialized
[   24.846598] Bluetooth: SCO socket layer initialized
[   24.890989] Bluetooth: HCI UART driver ver 2.3
[   24.891009] Bluetooth: HCI UART protocol H4 registered
[   24.897100] Bluetooth: HCI UART protocol LL registered
[   24.897116] Bluetooth: HCI UART protocol ATH3K registered
[   24.897122] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   24.897128] Bluetooth: HCI UART protocol QCA registered
[   26.273689] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   26.349964] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   26.349979] Bluetooth: BNEP filters: protocol multicast
[   26.350010] Bluetooth: BNEP socket layer initialized
[   26.745222] wlcore: PHY firmware version: Rev 8.2.0.0.242
[   26.848728] wlcore: firmware booted (Rev 8.9.0.0.79)
[   26.867820] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   26.879706] wlcore: down
[   27.344045] wlcore: PHY firmware version: Rev 8.2.0.0.242
[   27.453186] wlcore: firmware booted (Rev 8.9.0.0.79)
[   27.481785] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   28.324900] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   30.123904] Bridge firewalling registered
[   30.842298] Initializing XFRM netlink socket
[   30.923850] Netfilter messages via NETLINK v0.30.
[   30.932412] ctnetlink v0.93: registering with nfnetlink.
[   31.644832] IPv6: ADDRCONF(NETDEV_UP): balena0: link is not ready
[   32.298625] IPv6: ADDRCONF(NETDEV_UP): br-b0a72ee3d446: link is not ready
[   32.985820] wlcore: down
[   33.492464] wlcore: PHY firmware version: Rev 8.2.0.0.242
[   33.698438] wlcore: firmware booted (Rev 8.9.0.0.79)
[   33.721302] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   34.180866] IPv6: ADDRCONF(NETDEV_UP): supervisor0: link is not ready
[   38.712139] wlan0: authenticate with 7c:d9:5c:95:52:ab
[   38.724661] wlan0: send auth to 7c:d9:5c:95:52:ab (try 1/3)
[   38.830900] wlan0: authenticated
[   38.835721] wlan0: associate with 7c:d9:5c:95:52:ab (try 1/3)
[   38.842422] wlan0: RX AssocResp from 7c:d9:5c:95:52:ab (capab=0x1011 status=0 aid=9)
[   38.862786] wlan0: associated
[   39.171250] wlan0: Limiting TX power to 30 (30 - 0) dBm as advertised by 7c:d9:5c:95:52:ab
[   39.175561] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   39.193589] wlcore: Association completed.
[   49.399171] udevd[29]: starting version 3.2.9
[   49.544505] udevd[30]: starting eudev-3.2.9
[   51.775392] ip6_tables: (C) 2000-2006 Netfilter Core Team
[  220.849268] udevd[29]: starting version 3.2.9
[  220.910099] udevd[30]: starting eudev-3.2.9
[87233.637999] udevd[29]: starting version 3.2.9
[87233.692183] udevd[30]: starting eudev-3.2.9
[144668.427427] udevd[28]: starting version 3.2.9
[144668.488996] udevd[29]: starting eudev-3.2.9
[144712.330430] udevd[29]: starting version 3.2.9

Thanks for helping!

I only tested the container itself running on Debian or Alpine. So far I have not tried the same code on bare metal (I could it would just take ~2 days before we’d know if it failed the same way).

Can you clarify the steps for your test? Were all your tests on balenaOS and you changed the base images on your dockerfile to debian and alpine or something else? In general it would be great if we had the dmesg logs at around the time the issue occurs. eg when your dead man switch is to be triggered grab the dmesg logs maybe?

Answers to your questions:

  • My golang bluetooth scanning app works fine on a bare metal Linux desktop running Debian with a Bluetooth USB dongle.
  • An RPi 4 part in the same Balena Cloud App running the same container seems to be also unaffected by this issue.
  • I started out with the RPi, but need better antennas for my application. Hence the BBG Wireless.
  • All tests switching OSes were done on a BalenaOS host. I just tried different container OSes (Debian & Alpine) to see if that makes a difference (the inital hunch was a out-of-memory issue).
  • The dmesg I posted were from the time the board booted until the issues appeared. The “starting version” & “starting eudev” lines are repeated whenever the container restarts due to my dead man switch killing the container. So this is all the dmesg output I have.

@enachb can you get the same logs from dmesg but with -T so it’s dmesg -T in order to verify that the timestamps of the logs match the dates that you experienced the issue?

Your first test confirms that your app works in general. The second also confirms that your app is running on a PI4 running balenaOS. Switching base images Alpine <> Debian doesn’t make that much of a difference since you are changing userspace libs. Communicating with the bt module is done via dbus, right? If you do an experiment on the same board (beaglebone green) running your application on another linux disrto other than balenaOS, we will know that the problem lies on the board(its firmware maybe) if bluetooth scanning stops working after 2 days, or in case it works we will know that’s probably something with balenaOS.

Sure! The dates line up with my observations. There aren’t any log entries that I can see around the time the restarts start to happen (repeated udev* lines) due to my dead man switch.

[Mon Apr 20 21:10:59 2020] Booting Linux on physical CPU 0x0
[Mon Apr 20 21:10:59 2020] Linux version 4.14.53+ (oe-user@oe-host) (gcc version 8.2.0 (GCC)) #1 SMP PREEMPT Thu Mar 12 08:44:21 UTC 2020
[Mon Apr 20 21:10:59 2020] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[Mon Apr 20 21:10:59 2020] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[Mon Apr 20 21:10:59 2020] OF: fdt: Machine model: TI AM335x BeagleBone Green Wireless
[Mon Apr 20 21:10:59 2020] Memory policy: Data cache writeback
[Mon Apr 20 21:10:59 2020] efi: Getting EFI parameters from FDT:
[Mon Apr 20 21:10:59 2020] efi: UEFI not found.
[Mon Apr 20 21:10:59 2020] cma: Reserved 48 MiB at 0x9c800000
[Mon Apr 20 21:10:59 2020] On node 0 totalpages: 130560
[Mon Apr 20 21:10:59 2020] free_area_init_node: node 0, pgdat c19d7540, node_mem_map df961000
[Mon Apr 20 21:10:59 2020]   Normal zone: 1148 pages used for memmap
[Mon Apr 20 21:10:59 2020]   Normal zone: 0 pages reserved
[Mon Apr 20 21:10:59 2020]   Normal zone: 130560 pages, LIFO batch:31
[Mon Apr 20 21:10:59 2020] CPU: All CPU(s) started in SVC mode.
[Mon Apr 20 21:10:59 2020] AM335X ES2.1 (sgx neon)
[Mon Apr 20 21:10:59 2020] random: get_random_bytes called from start_kernel+0xac/0x45c with crng_init=0
[Mon Apr 20 21:10:59 2020] percpu: Embedded 18 pages/cpu @df928000 s41612 r8192 d23924 u73728
[Mon Apr 20 21:10:59 2020] pcpu-alloc: s41612 r8192 d23924 u73728 alloc=18*4096
[Mon Apr 20 21:10:59 2020] pcpu-alloc: [0] 0 
[Mon Apr 20 21:10:59 2020] Built 1 zonelists, mobility grouping on.  Total pages: 129412
[Mon Apr 20 21:10:59 2020] Kernel command line: console=ttyO0,115200n8 root=PARTUUID=1bc5ffe8-02 ro rootfstype=ext4 rootwait console=null quiet splash vt.global_cursor_default=0 consoleblank=0
[Mon Apr 20 21:10:59 2020] PID hash table entries: 2048 (order: 1, 8192 bytes)
[Mon Apr 20 21:10:59 2020] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[Mon Apr 20 21:10:59 2020] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[Mon Apr 20 21:10:59 2020] Memory: 441340K/522240K available (12288K kernel code, 1053K rwdata, 4204K rodata, 7168K init, 655K bss, 31748K reserved, 49152K cma-reserved, 0K highmem)
[Mon Apr 20 21:10:59 2020] Virtual kernel memory layout:
                               vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                               fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                               vmalloc : 0xe0000000 - 0xff800000   ( 504 MB)
                               lowmem  : 0xc0000000 - 0xdfe00000   ( 510 MB)
                               pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
                               modules : 0xbf000000 - 0xbfe00000   (  14 MB)
                                 .text : 0xc0008000 - 0xc0d00000   (13280 kB)
                                 .init : 0xc1200000 - 0xc1900000   (7168 kB)
                                 .data : 0xc1900000 - 0xc1a07658   (1054 kB)
                                  .bss : 0xc1a108e4 - 0xc1ab47a4   ( 656 kB)
[Mon Apr 20 21:10:59 2020] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[Mon Apr 20 21:10:59 2020] ftrace: allocating 40355 entries in 119 pages
[Mon Apr 20 21:10:59 2020] Preemptible hierarchical RCU implementation.
[Mon Apr 20 21:10:59 2020]      RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
[Mon Apr 20 21:10:59 2020]      Tasks RCU enabled.
[Mon Apr 20 21:10:59 2020] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[Mon Apr 20 21:10:59 2020] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[Mon Apr 20 21:10:59 2020] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[Mon Apr 20 21:10:59 2020] OMAP clockevent source: timer2 at 24000000 Hz
[Mon Apr 20 21:10:59 2020] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[Mon Apr 20 21:10:59 2020] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[Mon Apr 20 21:10:59 2020] OMAP clocksource: timer1 at 24000000 Hz
[Mon Apr 20 21:10:59 2020] timer_probe: no matching timers found
[Mon Apr 20 21:10:59 2020] Console: colour dummy device 80x30
[Mon Apr 20 21:10:59 2020] Calibrating delay loop... 995.32 BogoMIPS (lpj=1990656)
[Mon Apr 20 21:10:59 2020] pid_max: default: 32768 minimum: 301
[Mon Apr 20 21:10:59 2020] Security Framework initialized
[Mon Apr 20 21:10:59 2020] Yama: becoming mindful.
[Mon Apr 20 21:10:59 2020] AppArmor: AppArmor disabled by boot time parameter
[Mon Apr 20 21:10:59 2020] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[Mon Apr 20 21:10:59 2020] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[Mon Apr 20 21:10:59 2020] CPU: Testing write buffer coherency: ok
[Mon Apr 20 21:10:59 2020] CPU0: thread -1, cpu 0, socket -1, mpidr 0
[Mon Apr 20 21:10:59 2020] Setting up static identity map for 0x80100000 - 0x80100060
[Mon Apr 20 21:10:59 2020] Hierarchical SRCU implementation.
[Mon Apr 20 21:10:59 2020] EFI services will not be available.
[Mon Apr 20 21:10:59 2020] smp: Bringing up secondary CPUs ...
[Mon Apr 20 21:10:59 2020] smp: Brought up 1 node, 1 CPU
[Mon Apr 20 21:10:59 2020] SMP: Total of 1 processors activated (995.32 BogoMIPS).
[Mon Apr 20 21:10:59 2020] CPU: All CPU(s) started in SVC mode.
[Mon Apr 20 21:10:59 2020] devtmpfs: initialized
[Mon Apr 20 21:10:59 2020] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[Mon Apr 20 21:10:59 2020] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[Mon Apr 20 21:10:59 2020] futex hash table entries: 256 (order: 2, 16384 bytes)
[Mon Apr 20 21:10:59 2020] pinctrl core: initialized pinctrl subsystem
[Mon Apr 20 21:10:59 2020] DMI not present or invalid.
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 16
[Mon Apr 20 21:10:59 2020] DMA: preallocated 256 KiB pool for atomic coherent allocations
[Mon Apr 20 21:10:59 2020] omap_hwmod: debugss: _wait_target_disable failed
[Mon Apr 20 21:10:59 2020] cpuidle: using governor menu
[Mon Apr 20 21:10:59 2020] OMAP GPIO hardware version 0.1
[Mon Apr 20 21:10:59 2020] GPIO line 112 (MCASP0_AXR0) hogged as output/low
[Mon Apr 20 21:10:59 2020] No ATAGs?
[Mon Apr 20 21:10:59 2020] hw-breakpoint: debug architecture 0x4 unsupported.
[Mon Apr 20 21:10:59 2020] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[Mon Apr 20 21:10:59 2020] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[Mon Apr 20 21:10:59 2020] edma 49000000.edma: TI EDMA DMA engine driver
[Mon Apr 20 21:10:59 2020] SCSI subsystem initialized
[Mon Apr 20 21:10:59 2020] libata version 3.00 loaded.
[Mon Apr 20 21:10:59 2020] usbcore: registered new interface driver usbfs
[Mon Apr 20 21:10:59 2020] usbcore: registered new interface driver hub
[Mon Apr 20 21:10:59 2020] usbcore: registered new device driver usb
[Mon Apr 20 21:10:59 2020] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[Mon Apr 20 21:10:59 2020] omap_i2c 4819c000.i2c: bus 2 rev0.11 at 100 kHz
[Mon Apr 20 21:10:59 2020] media: Linux media interface: v0.10
[Mon Apr 20 21:10:59 2020] Linux video capture interface: v2.00
[Mon Apr 20 21:10:59 2020] pps_core: LinuxPPS API ver. 1 registered
[Mon Apr 20 21:10:59 2020] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[Mon Apr 20 21:10:59 2020] PTP clock support registered
[Mon Apr 20 21:10:59 2020] dmi: Firmware registration failed.
[Mon Apr 20 21:10:59 2020] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400
[Mon Apr 20 21:10:59 2020] Advanced Linux Sound Architecture Driver Initialized.
[Mon Apr 20 21:10:59 2020] NetLabel: Initializing
[Mon Apr 20 21:10:59 2020] NetLabel:  domain hash size = 128
[Mon Apr 20 21:10:59 2020] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[Mon Apr 20 21:10:59 2020] NetLabel:  unlabeled traffic allowed by default
[Mon Apr 20 21:10:59 2020] clocksource: Switched to clocksource timer1
[Mon Apr 20 21:10:59 2020] VFS: Disk quotas dquot_6.6.0
[Mon Apr 20 21:10:59 2020] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 2
[Mon Apr 20 21:10:59 2020] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[Mon Apr 20 21:10:59 2020] TCP bind hash table entries: 4096 (order: 3, 32768 bytes)
[Mon Apr 20 21:10:59 2020] TCP: Hash tables configured (established 4096 bind 4096)
[Mon Apr 20 21:10:59 2020] UDP hash table entries: 256 (order: 1, 8192 bytes)
[Mon Apr 20 21:10:59 2020] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 1
[Mon Apr 20 21:10:59 2020] RPC: Registered named UNIX socket transport module.
[Mon Apr 20 21:10:59 2020] RPC: Registered udp transport module.
[Mon Apr 20 21:10:59 2020] RPC: Registered tcp transport module.
[Mon Apr 20 21:10:59 2020] RPC: Registered tcp NFSv4.1 backchannel transport module.
[Mon Apr 20 21:10:59 2020] hw perfevents: no interrupt-affinity property for /pmu, guessing.
[Mon Apr 20 21:10:59 2020] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[Mon Apr 20 21:10:59 2020] audit: initializing netlink subsys (disabled)
[Mon Apr 20 21:10:59 2020] audit: type=2000 audit(0.496:1): state=initialized audit_enabled=0 res=1
[Mon Apr 20 21:10:59 2020] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[Mon Apr 20 21:10:59 2020] zbud: loaded
[Mon Apr 20 21:10:59 2020] NFS: Registering the id_resolver key type
[Mon Apr 20 21:10:59 2020] Key type id_resolver registered
[Mon Apr 20 21:10:59 2020] Key type id_legacy registered
[Mon Apr 20 21:10:59 2020] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[Mon Apr 20 21:10:59 2020] fuse init (API version 7.26)
[Mon Apr 20 21:10:59 2020] aufs 4.14-20180702
[Mon Apr 20 21:10:59 2020] Key type asymmetric registered
[Mon Apr 20 21:10:59 2020] Asymmetric key parser 'x509' registered
[Mon Apr 20 21:10:59 2020] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 244)
[Mon Apr 20 21:10:59 2020] io scheduler noop registered
[Mon Apr 20 21:10:59 2020] io scheduler deadline registered
[Mon Apr 20 21:10:59 2020] io scheduler cfq registered (default)
[Mon Apr 20 21:10:59 2020] io scheduler mq-deadline registered
[Mon Apr 20 21:10:59 2020] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[Mon Apr 20 21:10:59 2020] gpio-of-helper ocp:cape-universal: ready
[Mon Apr 20 21:10:59 2020] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[Mon Apr 20 21:10:59 2020] omap_uart 44e09000.serial: no wakeirq for uart0
[Mon Apr 20 21:10:59 2020] 44e09000.serial: ttyO0 at MMIO 0x44e09000 (irq = 30, base_baud = 3000000) is a OMAP UART0
[Mon Apr 20 21:10:59 2020] console [ttyO0] enabled
[Mon Apr 20 21:10:59 2020] omap_uart 481a6000.serial: no wakeirq for uart3
[Mon Apr 20 21:10:59 2020] 481a6000.serial: ttyO3 at MMIO 0x481a6000 (irq = 31, base_baud = 3000000) is a OMAP UART3
[Mon Apr 20 21:10:59 2020] omap_rng 48310000.rng: Random Number Generator ver. 20
[Mon Apr 20 21:10:59 2020] [drm] Initialized vgem 1.0.0 20120112 for virtual device on minor 0
[Mon Apr 20 21:10:59 2020] usbcore: registered new interface driver udl
[Mon Apr 20 21:10:59 2020] at24 2-0054: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[Mon Apr 20 21:10:59 2020] at24 2-0055: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[Mon Apr 20 21:10:59 2020] at24 2-0056: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[Mon Apr 20 21:10:59 2020] at24 2-0057: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[Mon Apr 20 21:10:59 2020] libphy: Fixed MDIO Bus: probed
[Mon Apr 20 21:10:59 2020] tun: Universal TUN/TAP device driver, 1.6
[Mon Apr 20 21:10:59 2020] CAN device driver interface
[Mon Apr 20 21:10:59 2020] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[Mon Apr 20 21:10:59 2020] ehci-platform: EHCI generic platform driver
[Mon Apr 20 21:10:59 2020] ehci-omap: OMAP-EHCI Host Controller driver
[Mon Apr 20 21:10:59 2020] usbcore: registered new interface driver usb-storage
[Mon Apr 20 21:10:59 2020] am335x-phy-driver 47401300.usb-phy: 47401300.usb-phy supply vcc not found, using dummy regulator
[Mon Apr 20 21:10:59 2020] am335x-phy-driver 47401b00.usb-phy: 47401b00.usb-phy supply vcc not found, using dummy regulator
[Mon Apr 20 21:10:59 2020] musb-hdrc musb-hdrc.1: MUSB HDRC host driver
[Mon Apr 20 21:10:59 2020] musb-hdrc musb-hdrc.1: new USB bus registered, assigned bus number 1
[Mon Apr 20 21:10:59 2020] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[Mon Apr 20 21:10:59 2020] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[Mon Apr 20 21:10:59 2020] usb usb1: Product: MUSB HDRC host driver
[Mon Apr 20 21:10:59 2020] usb usb1: Manufacturer: Linux 4.14.53+ musb-hcd
[Mon Apr 20 21:10:59 2020] usb usb1: SerialNumber: musb-hdrc.1
[Mon Apr 20 21:10:59 2020] hub 1-0:1.0: USB hub found
[Mon Apr 20 21:10:59 2020] hub 1-0:1.0: 1 port detected
[Mon Apr 20 21:10:59 2020] omap_rtc 44e3e000.rtc: registered as rtc0
[Mon Apr 20 21:10:59 2020] i2c /dev entries driver
[Mon Apr 20 21:10:59 2020] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[Mon Apr 20 21:10:59 2020] softdog: initialized. soft_noboot=0 soft_margin=60 sec soft_panic=0 (nowayout=0)
[Mon Apr 20 21:10:59 2020] cpuidle: enable-method property 'ti,am3352' found operations
[Mon Apr 20 21:10:59 2020] sdhci: Secure Digital Host Controller Interface driver
[Mon Apr 20 21:10:59 2020] sdhci: Copyright(c) Pierre Ossman
[Mon Apr 20 21:10:59 2020] omap_hsmmc 48060000.mmc: Got CD GPIO
[Mon Apr 20 21:10:59 2020] mmc1: new high speed MMC card at address 0001
[Mon Apr 20 21:10:59 2020] mmcblk1: mmc1:0001 Q2J54A 3.64 GiB 
[Mon Apr 20 21:10:59 2020] mmcblk1boot0: mmc1:0001 Q2J54A partition 1 2.00 MiB
[Mon Apr 20 21:10:59 2020] mmcblk1boot1: mmc1:0001 Q2J54A partition 2 2.00 MiB
[Mon Apr 20 21:10:59 2020] mmcblk1rpmb: mmc1:0001 Q2J54A partition 3 512 KiB
[Mon Apr 20 21:10:59 2020]  mmcblk1: p1 p2 p3 p4 < p5 p6 >
[Mon Apr 20 21:10:59 2020] sdhci-pltfm: SDHCI platform and OF driver helper
[Mon Apr 20 21:10:59 2020] ledtrig-cpu: registered to indicate activity on CPUs
[Mon Apr 20 21:10:59 2020] omap-aes 53500000.aes: OMAP AES hw accel rev: 3.2
[Mon Apr 20 21:10:59 2020] omap-aes 53500000.aes: will run requests pump with realtime priority
[Mon Apr 20 21:10:59 2020] omap_hsmmc 47810000.mmc: card claims to support voltages below defined range
[Mon Apr 20 21:10:59 2020] omap-sham 53100000.sham: hw accel on OMAP rev 4.3
[Mon Apr 20 21:10:59 2020] random: fast init done
[Mon Apr 20 21:10:59 2020] hidraw: raw HID events driver (C) Jiri Kosina
[Mon Apr 20 21:10:59 2020] usbcore: registered new interface driver usbhid
[Mon Apr 20 21:10:59 2020] usbhid: USB HID core driver
[Mon Apr 20 21:10:59 2020] remoteproc remoteproc0: wkup_m3 is available
[Mon Apr 20 21:10:59 2020] nf_conntrack version 0.5.0 (8192 buckets, 32768 max)
[Mon Apr 20 21:10:59 2020] wireguard: WireGuard 0.0.20180625 loaded. See www.wireguard.com for information.
[Mon Apr 20 21:10:59 2020] wireguard: Copyright (C) 2015-2018 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[Mon Apr 20 21:10:59 2020] ip_tables: (C) 2000-2006 Netfilter Core Team
[Mon Apr 20 21:10:59 2020] mmc2: new high speed SDIO card at address 0001
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 10
[Mon Apr 20 21:10:59 2020] Segment Routing with IPv6
[Mon Apr 20 21:10:59 2020] mip6: Mobile IPv6
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 17
[Mon Apr 20 21:10:59 2020] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[Mon Apr 20 21:10:59 2020] can: controller area network core (rev 20170425 abi 9)
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 29
[Mon Apr 20 21:10:59 2020] Key type dns_resolver registered
[Mon Apr 20 21:10:59 2020] mpls_gso: MPLS GSO support
[Mon Apr 20 21:10:59 2020] NET: Registered protocol family 44
[Mon Apr 20 21:10:59 2020] omap_voltage_late_init: Voltage driver support not added
[Mon Apr 20 21:10:59 2020] ThumbEE CPU extension supported.
[Mon Apr 20 21:10:59 2020] Registering SWP/SWPB emulation handler
[Mon Apr 20 21:10:59 2020] registered taskstats version 1
[Mon Apr 20 21:10:59 2020] zswap: loaded using pool lzo/zbud
[Mon Apr 20 21:10:59 2020] ima: No TPM chip found, activating TPM-bypass! (rc=-19)
[Mon Apr 20 21:10:59 2020] ima: Allocated hash algorithm: sha256
[Mon Apr 20 21:10:59 2020] input: tps65217_pwr_but as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0024/tps65217-pwrbutton/input/input0
[Mon Apr 20 21:10:59 2020] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[Mon Apr 20 21:10:59 2020] at24 0-0050: 32768 byte 24c256 EEPROM, writable, 1 bytes/write
[Mon Apr 20 21:10:59 2020] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[Mon Apr 20 21:10:59 2020] remoteproc remoteproc0: powering up wkup_m3
[Mon Apr 20 21:10:59 2020] remoteproc remoteproc0: Booting fw image am335x-pm-firmware.elf, size 217168
[Mon Apr 20 21:10:59 2020] remoteproc remoteproc0: remote processor wkup_m3 is now up
[Mon Apr 20 21:10:59 2020] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x193
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: Baseboard: 'A335BNLT,GW1A,BBGW19120259'
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: compatible-baseboard=ti,beaglebone-black - #slots=4
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: slot #0: No cape found
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: slot #1: No cape found
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: slot #2: No cape found
[Mon Apr 20 21:10:59 2020] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: slot #3: No cape found
[Mon Apr 20 21:10:59 2020] bone_capemgr bone_capemgr: initialized OK.
[Mon Apr 20 21:11:00 2020] omap_rtc 44e3e000.rtc: setting system clock to 2000-01-01 00:00:01 UTC (946684801)
[Mon Apr 20 21:11:00 2020] of_cfs_init
[Mon Apr 20 21:11:00 2020] of_cfs_init: OK
[Mon Apr 20 21:11:00 2020] wlan-en-regulator: disabling
[Mon Apr 20 21:11:00 2020] ALSA device list:
[Mon Apr 20 21:11:00 2020]   No soundcards found.
[Mon Apr 20 21:11:00 2020] Freeing unused kernel memory: 7168K
[Mon Apr 20 21:11:00 2020] usb 1-1: New USB device found, idVendor=05e3, idProduct=0610
[Mon Apr 20 21:11:00 2020] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[Mon Apr 20 21:11:00 2020] usb 1-1: Product: USB2.0 Hub
[Mon Apr 20 21:11:00 2020] hub 1-1:1.0: USB hub found
[Mon Apr 20 21:11:00 2020] hub 1-1:1.0: 4 ports detected
[Mon Apr 20 21:11:02 2020] CP437: Invalid argument
[Mon Apr 20 21:11:02 2020] fsck.fat 4.1 (2017-01-24)
                           0x25: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
                            Automatically removing dirty bit.
                           Performing changes.
                           /dev/disk/by-label/resin-boot: 17 files, 292/20431 clusters
[Mon Apr 20 21:11:02 2020] resin-rootA: recovering journal
[Mon Apr 20 21:11:02 2020] resin-rootA: clean, 7724/39936 files, 246827/319488 blocks

[Mon Apr 20 21:11:02 2020] resin-rootB: clean, 11/39936 files, 15349/319488 blocks

[Mon Apr 20 21:11:02 2020] resin-state: recovering journal
[Mon Apr 20 21:11:03 2020] resin-state: clean, 67/5136 files, 1902/20480 blocks

[Mon Apr 20 21:11:03 2020] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[Mon Apr 20 21:11:03 2020] EXT4-fs (mmcblk1p5): mounted filesystem with ordered data mode. Opts: (null)
[Mon Apr 20 21:11:04 2020] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[Mon Apr 20 21:11:04 2020] aufs au_opts_verify:1622:init[1]: dirperm1 breaks the protection by the permission bits on the lower branch
[Mon Apr 20 21:11:05 2020] systemd[1]: System time before build time, advancing clock.
[Mon Apr 20 21:11:08 2020] EXT4-fs (mmcblk1p6): mounted filesystem with ordered data mode. Opts: (null)
[Mon Apr 20 21:11:11 2020] random: crng init done
[Mon Apr 20 21:11:17 2020] wlcore: wl18xx HW: 183x or 180x, PG 2.2 (ROM 0x11)
[Mon Apr 20 21:11:17 2020] wlcore: WARNING Detected unconfigured mac address in nvs, derive from fuse instead.

[Mon Apr 20 21:11:17 2020] wlcore: WARNING This default nvs file can be removed from the file system

[Mon Apr 20 21:11:17 2020] wlcore: loaded
[Mon Apr 20 21:11:23 2020] Bluetooth: Core ver 2.22
[Mon Apr 20 21:11:23 2020] NET: Registered protocol family 31
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI device and connection manager initialized
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI socket layer initialized
[Mon Apr 20 21:11:23 2020] Bluetooth: L2CAP socket layer initialized
[Mon Apr 20 21:11:23 2020] Bluetooth: SCO socket layer initialized
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI UART driver ver 2.3
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI UART protocol H4 registered
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI UART protocol LL registered
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI UART protocol ATH3K registered
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI UART protocol Three-wire (H5) registered
[Mon Apr 20 21:11:23 2020] Bluetooth: HCI UART protocol QCA registered
[Mon Apr 20 21:11:25 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Mon Apr 20 21:11:25 2020] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[Mon Apr 20 21:11:25 2020] Bluetooth: BNEP filters: protocol multicast
[Mon Apr 20 21:11:25 2020] Bluetooth: BNEP socket layer initialized
[Mon Apr 20 21:11:25 2020] wlcore: PHY firmware version: Rev 8.2.0.0.242
[Mon Apr 20 21:11:25 2020] wlcore: firmware booted (Rev 8.9.0.0.79)
[Mon Apr 20 21:11:25 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Mon Apr 20 21:11:25 2020] wlcore: down
[Mon Apr 20 21:11:26 2020] wlcore: PHY firmware version: Rev 8.2.0.0.242
[Mon Apr 20 21:11:26 2020] wlcore: firmware booted (Rev 8.9.0.0.79)
[Mon Apr 20 21:11:26 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Mon Apr 20 21:11:27 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Mon Apr 20 21:11:29 2020] Bridge firewalling registered
[Mon Apr 20 21:11:29 2020] Initializing XFRM netlink socket
[Mon Apr 20 21:11:29 2020] Netfilter messages via NETLINK v0.30.
[Mon Apr 20 21:11:29 2020] ctnetlink v0.93: registering with nfnetlink.
[Mon Apr 20 21:11:30 2020] IPv6: ADDRCONF(NETDEV_UP): balena0: link is not ready
[Mon Apr 20 21:11:31 2020] IPv6: ADDRCONF(NETDEV_UP): br-b0a72ee3d446: link is not ready
[Mon Apr 20 21:11:31 2020] wlcore: down
[Mon Apr 20 21:11:32 2020] wlcore: PHY firmware version: Rev 8.2.0.0.242
[Mon Apr 20 21:11:32 2020] wlcore: firmware booted (Rev 8.9.0.0.79)
[Mon Apr 20 21:11:32 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Mon Apr 20 21:11:33 2020] IPv6: ADDRCONF(NETDEV_UP): supervisor0: link is not ready
[Mon Apr 20 21:11:37 2020] wlan0: authenticate with 7c:d9:5c:95:52:ab
[Mon Apr 20 21:11:37 2020] wlan0: send auth to 7c:d9:5c:95:52:ab (try 1/3)
[Mon Apr 20 21:11:37 2020] wlan0: authenticated
[Mon Apr 20 21:11:37 2020] wlan0: associate with 7c:d9:5c:95:52:ab (try 1/3)
[Mon Apr 20 21:11:37 2020] wlan0: RX AssocResp from 7c:d9:5c:95:52:ab (capab=0x1011 status=0 aid=9)
[Mon Apr 20 21:11:37 2020] wlan0: associated
[Mon Apr 20 21:11:38 2020] wlan0: Limiting TX power to 30 (30 - 0) dBm as advertised by 7c:d9:5c:95:52:ab
[Mon Apr 20 21:11:38 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Mon Apr 20 21:11:38 2020] wlcore: Association completed.
[Mon Apr 20 21:11:48 2020] udevd[29]: starting version 3.2.9
[Mon Apr 20 21:11:48 2020] udevd[30]: starting eudev-3.2.9
[Mon Apr 20 21:11:50 2020] ip6_tables: (C) 2000-2006 Netfilter Core Team
[Mon Apr 20 21:14:39 2020] udevd[29]: starting version 3.2.9
[Mon Apr 20 21:14:39 2020] udevd[30]: starting eudev-3.2.9
[Tue Apr 21 21:24:52 2020] udevd[29]: starting version 3.2.9
[Tue Apr 21 21:24:52 2020] udevd[30]: starting eudev-3.2.9
[Wed Apr 22 13:22:07 2020] udevd[28]: starting version 3.2.9
[Wed Apr 22 13:22:07 2020] udevd[29]: starting eudev-3.2.9

I’ll prep a bare metal BBG Wirelss board to run the app. Give me ~2 days to see if it crashes.

Great! Let’s see what the experiment’s results will show!

Update on my experiment on running my Bluetooth scanner on bare metal:
It has been running well for the last 4 days on bare metal. BalenaOS stops finding Bluetooth devices after ~2 days.

Of my 3 running BBGW boards, 1 is bare metal, 2 are running BalenaOS

Bare metal specs
Debian GNU/Linux 10
Debian Buster IoT Image 2020-04-06

BalenaOS specs
BalenaOS (2.47.1+rev2)

The all run Bluez 5.50 with the same single Golang binary (all dependencies and certs compiled in - no other OS package installs required apart from stdlib). The same code also has been running on my Linux desktop without any issues for weeks.

Any ideas on what could cause this?

Hey @enachb,

This is something that we would like to reproduce locally, would it be possible for you to share the test application you are using (or a simple version of it)?