Device won't update properly

[pcasey92]

I was trying to add the “Screenly OSE” to my device using balenaOS and, for reasons that I’m not smart enough to understand, it refuses to update. It will go anywhere between 20% and 99% and then just goes back to 0% and tries again. I have deleted 3 devices and made 3 more fresh images thinking it was something there, but it’s doing the same thing every time. The screen my Pi is connected to just has the “Voltage normalised” “Under-voltage detected!” lines, which I don’t recall my others having, but I wouldn’t assume that would be an issue. Please help

UUID is fb1282d if anyone can check me out too.

[shaunmulligan]

Hey @pcasey92 can pull out some logs from the hostOS? specifically logs from the commands dmesg , journalctl -u resin-supervisor --no-pager and journalctl -u balena --no-pager would be useful.

The undervoltage can definitely cause a problem, i have see that log cause the container engine to fail quiet often, so if you have a better power source, it would be worth trying that too.

[pcasey92]

Understood. I won’t be able to try another power source until tomorrow at least, but I can give you the logs for now.
dmroot@fb1282d:~# dmesg
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.14.98 (oe-user@oe-host) (gcc version 8.2.0 (GCC)) #1 SMP Mon Jun 17 12:13:38 UTC 2019
[ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 8 MiB at 0x33800000
[ 0.000000] On node 0 totalpages: 212992
[ 0.000000] free_area_init_node: node 0, pgdat 8138ae00, node_mem_map b30a4000
[ 0.000000] Normal zone: 1872 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 212992 pages, LIFO batch:31
[ 0.000000] random: get_random_bytes called from start_kernel+0xac/0x448 with crng_init=0
[ 0.000000] percpu: Embedded 17 pages/cpu @b304c000 s38796 r8192 d22644 u69632
[ 0.000000] pcpu-alloc: s38796 r8192 d22644 u69632 alloc=17*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 211120
[ 0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=1824 bcm2708_fb.fbheight=984 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.lpm_enable=0 console=tty1 console=ttyS0,115200 rootfstype=ext4 rootwait root=PARTUUID=1e5c56fe-02 rootwait
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 815284K/851968K available (8192K kernel code, 600K rwdata, 2288K rodata, 7168K init, 704K bss, 28492K reserved, 8192K cma-reserved)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xb4800000 - 0xff800000 (1200 MB)
lowmem : 0x80000000 - 0xb4000000 ( 832 MB)
modules : 0x7f000000 - 0x80000000 ( 16 MB)
.text : 0x80008000 - 0x80900000 (9184 kB)
.init : 0x80c00000 - 0x81300000 (7168 kB)
.data : 0x81300000 - 0x8139622c ( 601 kB)
.bss : 0x8139e624 - 0x8144e7b0 ( 705 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 27474 entries in 81 pages
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[ 0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[ 0.000023] Switching to timer-based delay loop, resolution 52ns
[ 0.000281] Console: colour dummy device 80x30
[ 0.000847] console [tty1] enabled
[ 0.000892] Calibrating delay loop (skipped), value calculated using timer frequency… 38.40 BogoMIPS (lpj=192000)
[ 0.000934] pid_max: default: 32768 minimum: 301
[ 0.001266] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001302] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.002223] CPU: Testing write buffer coherency: ok
[ 0.002695] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.003150] Setting up static identity map for 0x100000 - 0x10003c
[ 0.003299] Hierarchical SRCU implementation.
[ 0.004035] smp: Bringing up secondary CPUs …
[ 0.004852] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.005691] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.006468] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.006573] smp: Brought up 1 node, 4 CPUs
[ 0.006648] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[ 0.006669] CPU: All CPU(s) started in HYP mode.
[ 0.006687] CPU: Virtualization extensions available.
[ 0.007631] devtmpfs: initialized
[ 0.018508] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[ 0.018776] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.018822] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.019437] pinctrl core: initialized pinctrl subsystem
[ 0.020273] NET: Registered protocol family 16
[ 0.022919] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.027606] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.027639] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.027874] Serial: AMBA PL011 UART driver
[ 0.029637] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[ 0.030145] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[ 0.061524] bcm2835-dma 3f007000.dma: DMA legacy API manager at b4813000, dmachans=0x1
[ 0.063023] SCSI subsystem initialized
[ 0.063266] usbcore: registered new interface driver usbfs
[ 0.063343] usbcore: registered new interface driver hub
[ 0.063444] usbcore: registered new device driver usb
[ 0.070090] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-11-04 16:31
[ 0.071397] clocksource: Switched to clocksource arch_sys_counter
[ 0.150369] VFS: Disk quotas dquot_6.6.0
[ 0.150494] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.150704] FS-Cache: Loaded
[ 0.150933] CacheFiles: Loaded
[ 0.159853] NET: Registered protocol family 2
[ 0.160623] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.160754] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.160957] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.161114] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.161177] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.161483] NET: Registered protocol family 1
[ 0.162063] RPC: Registered named UNIX socket transport module.
[ 0.162088] RPC: Registered udp transport module.
[ 0.162108] RPC: Registered tcp transport module.
[ 0.162127] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.219682] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[ 0.223005] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[ 0.230577] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[ 0.230645] FS-Cache: Netfs ‘nfs’ registered for caching
[ 0.231284] NFS: Registering the id_resolver key type
[ 0.231333] Key type id_resolver registered
[ 0.231353] Key type id_legacy registered
[ 0.231430] nfs4filelayout_init: NFSv4 File Layout Driver Registering…
[ 0.232692] aufs 4.14.73±20190211
[ 0.233983] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 0.234134] io scheduler noop registered
[ 0.234156] io scheduler deadline registered
[ 0.234341] io scheduler cfq registered (default)
[ 0.234364] io scheduler mq-deadline registered
[ 0.234384] io scheduler kyber registered
[ 0.236825] BCM2708FB: allocated DMA memory f3900000
[ 0.236871] BCM2708FB: allocated DMA channel 0 @ b4813000
[ 0.268361] Console: switching to colour frame buffer device 228x61
[ 0.298929] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[ 0.300509] bcm2835-rng 3f104000.rng: hwrng registered
[ 0.300799] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 0.301494] vc-sm: Videocore shared memory driver
[ 0.301917] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[ 0.311592] brd: module loaded
[ 0.320569] loop: module loaded
[ 0.320704] Loading iSCSI transport class v2.0-870.
[ 0.321631] libphy: Fixed MDIO Bus: probed
[ 0.321790] tun: Universal TUN/TAP device driver, 1.6
[ 0.322112] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.322545] dwc_otg 3f980000.usb: base=0xf0980000
[ 0.522860] Core Release: 2.80a
[ 0.522961] Setting default values for core params
[ 0.523116] Finished setting default values for core params
[ 0.723501] Using Buffer DMA mode
[ 0.723605] Periodic Transfer Interrupt Enhancement - disabled
[ 0.723767] Multiprocessor Interrupt Enhancement - disabled
[ 0.723925] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 0.724057] Dedicated Tx FIFOs mode
[ 0.724566] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xb3914000 dma = 0xf3914000 len=9024
[ 0.724853] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[ 0.725436] dwc_otg: Microframe scheduler enabled
[ 0.725492] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x80638700
[ 0.725667] WARN::hcd_init_fiq:460: FIQ ASM at 0x80638a64 length 36
[ 0.725850] WARN::hcd_init_fiq:486: MPHI regs_base at 0xf0006000
[ 0.726065] dwc_otg 3f980000.usb: DWC OTG Controller
[ 0.726237] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[ 0.733704] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[ 0.741058] Init: Port Power? op_state=1
[ 0.748332] Init: Power Port (0)
[ 0.755717] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.763032] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.770309] usb usb1: Product: DWC OTG Controller
[ 0.777578] usb usb1: Manufacturer: Linux 4.14.98 dwc_otg_hcd
[ 0.784883] usb usb1: SerialNumber: 3f980000.usb
[ 0.792820] hub 1-0:1.0: USB hub found
[ 0.800170] hub 1-0:1.0: 1 port detected
[ 0.807931] dwc_otg: FIQ enabled
[ 0.807936] dwc_otg: NAK holdoff enabled
[ 0.807941] dwc_otg: FIQ split-transaction FSM enabled
[ 0.807950] Module dwc_common_port init
[ 0.808223] usbcore: registered new interface driver usb-storage
[ 0.815650] mousedev: PS/2 mouse device common for all mice
[ 0.822900] IR NEC protocol handler initialized
[ 0.830028] IR RC5(x/sz) protocol handler initialized
[ 0.837168] IR RC6 protocol handler initialized
[ 0.844276] IR JVC protocol handler initialized
[ 0.851300] IR Sony protocol handler initialized
[ 0.858397] IR SANYO protocol handler initialized
[ 0.865432] IR Sharp protocol handler initialized
[ 0.872358] IR MCE Keyboard/mouse protocol handler initialized
[ 0.879265] IR XMP protocol handler initialized
[ 0.886846] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[ 0.894080] bcm2835-cpufreq: min=600000 max=1400000
[ 0.901485] sdhci: Secure Digital Host Controller Interface driver
[ 0.908547] sdhci: Copyright© Pierre Ossman
[ 0.916230] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[ 0.920326] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[ 0.923590] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.927986] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.931338] hidraw: raw HID events driver © Jiri Kosina
[ 0.934696] usbcore: registered new interface driver usbhid
[ 0.937940] usbhid: USB HID core driver
[ 0.941535] vchiq: vchiq_init_state: slot_zero = b3980000, is_master = 0
[ 0.946034] [vc_sm_connected_init]: start
[ 0.955418] [vc_sm_connected_init]: end - returning 0
[ 0.958904] nf_conntrack version 0.5.0 (13312 buckets, 53248 max)
[ 0.962525] ip_tables: © 2000-2006 Netfilter Core Team
[ 0.966022] Initializing XFRM netlink socket
[ 0.969503] NET: Registered protocol family 10
[ 0.973204] Segment Routing with IPv6
[ 0.976383] NET: Registered protocol family 17
[ 0.979567] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[ 0.982983] Key type dns_resolver registered
[ 0.986478] Registering SWP/SWPB emulation handler
[ 0.990111] registered taskstats version 1
[ 0.996423] uart-pl011 3f201000.serial: cts_event_workaround enabled
[ 0.999857] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[ 1.004169] console [ttyS0] disabled
[ 1.007525] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 166, base_baud = 31250000) is a 16550
[ 2.083122] console [ttyS0] enabled
[ 2.090481] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[ 2.099790] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[ 2.108962] Indeed it is in host mode hprt0 = 00021501
[ 2.205476] random: fast init done
[ 2.232210] sdhost: log_buf @ b3913000 (f3913000)
[ 2.281785] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 2.292197] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.302634] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 2.314237] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 2.331395] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[ 2.331448] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 2.340726] of_cfs_init
[ 2.355906] of_cfs_init: OK
[ 2.370486] Indeed it is in host mode hprt0 = 00001101
[ 2.377804] Freeing unused kernel memory: 7168K
[ 2.489177] mmc0: host does not support reading read-only switch, assuming write-enable
[ 2.509751] mmc1: new high speed SDIO card at address 0001
[ 2.519387] mmc0: new high speed SDHC card at address 0007
[ 2.529580] mmcblk0: mmc0:0007 SD16G 14.4 GiB
[ 2.542983] mmcblk0: p1 p2 p3 p4 < p5 p6 >
[ 2.611892] usb 1-1: New USB device found, idVendor=0424, idProduct=2514
[ 2.625589] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 2.637220] hub 1-1:1.0: USB hub found
[ 2.645090] hub 1-1:1.0: 4 ports detected
[ 2.981478] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 3.121813] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514
[ 3.136646] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 3.153030] hub 1-1.1:1.0: USB hub found
[ 3.171916] hub 1-1.1:1.0: 3 ports detected
[ 3.253129] CP437: Invalid argument
[ 3.348994] fsck.fat 4.1 (2017-01-24)
/dev/disk/by-label/resin-boot: 156 files, 16694/80628 clusters
[ 3.401097] resin-rootA: clean, 5847/39936 files, 220650/319488 blocks

