OS Update Fails After Hanging at 50%.

Product support
1

I’m trying to update Balena OS on a rpi3 device and the update freezes at 50% and then fails after a long delay.

I can’t figure out why it’s not working. I tried rebooting the device, purging data, moving the device to an empty app with no services… nothing fixed the issue. I looked at the logs but I don’t see any obvious causes.

root@cd44093:~# journalctl -f
-- Logs begin at Sun 2020-08-16 10:31:39 UTC. --
Apr 27 20:11:20 cd44093 redsocks[1388]: 1619554280.137823 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:57062->52.55.60.119:443]: accepted
Apr 27 20:11:21 cd44093 redsocks[1388]: 1619554281.357814 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:55698->107.20.209.223:443]: connection closed
Apr 27 20:11:21 cd44093 redsocks[1388]: 1619554281.627490 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59492->18.209.132.178:443]: connection closed
Apr 27 20:11:22 cd44093 redsocks[1388]: 1619554282.013891 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:57062->52.55.60.119:443]: connection closed
Apr 27 20:11:25 cd44093 chronyd[1238]: 2021-04-27T20:11:25Z Selected source 94.130.49.186
Apr 27 20:11:30 cd44093 redsocks[1388]: 1619554290.145803 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:55710->107.20.209.223:443]: accepted
Apr 27 20:11:32 cd44093 sshd[2138]: error: Could not load host key: /etc/ssh/hostkeys/ssh_host_dsa_key
Apr 27 20:11:32 cd44093 redsocks[1388]: 1619554292.938656 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:55710->107.20.209.223:443]: connection closed
Apr 27 20:11:35 cd44093 sshd[2138]: Accepted publickey for root from 10.253.1.204 port 64273 ssh2: RSA SHA256:eOTg1eCVsaImU+sXoErVsOh5d0CQJQ9sGot46OWtm+0
Apr 27 20:11:40 cd44093 redsocks[1388]: 1619554300.990649 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:59504->18.209.132.178:443]: accepted
Apr 27 20:11:44 cd44093 redsocks[1388]: 1619554304.212792 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59504->18.209.132.178:443]: connection closed
Apr 27 20:12:20 cd44093 redsocks[1388]: 1619554340.033887 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59460->18.209.132.178:443]: connection closed
Apr 27 20:13:56 cd44093 balenad[1338]: time="2021-04-27T20:13:56.124084458Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/ed8c749d73fbb0e5b60161b3c79950a2c4ace661ea43a8438c26174bc6cf40cd.sock debug=false pid=2287
Apr 27 20:13:58 cd44093 balenad[1338]: time="2021-04-27T20:13:58.211807623Z" level=info msg="shim reaped" id=f222c8e584a744acd0c2c2b59f655cec6d191e3603b2190ea6dfb2c28f296ed1
Apr 27 20:13:58 cd44093 balenad[1338]: time="2021-04-27T20:13:58.222371637Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:15:56 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 9.359 ms
Apr 27 20:15:56 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 9.359 ms
Apr 27 20:16:59 cd44093 balenad[1338]: time="2021-04-27T20:16:59.655238155Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/2aff3d274833f1a0498221c4b3dbf304401c55e0cf4baa01fa7acd34dfc4689d.sock debug=false pid=2538
Apr 27 20:17:01 cd44093 balenad[1338]: time="2021-04-27T20:17:01.626084572Z" level=info msg="shim reaped" id=6aef6bf788d26c0f4022708f2bd75252b623969a876a2c52f088fe0ad57826e6
Apr 27 20:17:01 cd44093 balenad[1338]: time="2021-04-27T20:17:01.631964336Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:20:03 cd44093 balenad[1338]: time="2021-04-27T20:20:03.077600534Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/f8ef978c3e06ac3c741431bc94240cda9836119ed02d5d53a2b65f526807794c.sock debug=false pid=2695
Apr 27 20:20:05 cd44093 balenad[1338]: time="2021-04-27T20:20:05.131466149Z" level=info msg="shim reaped" id=be19050cf87a817aedd02bf4cb729e626679bed5bc1040356370cafb92303a7d
Apr 27 20:20:05 cd44093 balenad[1338]: time="2021-04-27T20:20:05.139406737Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:20:57 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 14.866 ms
Apr 27 20:20:57 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 14.866 ms
Apr 27 20:20:59 cd44093 3cdca6b90c30[1338]: [debug]   Attempting container log timestamp flush...
Apr 27 20:20:59 cd44093 resin-supervisor[1727]: [debug]   Attempting container log timestamp flush...
Apr 27 20:20:59 cd44093 resin-supervisor[1727]: [debug]   Container log timestamp flush complete
Apr 27 20:20:59 cd44093 3cdca6b90c30[1338]: [debug]   Container log timestamp flush complete
Apr 27 20:23:06 cd44093 balenad[1338]: time="2021-04-27T20:23:06.472627780Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/1a4e0f022aab72567ed35f7cbebae1620c89e2244d25146f1b02fb7fad8d077c.sock debug=false pid=2945
Apr 27 20:23:08 cd44093 balenad[1338]: time="2021-04-27T20:23:08.511883047Z" level=info msg="shim reaped" id=812fcb885e0d487e0936b9738ff64041da65ffab9519791452601bc4a9aa1bd5
Apr 27 20:23:08 cd44093 balenad[1338]: time="2021-04-27T20:23:08.520703162Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:25:33 cd44093 systemd-tmpfiles[3059]: [/etc/tmpfiles.d/openvpn.conf:1] Line references path below legacy directory /var/run/, updating /var/run/openvpn → /run/openvpn; please update the tmpfiles.d/ drop-in file accordingly.
Apr 27 20:25:34 cd44093 sh[3058]: Getting image name and tag...
Apr 27 20:25:34 cd44093 redsocks[1388]: 1619555134.260249 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:57086->52.55.60.119:443]: accepted
Apr 27 20:25:34 cd44093 sshd[3079]: error: Could not load host key: /etc/ssh/hostkeys/ssh_host_dsa_key
Apr 27 20:25:36 cd44093 sh[3058]: Supervisor configuration found from API.
Apr 27 20:25:36 cd44093 sh[3058]: Getting image id...
Apr 27 20:25:36 cd44093 sh[3058]: Supervisor registry2.balena-cloud.com/v2/e5a9b95f08373b03979ee007184e4753:latest already downloaded.
Apr 27 20:25:36 cd44093 redsocks[1388]: 1619555136.962819 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:57086->52.55.60.119:443]: connection closed
Apr 27 20:25:40 cd44093 sshd[3079]: Accepted publickey for root from 52.4.252.97 port 53354 ssh2: RSA SHA256:gMJ9LgzkTHsYjz4l3biYiuugYoYyRnQBGkMnNJhRqUQ
Apr 27 20:25:48 cd44093 redsocks[1388]: 1619555148.327485 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:59524->18.209.132.178:443]: accepted
Apr 27 20:25:51 cd44093 redsocks[1388]: 1619555151.090551 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59524->18.209.132.178:443]: connection closed
Apr 27 20:25:51 cd44093 redsocks[1388]: 1619555151.754036 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:57094->52.55.60.119:443]: accepted
Apr 27 20:25:54 cd44093 redsocks[1388]: 1619555154.188282 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:55742->107.20.209.223:443]: accepted
Apr 27 20:25:54 cd44093 redsocks[1388]: 1619555154.355799 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:57094->52.55.60.119:443]: connection closed
Apr 27 20:25:57 cd44093 redsocks[1388]: 1619555157.088365 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:55742->107.20.209.223:443]: connection closed
Apr 27 20:25:57 cd44093 redsocks[1388]: 1619555157.323179 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:59536->18.209.132.178:443]: accepted
Apr 27 20:25:58 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 10.593 ms
Apr 27 20:25:58 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 10.593 ms
Apr 27 20:26:00 cd44093 redsocks[1388]: 1619555160.616284 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59536->18.209.132.178:443]: connection closed
Apr 27 20:26:00 cd44093 redsocks[1388]: 1619555160.817695 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:57108->52.55.60.119:443]: accepted
Apr 27 20:26:03 cd44093 redsocks[1388]: 1619555163.463608 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:55862->52.205.74.65:443]: accepted
Apr 27 20:26:03 cd44093 redsocks[1388]: 1619555163.653808 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:57108->52.55.60.119:443]: connection closed
Apr 27 20:26:05 cd44093 redsocks[1388]: 1619555165.925574 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:55760->107.20.209.223:443]: accepted
Apr 27 20:26:06 cd44093 redsocks[1388]: 1619555166.379945 err redsocks.c:474 redsplice_write_cb(...) [10.128.34.172:55862->52.205.74.65:443]: shutdown(client, SHUT_WR): Transport endpoint is not connected
Apr 27 20:26:06 cd44093 redsocks[1388]: 1619555166.380102 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:55862->52.205.74.65:443]: connection closed
Apr 27 20:26:09 cd44093 redsocks[1388]: 1619555169.056284 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:55760->107.20.209.223:443]: connection closed
Apr 27 20:26:09 cd44093 redsocks[1388]: 1619555169.328137 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:59554->18.209.132.178:443]: accepted
Apr 27 20:26:09 cd44093 balenad[1338]: time="2021-04-27T20:26:09.990371592Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/20c62bbeae4c3142921e7bf13fec77e43091d0fc4b99e182dea1481f1674f5d8.sock debug=false pid=3391
Apr 27 20:26:12 cd44093 redsocks[1388]: 1619555172.066227 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59554->18.209.132.178:443]: connection closed
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.096405767Z" level=info msg="Starting up"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.105274007Z" level=info msg="libcontainerd: started new balena-engine-containerd process" pid=3498
Apr 27 20:26:12 cd44093 balenad[1338]: time="2021-04-27T20:26:12.192518393Z" level=info msg="shim reaped" id=9f0a10618ba159b4f86272776698b90bb1b9ab11f99abd613a43aa44e6c058cc
Apr 27 20:26:12 cd44093 balenad[1338]: time="2021-04-27T20:26:12.199439975Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.255169248Z" level=info msg="starting containerd" revision= version=1.2.0+unknown
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.256966427Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.258161369Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.aufs\"..." type=io.containerd.snapshotter.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.266577059Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.native\"..." type=io.containerd.snapshotter.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.267354556Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.overlayfs\"..." type=io.containerd.snapshotter.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.268319499Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.268484967Z" level=info msg="metadata content store policy set" policy=shared
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.272921092Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273092914Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273294268Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273449007Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273564319Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273660047Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273752130Z" level=info msg="loading plugin \"io.containerd.service.v1.leases-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273840671Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.273928015Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.274013275Z" level=info msg="loading plugin \"io.containerd.runtime.v1.linux\"..." type=io.containerd.runtime.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.274597803Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.275018270Z" level=info msg="loading plugin \"io.containerd.monitor.v1.cgroups\"..." type=io.containerd.monitor.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278042996Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278278828Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278489244Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278580701Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278666326Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278751430Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278841377Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.278931221Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279018616Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279103668Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279185542Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279320073Z" level=warning msg="failed to load plugin io.containerd.internal.v1.opt" error="mkdir /opt: read-only file system"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279395281Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279492416Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279581999Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.279663665Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.280524547Z" level=info msg=serving... address=/var/run/balena-host/containerd/balena-engine-containerd-debug.sock
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.280813868Z" level=info msg=serving... address=/var/run/balena-host/containerd/balena-engine-containerd.sock.ttrpc
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.281035690Z" level=info msg=serving... address=/var/run/balena-host/containerd/balena-engine-containerd.sock
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.281113242Z" level=info msg="containerd successfully booted in 0.046171s"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.319287023Z" level=warning msg="[graphdriver] WARNING: the aufs storage-driver is deprecated, and will be removed in a future release"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.333139406Z" level=warning msg="[graphdriver] WARNING: the aufs storage-driver is deprecated, and will be removed in a future release"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.538562150Z" level=warning msg="Your kernel does not support cgroup rt period"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.538776524Z" level=warning msg="Your kernel does not support cgroup rt runtime"
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.540227767Z" level=info msg="Loading containers: start."
Apr 27 20:26:12 cd44093 balenad[3484]: time="2021-04-27T20:26:12.894528830Z" level=info msg="Loading containers: done."
Apr 27 20:26:13 cd44093 balenad[3484]: time="2021-04-27T20:26:13.175734034Z" level=info msg="Docker daemon" commit=074a481789174b4b6fd2d706086e8ffceb72e924 graphdriver(s)=aufs version=19.03.13-dev
Apr 27 20:26:13 cd44093 balenad[3484]: time="2021-04-27T20:26:13.178199387Z" level=info msg="Daemon has completed initialization"
Apr 27 20:26:13 cd44093 balenad[3484]: time="2021-04-27T20:26:13.228562330Z" level=info msg="API listen on /var/run/balena-host.sock"
Apr 27 20:26:13 cd44093 redsocks[1388]: 1619555173.514795 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:51066->3.216.122.111:443]: accepted
Apr 27 20:26:17 cd44093 redsocks[1388]: 1619555177.022799 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:59562->18.209.132.178:443]: accepted
Apr 27 20:26:17 cd44093 redsocks[1388]: 1619555177.293647 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:51066->3.216.122.111:443]: connection closed
Apr 27 20:26:20 cd44093 redsocks[1388]: 1619555180.026138 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:51074->3.216.122.111:443]: accepted
Apr 27 20:26:20 cd44093 redsocks[1388]: 1619555180.241879 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59562->18.209.132.178:443]: connection closed
Apr 27 20:26:22 cd44093 redsocks[1388]: 1619555182.627529 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:51074->3.216.122.111:443]: connection closed
Apr 27 20:26:23 cd44093 redsocks[1388]: 1619555183.202435 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:51078->3.216.122.111:443]: accepted
Apr 27 20:26:25 cd44093 redsocks[1388]: 1619555185.304878 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:57140->52.55.60.119:443]: accepted
Apr 27 20:26:25 cd44093 redsocks[1388]: 1619555185.532929 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:51078->3.216.122.111:443]: connection closed
Apr 27 20:26:28 cd44093 redsocks[1388]: 1619555188.132225 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:51086->3.216.122.111:443]: accepted
Apr 27 20:26:28 cd44093 redsocks[1388]: 1619555188.305990 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:57140->52.55.60.119:443]: connection closed
Apr 27 20:26:30 cd44093 redsocks[1388]: 1619555190.996780 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:51090->3.216.122.111:443]: accepted
Apr 27 20:26:31 cd44093 redsocks[1388]: 1619555191.331572 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:51086->3.216.122.111:443]: connection closed
Apr 27 20:26:33 cd44093 redsocks[1388]: 1619555193.451108 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:59586->18.209.132.178:443]: accepted
Apr 27 20:26:33 cd44093 redsocks[1388]: 1619555193.529610 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:56356->54.230.183.73:443]: accepted
Apr 27 20:26:33 cd44093 redsocks[1388]: 1619555193.766358 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:51090->3.216.122.111:443]: connection closed
Apr 27 20:26:35 cd44093 redsocks[1388]: 1619555195.356339 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:59586->18.209.132.178:443]: connection closed
Apr 27 20:26:36 cd44093 redsocks[1388]: 1619555196.830210 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:56356->54.230.183.73:443]: connection closed
Apr 27 20:26:37 cd44093 redsocks[1388]: 1619555197.460958 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:53476->34.195.215.199:443]: accepted
Apr 27 20:26:40 cd44093 redsocks[1388]: 1619555200.015930 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:52254->54.230.183.39:443]: accepted
Apr 27 20:26:40 cd44093 redsocks[1388]: 1619555200.277127 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:53476->34.195.215.199:443]: connection closed
Apr 27 20:29:13 cd44093 balenad[1338]: time="2021-04-27T20:29:13.625059183Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/d08c86789cf33980df2b5a0a331b3edb9502e90c239f5b3ae920a6eec6fc582b.sock debug=false pid=3677
Apr 27 20:29:15 cd44093 balenad[1338]: time="2021-04-27T20:29:15.687920954Z" level=info msg="shim reaped" id=92f5b27e63950294e769e9afa0bbc69796c773ae74926c5f168b029b0d171be3
Apr 27 20:29:15 cd44093 balenad[1338]: time="2021-04-27T20:29:15.696738778Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:30:59 cd44093 3cdca6b90c30[1338]: [debug]   Attempting container log timestamp flush...
Apr 27 20:30:59 cd44093 resin-supervisor[1727]: [debug]   Attempting container log timestamp flush...
Apr 27 20:30:59 cd44093 3cdca6b90c30[1338]: [debug]   Container log timestamp flush complete
Apr 27 20:30:59 cd44093 resin-supervisor[1727]: [debug]   Container log timestamp flush complete
Apr 27 20:30:59 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 16.396 ms
Apr 27 20:30:59 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 16.396 ms
Apr 27 20:32:17 cd44093 balenad[1338]: time="2021-04-27T20:32:17.156587566Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/1648fe6353c6bfaebd026151f7ed753d986bf71ce8c80e3bb7cbb49bcee850b0.sock debug=false pid=3933
Apr 27 20:32:19 cd44093 balenad[1338]: time="2021-04-27T20:32:19.346523434Z" level=info msg="shim reaped" id=9313eb2b026389b1503a825b1e1a0e77425fa41db5f8c685dfebfde191feb65f
Apr 27 20:32:19 cd44093 balenad[1338]: time="2021-04-27T20:32:19.353011633Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:35:20 cd44093 balenad[1338]: time="2021-04-27T20:35:20.765167205Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/980f6a865d7d2429276988c599e36d459e2e3447e68c89181d05efbafa4c2b3c.sock debug=false pid=4087
Apr 27 20:35:22 cd44093 balenad[1338]: time="2021-04-27T20:35:22.882475442Z" level=info msg="shim reaped" id=ae8c48bba3d115304c77aa7fc0f245aa8f174e55ca7a6fc33c2dbbcef0bae2af
Apr 27 20:35:22 cd44093 balenad[1338]: time="2021-04-27T20:35:22.891723472Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:36:00 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 5.970 ms
Apr 27 20:36:00 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 5.970 ms
Apr 27 20:38:24 cd44093 balenad[1338]: time="2021-04-27T20:38:24.325710193Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/17770dac638e08a64aee59e2c5c50cef53a36bcd90823ced2cdf46e0570c32d6.sock debug=false pid=4335
Apr 27 20:38:26 cd44093 balenad[1338]: time="2021-04-27T20:38:26.429178182Z" level=info msg="shim reaped" id=5644e546c37a891dababee2c2737130837cfc64482ba7f10e3da4d4ee867ac60
Apr 27 20:38:26 cd44093 balenad[1338]: time="2021-04-27T20:38:26.436612626Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:40:18 cd44093 sshd[4451]: error: Could not load host key: /etc/ssh/hostkeys/ssh_host_dsa_key
Apr 27 20:40:21 cd44093 sshd[4451]: Accepted publickey for root from 10.253.1.204 port 31263 ssh2: RSA SHA256:eOTg1eCVsaImU+sXoErVsOh5d0CQJQ9sGot46OWtm+0
Apr 27 20:40:59 cd44093 resin-supervisor[1727]: [debug]   Attempting container log timestamp flush...
Apr 27 20:40:59 cd44093 resin-supervisor[1727]: [debug]   Container log timestamp flush complete
Apr 27 20:40:59 cd44093 3cdca6b90c30[1338]: [debug]   Attempting container log timestamp flush...
Apr 27 20:40:59 cd44093 3cdca6b90c30[1338]: [debug]   Container log timestamp flush complete
Apr 27 20:41:01 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 12.192 ms
Apr 27 20:41:01 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 12.192 ms
Apr 27 20:41:27 cd44093 balenad[1338]: time="2021-04-27T20:41:27.826119137Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/4dcd7f04213b88556b0adb61b352c1c46c75aeb14982b4857c1e1bf6b2511965.sock debug=false pid=4612
Apr 27 20:41:29 cd44093 balenad[1338]: time="2021-04-27T20:41:29.881084955Z" level=info msg="shim reaped" id=5b40ca458710f0b130b55a466cc6bec61329cbbc7bb5baba67231d70fdc63b62
Apr 27 20:41:29 cd44093 balenad[1338]: time="2021-04-27T20:41:29.888807315Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:42:17 cd44093 redsocks[1388]: 1619556137.209076 info redsocks.c:1254 redsocks_accept_client(...) [10.128.34.172:55820->107.20.209.223:443]: accepted
Apr 27 20:42:20 cd44093 redsocks[1388]: 1619556140.570795 info redsocks.c:682 redsocks_drop_client(...) [10.128.34.172:55820->107.20.209.223:443]: connection closed
Apr 27 20:44:31 cd44093 balenad[1338]: time="2021-04-27T20:44:31.281516155Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/e54dfb437cc4becc88048f3c96d0eaf4f8316b7be54afd2e1e63588942e6ae46.sock debug=false pid=4771
Apr 27 20:44:33 cd44093 balenad[1338]: time="2021-04-27T20:44:33.366441417Z" level=info msg="shim reaped" id=742990b97c11a600a6f1d1c970ae247b02081cfa0821a57448b518a2f2e73cc6
Apr 27 20:44:33 cd44093 balenad[1338]: time="2021-04-27T20:44:33.374457630Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:46:02 cd44093 3cdca6b90c30[1338]: [api]     GET /v1/healthy 200 - 12.172 ms
Apr 27 20:46:02 cd44093 resin-supervisor[1727]: [api]     GET /v1/healthy 200 - 12.172 ms
Apr 27 20:47:34 cd44093 balenad[1338]: time="2021-04-27T20:47:34.663170286Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/989da931446f72b4258f6f5093fa59451e4d565b972d82c681c1213f6d32dd54.sock debug=false pid=5015
Apr 27 20:47:36 cd44093 balenad[1338]: time="2021-04-27T20:47:36.767606187Z" level=info msg="shim reaped" id=18962191da58e54888ab8c1fa5c9255664879d26219759718982f4ee3eebde46
Apr 27 20:47:36 cd44093 balenad[1338]: time="2021-04-27T20:47:36.778551292Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Apr 27 20:50:38 cd44093 balenad[1338]: time="2021-04-27T20:50:38.198415891Z" level=info msg="shim balena-engine-containerd-shim started" address=/containerd-shim/02070580bc6fc5c38730a8515786041e573355b1b45d0008f7707566f598ce56.sock debug=false pid=5172
Apr 27 20:50:40 cd44093 balenad[1338]: time="2021-04-27T20:50:40.244770447Z" level=info msg="shim reaped" id=49b3769d361d5ac687f9348a2a11b967cd4f724682edae0949a07cb932a83737
Apr 27 20:50:40 cd44093 balenad[1338]: time="2021-04-27T20:50:40.252312756Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
2