[ 3.538115] dwc_otg_handle_wakeup_detected_intr lxstate = 2
[ 3.606800] resin-rootB: clean, 11/39936 files, 15349/319488 blocks

[ 3.692518] resin-state: clean, 64/5136 files, 1900/20480 blocks

[ 4.037301] mmcblk0: p1 p2 p3 p4 < p5 p6 >
[ 4.071549] usb 1-1.1.1: new high-speed USB device number 4 using dwc_otg
[ 4.151563] Under-voltage detected! (0x00050005)
[ 4.211716] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800
[ 4.222398] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 5.181730] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 5.249213] EXT4-fs (mmcblk0p5): mounted filesystem with ordered data mode. Opts: (null)
[ 5.728147] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 5.758632] aufs au_opts_verify:1609:init[1]: dirperm1 breaks the protection by the permission bits on the lower branch
[ 7.561739] systemd[1]: System time before build time, advancing clock.
[ 7.585792] systemd[1]: systemd 239 running in system mode. (-PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid)
[ 7.615392] systemd[1]: Detected architecture arm.
[ 7.661764] systemd[1]: No hostname configured.
[ 7.674708] systemd[1]: Set hostname to .
[ 7.696177] systemd[1]: Hardware watchdog ‘Broadcom BCM2835 Watchdog timer’, version 0
[ 7.712759] systemd[1]: Set hardware watchdog to 10s.
[ 7.842618] systemd[1]: File /lib/systemd/system/systemd-journald.service:36 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
[ 7.869292] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.)
[ 8.437243] random: systemd: uninitialized urandom read (16 bytes read)
[ 8.457144] systemd[1]: Created slice system-getty.slice.
[ 8.501946] random: systemd: uninitialized urandom read (16 bytes read)
[ 8.518198] systemd[1]: Listening on udev Control Socket.
[ 8.561577] random: systemd: uninitialized urandom read (16 bytes read)
[ 11.066572] EXT4-fs (mmcblk0p6): mounted filesystem with ordered data mode. Opts: (null)
[ 13.856498] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[ 13.885939] bcm2835_alsa bcm2835_alsa: card created with 8 channels
[ 14.069419] libphy: lan78xx-mdiobus: probed
[ 14.111193] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
[ 14.163845] brcmfmac: F1 signature read @0x18000000=0x15264345
[ 14.171108] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43455-sdio.bin for chip 0x004345(17221) rev 0x000006
[ 14.197109] usbcore: registered new interface driver brcmfmac
[ 14.299165] usbcore: registered new interface driver lan78xx
[ 14.475762] random: crng init done
[ 14.489266] random: 7 urandom warning(s) missed due to ratelimiting
[ 14.667863] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
[ 14.691021] brcmfmac: brcmf_c_preinit_dcmds: CLM version = API: 12.2 Data: 9.10.105 Compiler: 1.29.4 ClmImport: 1.36.3 Creation: 2018-03-09 18:56:28
[ 16.547679] uart-pl011 3f201000.serial: no DMA platform data
[ 18.935834] i2c /dev entries driver
[ 20.183861] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 20.201555] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 20.281575] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 20.325468] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 20.342171] brcmfmac: power management disabled
[ 20.887121] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 20.903377] brcmfmac: power management disabled
[ 21.283757] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 22.230511] Bridge firewalling registered
[ 22.699770] Netfilter messages via NETLINK v0.30.
[ 22.710812] ctnetlink v0.93: registering with nfnetlink.
[ 23.370456] IPv6: ADDRCONF(NETDEV_UP): supervisor0: link is not ready
[ 23.530630] Bluetooth: Core ver 2.22
[ 23.534826] NET: Registered protocol family 31
[ 23.539563] Bluetooth: HCI device and connection manager initialized
[ 23.546437] Bluetooth: HCI socket layer initialized
[ 23.551640] Bluetooth: L2CAP socket layer initialized
[ 23.557001] Bluetooth: SCO socket layer initialized
[ 23.583680] Bluetooth: HCI UART driver ver 2.3
[ 23.588444] Bluetooth: HCI UART protocol H4 registered
[ 23.594024] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 23.601213] Bluetooth: HCI UART protocol Broadcom registered
[ 23.778555] IPv6: ADDRCONF(NETDEV_UP): br-2ca4fb48f74d: link is not ready
[ 24.120556] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 24.126458] Bluetooth: BNEP filters: protocol multicast
[ 24.133710] Bluetooth: BNEP socket layer initialized
[ 24.146182] IPv6: ADDRCONF(NETDEV_UP): balena0: link is not ready
[ 24.964003] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 24.970331] brcmfmac: power management disabled
[ 28.232334] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 36.790592] ip6_tables: © 2000-2006 Netfilter Core Team
[ 83.192104] Voltage normalised (0x00000000)
[ 89.432637] Under-voltage detected! (0x00050005)
[ 93.592102] Voltage normalised (0x00000000)
[ 95.672126] Under-voltage detected! (0x00050005)
[ 131.032365] Voltage normalised (0x00000000)
[ 391.030822] rpi_firmware_get_throttled: 2 callbacks suppressed
[ 391.030829] Under-voltage detected! (0x00050005)
[ 418.070748] rpi_firmware_get_throttled: 2 callbacks suppressed
[ 418.070754] Voltage normalised (0x00000000)
[ 426.390745] Under-voltage detected! (0x00050005)
[ 432.630718] Voltage normalised (0x00000000)
[ 445.110744] Under-voltage detected! (0x00050005)
[ 644.791646] Voltage normalised (0x00000000)
[ 692.632080] rpi_firmware_get_throttled: 1 callbacks suppressed
[ 692.632086] Under-voltage detected! (0x00050005)
[ 698.872250] Under-voltage detected! (0x00050005)
[ 725.912503] rpi_firmware_get_throttled: 2 callbacks suppressed
[ 725.912510] Voltage normalised (0x00000000)
[ 732.152585] Under-voltage detected! (0x00050005)
[ 736.312640] Voltage normalised (0x00000000)
[ 763.352664] Voltage normalised (0x00000000)
[ 1031.672157] rpi_firmware_get_throttled: 6 callbacks suppressed
[ 1031.672163] Voltage normalised (0x00000000)
[ 1042.072177] rpi_firmware_get_throttled: 8 callbacks suppressed
[ 1042.072186] Under-voltage detected! (0x00050005)
[ 1046.232156] Voltage normalised (0x00000000)
[ 1048.312165] Under-voltage detected! (0x00050005)
[ 1073.272163] Voltage normalised (0x00000000)
[ 1081.592194] Under-voltage detected! (0x00050005)
[ 1343.671911] rpi_firmware_get_throttled: 9 callbacks suppressed
[ 1343.671920] Voltage normalised (0x00000000)
[ 1349.912004] rpi_firmware_get_throttled: 9 callbacks suppressed
[ 1349.912012] Under-voltage detected! (0x00050005)
[ 1368.631951] Voltage normalised (0x00000000)
[ 1379.031896] Under-voltage detected! (0x00050005)
[ 1385.271886] Voltage normalised (0x00000000)
[ 1387.351972] Under-voltage detected! (0x00050005)

[pcasey92]

Journalctl -u resin-supervisor --no-pager Logs
– Logs begin at Wed 2019-06-12 18:01:15 UTC, end at Wed 2019-07-03 19:59:13 UTC. –
Jun 25 14:49:44 fb1282d systemd[1]: Starting Resin supervisor…
Jun 25 14:49:45 fb1282d resin-supervisor[1109]: resin_supervisor
Jun 25 14:49:45 fb1282d resin-supervisor[1126]: active
Jun 25 14:49:45 fb1282d systemd[1]: Started Resin supervisor.
Jun 25 14:49:47 fb1282d resin-supervisor[1130]: Container config has not changed
Jun 25 14:49:51 fb1282d resin-supervisor[1130]: Starting system message bus: dbus.
Jun 25 14:49:51 fb1282d resin-supervisor[1130]: * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon
Jul 03 19:27:58 fb1282d resin-supervisor[1130]: …done.
Jul 03 19:28:09 fb1282d resin-supervisor[1130]: (node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Starting event tracker
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Starting up api binder
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Starting logging infrastructure
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Event: Supervisor start {}
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Performing database cleanup for container log timestamps
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Connectivity check enabled: true
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Starting periodic check for IP addresses
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Reporting initial state, supervisor version and API info
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: VPN status path exists.
Jul 03 19:28:12 fb1282d resin-supervisor[1130]: Waiting for connectivity…
Jul 03 19:28:13 fb1282d resin-supervisor[1130]: Skipping preloading
Jul 03 19:28:13 fb1282d resin-supervisor[1130]: Starting API server
Jul 03 19:28:13 fb1282d resin-supervisor[1130]: Applying target state
Jul 03 19:28:13 fb1282d resin-supervisor[1130]: Ensuring device is provisioned
Jul 03 19:28:13 fb1282d resin-supervisor[1130]: Starting current state report
Jul 03 19:28:13 fb1282d resin-supervisor[1130]: Starting target state poll
Jul 03 19:28:14 fb1282d resin-supervisor[1130]: Supervisor API listening on allowed interfaces only
Jul 03 19:28:15 fb1282d resin-supervisor[1130]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/3cfce2363bf73a524aabd034359d01f8@sha256:72a83e3008dcaf9fad6f697677e23886e687f78b03ace6110c758ca9badfad23",“appId”:1488952,“serviceId”:283830,“serviceName”:“screenly-server”,“imageId”:1293733,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:28:15 fb1282d resin-supervisor[1130]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/2c23ccf2a8640cb5e509684ce2331622@sha256:4eb2fd0ea17b5671c8b56e7345080d5bb4b6a081e3e0088f6281aafb98d4372d",“appId”:1488952,“serviceId”:283831,“serviceName”:“screenly-viewer”,“imageId”:1293734,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:28:15 fb1282d resin-supervisor[1130]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/9d6055bf76dc47462821377ff33e4fc0@sha256:5c55221fe26518fd42f8efcb2738e8ca373404d54ffbc4ceb01d86e471798ec3",“appId”:1488952,“serviceId”:283832,“serviceName”:“screenly-websocket”,“imageId”:1293735,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:28:22 fb1282d resin-supervisor[1130]: Internet Connectivity: OK
Jul 03 19:28:37 fb1282d resin-supervisor[1130]: Supervisor API: POST /v2/applications/1488952/stop-service 404 - 94.994 ms
Jul 03 19:33:01 fb1282d resin-supervisor[1130]: Supervisor API: GET /v1/healthy 200 - 29.900 ms
Jul 03 19:38:08 fb1282d resin-supervisor[1130]: Attempting container log timestamp flush…
Jul 03 19:38:08 fb1282d resin-supervisor[1130]: Container log timestamp flush complete
Jul 03 19:39:59 fb1282d resin-supervisor[1130]: Supervisor API: GET /v1/healthy 200 - 12.642 ms
Jul 03 19:45:27 fb1282d resin-supervisor[1130]: Supervisor API: GET /v1/healthy 200 - 7.549 ms
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Watchdog timeout (limit 3min)!
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Killing process 1130 (start-resin-sup) with signal SIGABRT.
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Killing process 1133 (exe) with signal SIGABRT.
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Killing process 1222 (balena) with signal SIGABRT.
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Killing process 2237 (resin-superviso) with signal SIGABRT.
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Killing process 2238 (balena) with signal SIGABRT.
Jul 03 19:47:05 fb1282d systemd[1]: resin-supervisor.service: Main process exited, code=killed, status=6/ABRT
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: SIGABRT: abort
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: PC=0x6f47c m=0 sigcode=0
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: goroutine 0 [idle]:
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.futex(0x1cfe390, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1cfe390, 0x0, 0x0, 0x46724, …)
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/sys_linux_arm.s:266 +0x1c
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.futexsleep(0x1cfe390, 0x0, 0xffffffff, 0xffffffff)
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/os_linux.go:45 +0x74
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.notesleep(0x1cfe390)
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/lock_futex.go:151 +0xac
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.stopm()
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/proc.go:1952 +0xac
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.findrunnable(0x12b43300, 0x0)
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/proc.go:2415 +0x378
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.schedule()
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/proc.go:2541 +0x110
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.goexit0(0x130a8d20)
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/proc.go:2713 +0x1e0
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: runtime.mcall(0x0)
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: /usr/lib/go/src/runtime/asm_arm.s:285 +0x5c
Jul 03 19:47:05 fb1282d resin-supervisor[1130]: goroutine 1 [select]:
Jul 03 19:48:08 fb1282d resin-supervisor[1130]: Attempting container log timestamp flush…
Jul 03 19:48:08 fb1282d resin-supervisor[1130]: Container log timestamp flush complete
Jul 03 19:48:35 fb1282d systemd[1]: resin-supervisor.service: State ‘stop-final-sigterm’ timed out. Killing.
Jul 03 19:48:35 fb1282d systemd[1]: resin-supervisor.service: Killing process 1222 (balena) with signal SIGKILL.
Jul 03 19:48:35 fb1282d systemd[1]: resin-supervisor.service: Failed with result ‘watchdog’.
Jul 03 19:48:46 fb1282d systemd[1]: resin-supervisor.service: Service RestartSec=10s expired, scheduling restart.
Jul 03 19:48:46 fb1282d systemd[1]: resin-supervisor.service: Scheduled restart job, restart counter is at 1.
Jul 03 19:48:46 fb1282d systemd[1]: Stopped Resin supervisor.
Jul 03 19:48:46 fb1282d systemd[1]: Starting Resin supervisor…
Jul 03 19:49:38 fb1282d resin-supervisor[2325]: resin_supervisor
Jul 03 19:49:38 fb1282d resin-supervisor[2399]: active
Jul 03 19:49:38 fb1282d systemd[1]: Started Resin supervisor.
Jul 03 19:49:40 fb1282d resin-supervisor[2400]: Container config has not changed
Jul 03 19:49:54 fb1282d resin-supervisor[2400]: Starting system message bus: dbus.
Jul 03 19:49:54 fb1282d resin-supervisor[2400]: * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon
Jul 03 19:49:55 fb1282d resin-supervisor[2400]: …done.
Jul 03 19:50:05 fb1282d resin-supervisor[2400]: (node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Jul 03 19:50:29 fb1282d resin-supervisor[2400]: Starting event tracker
Jul 03 19:50:29 fb1282d resin-supervisor[2400]: Starting up api binder
Jul 03 19:50:29 fb1282d resin-supervisor[2400]: Starting logging infrastructure
Jul 03 19:50:29 fb1282d resin-supervisor[2400]: Event: Supervisor start {}
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Performing database cleanup for container log timestamps
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Connectivity check enabled: true
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Starting periodic check for IP addresses
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Reporting initial state, supervisor version and API info
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: VPN status path exists.
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Waiting for connectivity…
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Skipping preloading
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Starting API server
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Applying target state
Jul 03 19:50:39 fb1282d resin-supervisor[2400]: Ensuring device is provisioned
Jul 03 19:50:40 fb1282d resin-supervisor[2400]: Starting current state report
Jul 03 19:50:40 fb1282d resin-supervisor[2400]: Starting target state poll
Jul 03 19:50:41 fb1282d resin-supervisor[2400]: Supervisor API listening on allowed interfaces only
Jul 03 19:50:42 fb1282d resin-supervisor[2400]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/3cfce2363bf73a524aabd034359d01f8@sha256:72a83e3008dcaf9fad6f697677e23886e687f78b03ace6110c758ca9badfad23",“appId”:1488952,“serviceId”:283830,“serviceName”:“screenly-server”,“imageId”:1293733,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:50:42 fb1282d resin-supervisor[2400]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/2c23ccf2a8640cb5e509684ce2331622@sha256:4eb2fd0ea17b5671c8b56e7345080d5bb4b6a081e3e0088f6281aafb98d4372d",“appId”:1488952,“serviceId”:283831,“serviceName”:“screenly-viewer”,“imageId”:1293734,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:50:42 fb1282d resin-supervisor[2400]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/9d6055bf76dc47462821377ff33e4fc0@sha256:5c55221fe26518fd42f8efcb2738e8ca373404d54ffbc4ceb01d86e471798ec3",“appId”:1488952,“serviceId”:283832,“serviceName”:“screenly-websocket”,“imageId”:1293735,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:50:49 fb1282d resin-supervisor[2400]: Internet Connectivity: OK
Jul 03 19:54:54 fb1282d resin-supervisor[2400]: Supervisor API: GET /v1/healthy 200 - 48.972 ms
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Watchdog timeout (limit 3min)!
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Killing process 2400 (start-resin-sup) with signal SIGABRT.
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Killing process 2402 (exe) with signal SIGABRT.
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Killing process 2504 (balena) with signal SIGABRT.
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Killing process 2891 (resin-superviso) with signal SIGABRT.
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Killing process 2892 (balena) with signal SIGABRT.
Jul 03 19:57:10 fb1282d systemd[1]: resin-supervisor.service: Main process exited, code=killed, status=6/ABRT
Jul 03 19:58:40 fb1282d systemd[1]: resin-supervisor.service: State ‘stop-final-sigterm’ timed out. Killing.
Jul 03 19:58:40 fb1282d systemd[1]: resin-supervisor.service: Killing process 2504 (balena) with signal SIGKILL.
Jul 03 19:58:40 fb1282d systemd[1]: resin-supervisor.service: Failed with result ‘watchdog’.
Jul 03 19:58:50 fb1282d systemd[1]: resin-supervisor.service: Service RestartSec=10s expired, scheduling restart.
Jul 03 19:58:50 fb1282d systemd[1]: resin-supervisor.service: Scheduled restart job, restart counter is at 2.
Jul 03 19:58:50 fb1282d systemd[1]: Stopped Resin supervisor.
Jul 03 19:58:50 fb1282d systemd[1]: Starting Resin supervisor…

[pcasey92]

journalctl -u balena --no-pager Logs
– Logs begin at Wed 2019-06-12 18:01:15 UTC, end at Wed 2019-07-03 20:01:07 UTC. –
Jun 25 14:49:37 fb1282d systemd[1]: Starting Balena Application Container Engine…
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.591968539Z” level=warning msg=“Running experimental build”
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.622978279Z” level=warning msg="[!] DON’T BIND ON ANY IP ADDRESS WITHOUT setting --tlsverify IF YOU DON’T KNOW WHAT YOU’RE DOING [!]"
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.655721612Z” level=info msg=“libcontainerd: started new balena-engine-containerd process” pid=842
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.961306560Z” level=info msg=“starting containerd” revision= version=1.2.2+unknown
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.964760831Z” level=info msg=“loading plugin “io.containerd.content.v1.content”…” type=io.containerd.content.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.966217549Z” level=info msg=“loading plugin “io.containerd.snapshotter.v1.aufs”…” type=io.containerd.snapshotter.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.977786039Z” level=info msg=“loading plugin “io.containerd.snapshotter.v1.native”…” type=io.containerd.snapshotter.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.979101039Z” level=info msg=“loading plugin “io.containerd.snapshotter.v1.overlayfs”…” type=io.containerd.snapshotter.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.980805153Z” level=info msg=“loading plugin “io.containerd.metadata.v1.bolt”…” type=io.containerd.metadata.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.981106247Z” level=info msg=“metadata content store policy set” policy=shared
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.990434112Z” level=info msg=“loading plugin “io.containerd.differ.v1.walking”…” type=io.containerd.differ.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.990766768Z” level=info msg=“loading plugin “io.containerd.gc.v1.scheduler”…” type=io.containerd.gc.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.991105935Z” level=info msg=“loading plugin “io.containerd.service.v1.containers-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.991318956Z” level=info msg=“loading plugin “io.containerd.service.v1.content-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.991534164Z” level=info msg=“loading plugin “io.containerd.service.v1.diff-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.991728747Z” level=info msg=“loading plugin “io.containerd.service.v1.images-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.991951195Z” level=info msg=“loading plugin “io.containerd.service.v1.leases-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.992166872Z” level=info msg=“loading plugin “io.containerd.service.v1.namespaces-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.992350726Z” level=info msg=“loading plugin “io.containerd.service.v1.snapshots-service”…” type=io.containerd.service.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.992585414Z” level=info msg=“loading plugin “io.containerd.runtime.v1.linux”…” type=io.containerd.runtime.v1
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.993695362Z” level=info msg=“loading plugin “io.containerd.runtime.v2.task”…” type=io.containerd.runtime.v2
Jun 25 14:49:39 fb1282d balenad[783]: time=“2019-06-25T14:49:39.994443070Z” level=info msg=“loading plugin “io.containerd.monitor.v1.cgroups”…” type=io.containerd.monitor.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.002438331Z” level=info msg=“loading plugin “io.containerd.service.v1.tasks-service”…” type=io.containerd.service.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.002825570Z” level=info msg=“loading plugin “io.containerd.internal.v1.restart”…” type=io.containerd.internal.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.003298539Z” level=info msg=“loading plugin “io.containerd.grpc.v1.containers”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.003579112Z” level=info msg=“loading plugin “io.containerd.grpc.v1.content”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.003761976Z” level=info msg=“loading plugin “io.containerd.grpc.v1.diff”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.003936612Z” level=info msg=“loading plugin “io.containerd.grpc.v1.events”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.004108122Z” level=info msg=“loading plugin “io.containerd.grpc.v1.healthcheck”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.004387497Z” level=info msg=“loading plugin “io.containerd.grpc.v1.images”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.004564633Z” level=info msg=“loading plugin “io.containerd.grpc.v1.leases”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.004742237Z” level=info msg=“loading plugin “io.containerd.grpc.v1.namespaces”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.005008643Z” level=info msg=“loading plugin “io.containerd.internal.v1.opt”…” type=io.containerd.internal.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.005411560Z” level=warning msg=“failed to load plugin io.containerd.internal.v1.opt” error=“mkdir /opt: read-only file system”
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.005571716Z” level=info msg=“loading plugin “io.containerd.grpc.v1.snapshots”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.005769789Z” level=info msg=“loading plugin “io.containerd.grpc.v1.tasks”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.005948226Z” level=info msg=“loading plugin “io.containerd.grpc.v1.version”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.006135570Z” level=info msg=“loading plugin “io.containerd.grpc.v1.introspection”…” type=io.containerd.grpc.v1
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.007562862Z” level=info msg=serving… address=/var/run/balena-engine/containerd/balena-engine-containerd-debug.sock
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.008465674Z” level=info msg=serving… address=/var/run/balena-engine/containerd/balena-engine-containerd.sock
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.015095622Z” level=info msg=“containerd successfully booted in 0.067507s”
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.355822393Z” level=info msg=“Graph migration to content-addressability took 0.00 seconds”
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.358454268Z” level=warning msg=“Your kernel does not support cgroup rt period”
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.358681351Z” level=warning msg=“Your kernel does not support cgroup rt runtime”
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.359593955Z” level=warning msg=“mountpoint for pids not found”
Jun 25 14:49:40 fb1282d balenad[783]: time=“2019-06-25T14:49:40.361070674Z” level=info msg=“Loading containers: start.”
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.190416558Z” level=info msg=“Loading containers: done.”
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.847754006Z” level=info msg=“Docker daemon” commit=95c7371304f9cef494efe93f0a8ffd53a75eac21 graphdriver(s)=aufs version=18.09.6-dev
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.847976402Z” level=info msg=“Daemon has completed initialization”
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.954446818Z” level=info msg=“API listen on /var/run/balena.sock”
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.954597964Z” level=info msg=“API listen on /var/run/balena-engine.sock”
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.955108745Z” level=info msg=“API listen on /var/run/balena-engine.sock”
Jun 25 14:49:44 fb1282d systemd[1]: Started Balena Application Container Engine.
Jun 25 14:49:44 fb1282d balenad[783]: time=“2019-06-25T14:49:44.954406974Z” level=info msg=“API listen on [::]:2375”
Jun 25 14:49:48 fb1282d balenad[783]: time=“2019-06-25T14:49:48.991204629Z” level=info msg=“shim balena-engine-containerd-shim started” address=/containerd-shim/moby/3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80/shim.sock debug=false pid=1268
Jun 25 14:49:51 fb1282d 3f6778331664[783]: Starting system message bus: dbus.
Jun 25 14:49:51 fb1282d 3f6778331664[783]: * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon
Jul 03 19:27:58 fb1282d 3f6778331664[783]: …done.
Jul 03 19:28:09 fb1282d 3f6778331664[783]: (node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Starting event tracker
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Starting up api binder
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Starting logging infrastructure
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Event: Supervisor start {}
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Performing database cleanup for container log timestamps
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Connectivity check enabled: true
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Starting periodic check for IP addresses
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Reporting initial state, supervisor version and API info
Jul 03 19:28:12 fb1282d 3f6778331664[783]: VPN status path exists.
Jul 03 19:28:12 fb1282d 3f6778331664[783]: Waiting for connectivity…
Jul 03 19:28:13 fb1282d 3f6778331664[783]: Skipping preloading
Jul 03 19:28:13 fb1282d 3f6778331664[783]: Starting API server
Jul 03 19:28:13 fb1282d 3f6778331664[783]: Applying target state
Jul 03 19:28:13 fb1282d 3f6778331664[783]: Ensuring device is provisioned
Jul 03 19:28:13 fb1282d 3f6778331664[783]: Starting current state report
Jul 03 19:28:13 fb1282d 3f6778331664[783]: Starting target state poll
Jul 03 19:28:14 fb1282d 3f6778331664[783]: Supervisor API listening on allowed interfaces only
Jul 03 19:28:15 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/3cfce2363bf73a524aabd034359d01f8@sha256:72a83e3008dcaf9fad6f697677e23886e687f78b03ace6110c758ca9badfad23",“appId”:1488952,“serviceId”:283830,“serviceName”:“screenly-server”,“imageId”:1293733,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:28:15 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/2c23ccf2a8640cb5e509684ce2331622@sha256:4eb2fd0ea17b5671c8b56e7345080d5bb4b6a081e3e0088f6281aafb98d4372d",“appId”:1488952,“serviceId”:283831,“serviceName”:“screenly-viewer”,“imageId”:1293734,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:28:15 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/9d6055bf76dc47462821377ff33e4fc0@sha256:5c55221fe26518fd42f8efcb2738e8ca373404d54ffbc4ceb01d86e471798ec3",“appId”:1488952,“serviceId”:283832,“serviceName”:“screenly-websocket”,“imageId”:1293735,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:28:22 fb1282d 3f6778331664[783]: Internet Connectivity: OK
Jul 03 19:28:37 fb1282d 3f6778331664[783]: Supervisor API: POST /v2/applications/1488952/stop-service 404 - 94.994 ms
Jul 03 19:33:01 fb1282d 3f6778331664[783]: Supervisor API: GET /v1/healthy 200 - 29.900 ms
Jul 03 19:38:08 fb1282d 3f6778331664[783]: Attempting container log timestamp flush…
Jul 03 19:38:08 fb1282d 3f6778331664[783]: Container log timestamp flush complete
Jul 03 19:39:59 fb1282d 3f6778331664[783]: Supervisor API: GET /v1/healthy 200 - 12.642 ms
Jul 03 19:45:27 fb1282d 3f6778331664[783]: Supervisor API: GET /v1/healthy 200 - 7.549 ms
Jul 03 19:47:11 fb1282d balenad[783]: time=“2019-07-03T19:47:11.786388911Z” level=error msg=“Handler for GET /v1.39/containers/resin_supervisor/json returned error: write unix /var/run/balena-engine.sock->@: write: broken pipe”
Jul 03 19:47:11 fb1282d balenad[783]: 2019/07/03 19:47:11 http: multiple response.WriteHeader calls
Jul 03 19:48:08 fb1282d 3f6778331664[783]: Attempting container log timestamp flush…
Jul 03 19:48:08 fb1282d 3f6778331664[783]: Container log timestamp flush complete
Jul 03 19:48:56 fb1282d balenad[783]: time=“2019-07-03T19:48:56.794517336Z” level=info msg=“Container 3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80 failed to exit within 10 seconds of signal 15 - using the force”
Jul 03 19:48:58 fb1282d balenad[783]: time=“2019-07-03T19:48:58.175038068Z” level=info msg=“shim reaped” id=3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80
Jul 03 19:49:03 fb1282d balenad[783]: time=“2019-07-03T19:49:03.394362186Z” level=info msg=“ignoring event” module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Jul 03 19:49:39 fb1282d balenad[783]: time=“2019-07-03T19:49:39.298554382Z” level=info msg=“Pull session cancelled”
Jul 03 19:49:39 fb1282d balenad[783]: time=“2019-07-03T19:49:39.300340528Z” level=error msg=“Not continuing with pull after error: context canceled”
Jul 03 19:49:39 fb1282d balenad[783]: time=“2019-07-03T19:49:39.565823652Z” level=info msg=“Pull session cancelled”
Jul 03 19:49:39 fb1282d balenad[783]: time=“2019-07-03T19:49:39.566562454Z” level=error msg=“Not continuing with pull after error: context canceled”
Jul 03 19:49:40 fb1282d balenad[783]: time=“2019-07-03T19:49:40.166819912Z” level=info msg=“Pull session cancelled”
Jul 03 19:49:40 fb1282d balenad[783]: time=“2019-07-03T19:49:40.168378819Z” level=error msg=“Not continuing with pull after error: context canceled”
Jul 03 19:49:49 fb1282d balenad[783]: time=“2019-07-03T19:49:49.567350972Z” level=info msg=“shim balena-engine-containerd-shim started” address=/containerd-shim/moby/3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80/shim.sock debug=false pid=2513
Jul 03 19:49:54 fb1282d 3f6778331664[783]: Starting system message bus: dbus.
Jul 03 19:49:54 fb1282d 3f6778331664[783]: * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon
Jul 03 19:49:55 fb1282d 3f6778331664[783]: …done.
Jul 03 19:50:01 fb1282d balenad[783]: time=“2019-07-03T19:50:01.327015761Z” level=info msg=“Layer sha256:9060e0e78fa38887d6978a7844ae21c7e6817845db6b171c1efcf927a3bd6ef6 cleaned up”
Jul 03 19:50:01 fb1282d balenad[783]: time=“2019-07-03T19:50:01.327231178Z” level=info msg=“Layer sha256:abc682bb2981fd2d6c3b15b90b5a0f4838959599d9d2c17d1191636fff31f409 cleaned up”
Jul 03 19:50:01 fb1282d balenad[783]: time=“2019-07-03T19:50:01.327347116Z” level=info msg=“Layer sha256:c42e56ae236b4741f8165d30d5ab80b79aaa235eb3a3a504c6c1647f231c45df cleaned up”
Jul 03 19:50:01 fb1282d balenad[783]: time=“2019-07-03T19:50:01.327453366Z” level=info msg=“Layer sha256:8cc0241f5b5cefa76d0977070b6f78ccdc8f3f94a29e38e2316a1cbf00d2d557 cleaned up”
Jul 03 19:50:05 fb1282d 3f6778331664[783]: (node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Jul 03 19:50:28 fb1282d balenad[783]: time=“2019-07-03T19:50:28.168177275Z” level=info msg=“Layer sha256:145202f143ef0f9e2c6be6d7b6e49426cfc1f5d1d61fdbb50f5b811537000c38 cleaned up”
Jul 03 19:50:28 fb1282d balenad[783]: time=“2019-07-03T19:50:28.170017900Z” level=info msg=“Layer sha256:4248b04a612666ae89a5037982d6e41749beb1634814f935feb991c06b3257f4 cleaned up”
Jul 03 19:50:28 fb1282d balenad[783]: time=“2019-07-03T19:50:28.170522015Z” level=info msg=“Layer sha256:377042834a16b1eb14e77fd427601a96fe22cde4eab1222fbac0cc90283ecb2c cleaned up”
Jul 03 19:50:28 fb1282d balenad[783]: time=“2019-07-03T19:50:28.170923890Z” level=info msg=“Layer sha256:2a0c7c35dd3688ac9f08c525905d547527a1624c93c84c94faa055e975ac4c82 cleaned up”
Jul 03 19:50:29 fb1282d 3f6778331664[783]: Starting event tracker
Jul 03 19:50:29 fb1282d 3f6778331664[783]: Starting up api binder
Jul 03 19:50:29 fb1282d 3f6778331664[783]: Starting logging infrastructure
Jul 03 19:50:29 fb1282d 3f6778331664[783]: Event: Supervisor start {}
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.036944864Z” level=info msg=“Layer sha256:91a185fc0df737565e18fd94f54bd98edf93217fc302cb7e89dbe8381e008b68 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.037164239Z” level=info msg=“Layer sha256:f74c4ed6e823b4523041e280aa7ac4c34ee75bc8115f26603608411aafe53d0a cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.037271478Z” level=info msg=“Layer sha256:689d461313b19991773155b845ba52770ac9b3c951629392c3434e360af7eded cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.037374864Z” level=info msg=“Layer sha256:b91186cc7fa7c3ec210802b8ccc288f022c97cd03baf31e7fb30c74d32fcc9fe cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.037477468Z” level=info msg=“Layer sha256:72e90c7627cd208cf7fefe40564f54b55794728d984c2adc538f87dba7d191a8 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.039743875Z” level=info msg=“Layer sha256:f27cc25aed5f0def9627d89fad9b8ea959a3fe53895f3b2bf8124e32649e294f cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.039885021Z” level=info msg=“Layer sha256:0c903a2376d69e473bb52f5b5e77dc5a7fe1622b38a51fea170618ea82bd6292 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.039991791Z” level=info msg=“Layer sha256:d72ad8af8c7304bda2a788edac8ac9e34f75b666ffc9d16442ce3a790bb01869 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.040093979Z” level=info msg=“Layer sha256:ecdd00927f0be07dc711e871cdd32ad6a1a9e05f50e4a23dc0a3b860f2af0bb3 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.040197052Z” level=info msg=“Layer sha256:637ee6b821b5ee18209ad615a8c57d237448c9b99a96f25891db91e99758ef09 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.040299916Z” level=info msg=“Layer sha256:8ef15cc0a80c68683ffb7543b76c0d9734227a1cbd32c8e4a88118969e522fe0 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.040400125Z” level=info msg=“Layer sha256:7f256d3dc81033bc5755659271b12c20094bb8019efea210efacc05a72c440b3 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.040501062Z” level=info msg=“Layer sha256:61debb30dbaead016e71b66b6881b8f200bfb2bd206cdf2779bd37ee24589cc8 cleaned up”
Jul 03 19:50:39 fb1282d balenad[783]: time=“2019-07-03T19:50:39.040600698Z” level=info msg=“Layer sha256:53904a73c6b758fbf7cf126567267e5444e422bb375c34439e1296e04217b79f cleaned up”
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Performing database cleanup for container log timestamps
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Connectivity check enabled: true
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Starting periodic check for IP addresses
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Reporting initial state, supervisor version and API info
Jul 03 19:50:39 fb1282d 3f6778331664[783]: VPN status path exists.
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Waiting for connectivity…
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Skipping preloading
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Starting API server
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Applying target state
Jul 03 19:50:39 fb1282d 3f6778331664[783]: Ensuring device is provisioned
Jul 03 19:50:40 fb1282d 3f6778331664[783]: Starting current state report
Jul 03 19:50:40 fb1282d 3f6778331664[783]: Starting target state poll
Jul 03 19:50:41 fb1282d 3f6778331664[783]: Supervisor API listening on allowed interfaces only
Jul 03 19:50:42 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/3cfce2363bf73a524aabd034359d01f8@sha256:72a83e3008dcaf9fad6f697677e23886e687f78b03ace6110c758ca9badfad23",“appId”:1488952,“serviceId”:283830,“serviceName”:“screenly-server”,“imageId”:1293733,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:50:42 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/2c23ccf2a8640cb5e509684ce2331622@sha256:4eb2fd0ea17b5671c8b56e7345080d5bb4b6a081e3e0088f6281aafb98d4372d",“appId”:1488952,“serviceId”:283831,“serviceName”:“screenly-viewer”,“imageId”:1293734,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:50:42 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/9d6055bf76dc47462821377ff33e4fc0@sha256:5c55221fe26518fd42f8efcb2738e8ca373404d54ffbc4ceb01d86e471798ec3",“appId”:1488952,“serviceId”:283832,“serviceName”:“screenly-websocket”,“imageId”:1293735,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 19:50:49 fb1282d 3f6778331664[783]: Internet Connectivity: OK
Jul 03 19:54:54 fb1282d 3f6778331664[783]: Supervisor API: GET /v1/healthy 200 - 48.972 ms
Jul 03 19:58:01 fb1282d balenad[783]: time=“2019-07-03T19:58:01.759406549Z” level=error msg=“Handler for GET /v1.39/containers/resin_supervisor/json returned error: write unix /var/run/balena-engine.sock->@: write: broken pipe”
Jul 03 19:58:01 fb1282d balenad[783]: 2019/07/03 19:58:01 http: multiple response.WriteHeader calls
Jul 03 19:59:01 fb1282d balenad[783]: time=“2019-07-03T19:59:01.720581508Z” level=info msg=“Container 3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80 failed to exit within 10 seconds of signal 15 - using the force”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.086335007Z” level=info msg=“Pull session cancelled”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.088885007Z” level=error msg=“Not continuing with pull after error: context canceled”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.115807084Z” level=info msg=“Pull session cancelled”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.116614428Z” level=error msg=“Not continuing with pull after error: context canceled”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.276074393Z” level=info msg=“Pull session cancelled”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.276884549Z” level=error msg=“Not continuing with pull after error: context canceled”
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.500003353Z” level=info msg=“shim reaped” id=3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80
Jul 03 19:59:03 fb1282d balenad[783]: time=“2019-07-03T19:59:03.507296164Z” level=info msg=“ignoring event” module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Jul 03 19:59:42 fb1282d balenad[783]: time=“2019-07-03T19:59:42.569974158Z” level=info msg=“shim balena-engine-containerd-shim started” address=/containerd-shim/moby/3f6778331664fc4c4afc688ab9fe44a2b75dbe78b6fd2d54a2dadaae15e29c80/shim.sock debug=false pid=3165
Jul 03 19:59:44 fb1282d 3f6778331664[783]: Starting system message bus: dbus.
Jul 03 19:59:44 fb1282d 3f6778331664[783]: * Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon
Jul 03 19:59:44 fb1282d 3f6778331664[783]: …done.
Jul 03 19:59:53 fb1282d 3f6778331664[783]: (node:1) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
Jul 03 19:59:54 fb1282d 3f6778331664[783]: Starting event tracker
Jul 03 19:59:54 fb1282d 3f6778331664[783]: Starting up api binder
Jul 03 19:59:54 fb1282d 3f6778331664[783]: Starting logging infrastructure
Jul 03 19:59:54 fb1282d 3f6778331664[783]: Event: Supervisor start {}
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Performing database cleanup for container log timestamps
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Connectivity check enabled: true
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Starting periodic check for IP addresses
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Reporting initial state, supervisor version and API info
Jul 03 19:59:55 fb1282d 3f6778331664[783]: VPN status path exists.
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Waiting for connectivity…
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Skipping preloading
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Starting API server
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Applying target state
Jul 03 19:59:55 fb1282d 3f6778331664[783]: Ensuring device is provisioned
Jul 03 19:59:56 fb1282d 3f6778331664[783]: Starting current state report
Jul 03 19:59:56 fb1282d 3f6778331664[783]: Starting target state poll
Jul 03 19:59:57 fb1282d 3f6778331664[783]: Supervisor API listening on allowed interfaces only
Jul 03 20:00:05 fb1282d 3f6778331664[783]: Internet Connectivity: OK
Jul 03 20:00:09 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/3cfce2363bf73a524aabd034359d01f8@sha256:72a83e3008dcaf9fad6f697677e23886e687f78b03ace6110c758ca9badfad23",“appId”:1488952,“serviceId”:283830,“serviceName”:“screenly-server”,“imageId”:1293733,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 20:00:09 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/2c23ccf2a8640cb5e509684ce2331622@sha256:4eb2fd0ea17b5671c8b56e7345080d5bb4b6a081e3e0088f6281aafb98d4372d",“appId”:1488952,“serviceId”:283831,“serviceName”:“screenly-viewer”,“imageId”:1293734,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}
Jul 03 20:00:09 fb1282d 3f6778331664[783]: Event: Docker image download {“image”:{“name”:“registry2.balena-cloud.com/v2/9d6055bf76dc47462821377ff33e4fc0@sha256:5c55221fe26518fd42f8efcb2738e8ca373404d54ffbc4ceb01d86e471798ec3",“appId”:1488952,“serviceId”:283832,“serviceName”:“screenly-websocket”,“imageId”:1293735,“releaseId”:980618,“dependent”:0,"dockerImageId”:null}}

[samothx]

hi @pcasey92 ,
the under voltage logs do look serious.

[ 391.030829] Under-voltage detected! (0x00050005)
[ 418.070748] rpi_firmware_get_throttled: 2 callbacks suppressed
[ 418.070754] Voltage normalised (0x00000000)

The logs from the supervisor show that a watchdog timeout occurs on the supervisor. This stuff could easily be caused by the cpu being throttled due to under voltage.
For further investigation I would need to get support access to the device.

[pcasey92]

I was kind of thinking the same thing, but I’ve never had a problem with the power cable I’ve been using before, so I wasn’t sure. I’ll open up support access for the next few days in hopes we can figure this out. Thanks a lot. The UUID is fb1282d

I also just bought another power box to see if this will fix the issue easily. I will report back about whether this works or not.

[pcasey92]

While I am not getting the same error message about voltage on my screen as before, it is still failing to download the updates properly. Looks like every five to ten minutes, it shuts down and then restarts the download on it’s own.

[pdcastro]

@pcasey92, thanks for granting support access to the device. The device is indeed regularly rebooting – the host OS command prompt closed on me several times during the investigation, and every time the uptime command shows a short time since the last reboot.

The balena supervisor is regularly missing system watchdog health checks and crashing shortly before the device reboots, with logs like:

$ journalctl -au resin-supervisor --no-pager
...
Jul 05 23:11:18 fb1282d systemd[1]: resin-supervisor.service: Watchdog timeout (limit 3min)!
Jul 05 23:11:18 fb1282d systemd[1]: resin-supervisor.service: Killing process 1123 (start-resin-sup) with signal SIGABRT.
Jul 05 23:11:18 fb1282d systemd[1]: resin-supervisor.service: Killing process 1128 (exe) with signal SIGABRT.
Jul 05 23:11:18 fb1282d systemd[1]: resin-supervisor.service: Killing process 1233 (balena) with signal SIGABRT.
Jul 05 23:11:18 fb1282d systemd[1]: resin-supervisor.service: Killing process 1779 (resin-superviso) with signal SIGABRT.
Jul 05 23:11:18 fb1282d systemd[1]: resin-supervisor.service: Killing process 1782 (balena) with signal SIGABRT.
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: SIGABRT: abort
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: PC=0x6f47c m=0 sigcode=0
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: goroutine 0 [idle]:
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.futex(0x1cfe390, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1cfe390, 0x0, 0x0, 0x46724, ...)
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/sys_linux_arm.s:266 +0x1c
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.futexsleep(0x1cfe390, 0x0, 0xffffffff, 0xffffffff)
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/os_linux.go:45 +0x74
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.notesleep(0x1cfe390)
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/lock_futex.go:151 +0xac
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.stopm()
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/proc.go:1952 +0xac
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.findrunnable(0x13d43300, 0x0)
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/proc.go:2415 +0x378
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.schedule()
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/proc.go:2541 +0x110
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.goschedImpl(0x13d000e0)
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/proc.go:2619 +0xec
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.gopreempt_m(0x13d000e0)
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/proc.go:2647 +0x2c
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.newstack()
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/stack.go:1046 +0x224
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: runtime.morestack()
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: 	/usr/lib/go/src/runtime/asm_arm.s:419 +0x64
Jul 05 23:11:18 fb1282d resin-supervisor[1123]: goroutine 1 [select]:
Jul 05 23:11:19 fb1282d systemd[1]: resin-supervisor.service: Main process exited, code=killed, status=6/ABRT

The supervisor regularly crashes because… I suspect it is down to filesystem corruption, though I could not gather definitive evidence. The following command on the host OS is meant to test filesystem corruption, but it never completes (tried some 10 times) and, in fact, it appears that attempting to run this command brings forward the supervisor crash and system reboot:

md5sum --quiet -c /resinos.fingerprint

As if (“informed guess”) trying the filesystem check caused some system processes to access corrupt storage and then cause other processes to crash too. As far as informed guesses go, the earlier under voltage events (of which I still found some very few in the dmesg output) could have been a reason for filesystem corruption, which in turn causes the supervisor crash and system reboot.

So my recommendation at this point, to enable further investigation if nothing else, would be to try flashing a new SD card. Reflashing the current SD card may also work (filesystem corruption does not necessarily mean that the SD card is physically damaged, just that data got corrupted), but in order to also exclude the possibility of SD card damage, it would be better to use a card that is known to be OK.

[pcasey92]

Understood. I will first attempt to reflash it and see what that does for us. Thank you so much for your time. I’ll report back when I get back to this point.

[pcasey92]

Ok. So after reflashing the SD card that was being used, the same issues were coming up. I guess we can assume that this card is no longer functional. I do recall this SD card being used for signage before and an image crashed both the computer and the Pi in use. So maaaaaaybe that has something to do with this issue. I will have to purchase a new card and try again later.

[pcasey92]

Brand new, out of the package SD card and I’m still having the same problem.
I flashed it with it’s all new application, pushed screenly after it loaded into my dashboard and it is still stuck on that weird updating loop.
I am getting a message on my Pi screen that I haven’t seen before though.
[ 79.490669] IPv6 ADDRCONF(NETDEV_UP): supervisor0: link is not ready
[ 82.478649] IPv6 ADDRCONF(NETDEV_UP): br-72a1d351235a: link is not ready

Another thing that is kind of concering is when I plug the SD card back into my desktop, it saying the SD card needs repair. It did the same thing with my last SD card. I am always making sure to eject and remove the storage device properly, so I don’t know why this is a thing either.
I also tried using a different Pi device. Gave me the same problem as well.
For some reason or another, it’s not connecting properly. They’re both giving me the 4 blinking lights.
I don’t know if anyone wants to hop in, but the UFID for this one is e5a9c8b98f5ec630c53c4a8587006c0f

[pdcastro]

Thanks for granting support access to the newly flashed device (e5a9c8b) with a brand new SD card. I
see that it is a “Raspberry Pi 3 Model B Plus Rev 1.3”:

$ cat /sys/firmware/devicetree/base/model
Raspberry Pi 3 Model B Plus Rev 1.3

$ cat /proc/cpuinfo
...
Hardware	: BCM2835
Revision	: a020d3

I happen to have a Raspberry Pi of the exact same model and CPU here on my desk, so:

• I flashed it with balenaOS 2.38.0+rev1 (development), supervisor 9.15.7 (the same as your device).
• I set the Device Configuration variable RESIN_HOST_CONFIG_gpu_mem = 192 (the same as your device). The command “free” on the host OS shows the total memory capacity as “830644” KB, the same as your device.
• I followed the Balena Screenly blog. I pushed the project without changing a single line of it, literally running the following commands:

git clone git@github.com:Screenly/screenly-ose.git
cd screenly-ose
balena push test-rpi

(where “test-rpi” is the name of my balena application)

My result: the image was build and eventually downloaded on the device, from 0% to 100%, then eventually the “Running” status. No download loops, no supervisor crash, not any errors. Then I switched projects a few times to force image re-downloads, and still did not have any problems.

Could you confirm that you also followed the steps above, in particular the “git clone” and “balena push” without any code modifications?

Some additional details:

• My RPi did not have any HDMI cables connected, nor any other kind of screen. If you have a screen connected to your RPi, try disconnecting it in order to remove that “variable” too.
• I was running balena CLI version 11.5.0 on macOS. But even if you are running a different CLI version, perhaps on Windows, this wouldn’t normally explain the supervisor crashing.

I was going to suggest that you tried a different RPi device, but you’re saying that you’ve already tried that and the other RPi also “gives the same problem”? Do you mean that on the other RPi, you also see the following crash in the system logs every 10 minutes or so? -

$ journalctl -ab --no-pager
...
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Watchdog timeout (limit 3min)!
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Killing process 1958 (start-resin-sup) with signal SIGABRT.
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Killing process 1959 (exe) with signal SIGABRT.
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Killing process 2032 (balena) with signal SIGABRT.
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Killing process 2477 (resin-superviso) with signal SIGABRT.
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Killing process 2478 (balena) with signal SIGABRT.
Jul 06 16:40:22 e5a9c8b systemd[1]: resin-supervisor.service: Main process exited, code=killed, status=6/ABRT
Jul 06 16:41:52 e5a9c8b systemd[1]: resin-supervisor.service: State 'stop-final-sigterm' timed out. Killing.
Jul 06 16:41:52 e5a9c8b systemd[1]: resin-supervisor.service: Killing process 2032 (balena) with signal SIGKILL.
Jul 06 16:41:52 e5a9c8b systemd[1]: resin-supervisor.service: Failed with result 'watchdog'.
Jul 06 16:42:02 e5a9c8b systemd[1]: resin-supervisor.service: Service RestartSec=10s expired, scheduling restart.
Jul 06 16:42:02 e5a9c8b systemd[1]: resin-supervisor.service: Scheduled restart job, restart counter is at 2.
Jul 06 16:42:02 e5a9c8b systemd[1]: Stopped Resin supervisor.
Jul 06 16:42:02 e5a9c8b systemd[1]: Starting Resin supervisor...

(I got the output above from your device of UUID e5a9c8b.)

I am getting a message on my Pi screen that I haven’t seen before though.
[ 79.490669] IPv6 ADDRCONF(NETDEV_UP): supervisor0: link is not ready
[ 82.478649] IPv6 ADDRCONF(NETDEV_UP): br-72a1d351235a: link is not ready

I also initially get “link is not ready” on my device, but shortly after it changes to "device activated::

$ journalctl -ab --no-pager
...
Jul 06 16:22:38 6983a3f kernel[633]: [   17.942489] IPv6: ADDRCONF(NETDEV_UP): supervisor0: link is not ready
...
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.3927] device (supervisor0): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-st>
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4003] device (supervisor0): Activation: starting connection 'supervisor0' (b9e991e5-dc58-4591-a6ba-7c7843d7c279)
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4175] device (supervisor0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4298] device (supervisor0): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4370] device (supervisor0): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4395] device (supervisor0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4456] device (supervisor0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4475] device (supervisor0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
Jul 06 16:22:38 6983a3f NetworkManager[733]: <info>  [1562430158.4624] device (supervisor0): Activation: successful, device activated.

For some reason or another, it’s not connecting properly. They’re both giving me the 4 blinking lights.

Do you mean the LED pattern described on the following page as “Unable to connect to the Internet”?

Troubleshooting - Balena Documentation

If you are using WiFi, that LED pattern could be because, for example, the WiFi password was entered incorrectly. In this case, however, you would not see the app images downloading “between 20% and 99%”. The web dashboard should actually say that the device is offline.