Hi @nick-slocum, I’ve noticed the date in your logs is Sun 2020-08-16 10:31:39 . Is it possible there is an error with the time in your system?
It would be very helpful for us if you could run and attach the health checks and the diagnostics from the diagnostics tab.

Thanks,
Georgia

4

Hi Georgia,

That’s a good question.
I’m not sure why the logs start with:

-- Logs begin at Sun 2020-08-16 10:31:39 UTC. --

The system time looks correct:

root@cd44093:~# date
Wed Apr 28 12:36:10 UTC 2021

and the timestamps in the log entries have the correct UTC time.

After watching the device for a while, I’m not convinced the problem is with anything Balena related. This one device is taking a really long time to download updates for both the OS and the services. Do you have any suggestions on how to check the network connection quality?

thanks,
-Nick

5

Update:
I’m trying the methods described in this post: Smallest "speedtest" container

If that doesn’t find any likely causes, I’m going to figure out how to check the health of the SD card.

6

Hi @nick-slocum, let us know how it goes with these investigations. Sounds good to monitor the network speed as well as the SD card’s health.

You could run Device Diagnostics on the balena dashboard as they include SD cards check as well. Documentation: Check Descriptions - Balena Documentation

(in case you are wondering here is the code for these checks)

8

We replaced the device which fixed the problem.
Strangely, the old device is working fine now. The problem is probably hardware based, maybe a faulty connection or a intermittent issue with the rpi.