Synchronous offline updates broken

Technical Support
, , , ,
2

Greetings @Ernest,

Looking through the code I can see a very niche case where this chain of events can happen. The only case where this can happen is if the new docker-compose file was written to the system, but it did not come from an update as far as the system can tell. Which explains why you noticed the OS portion of the update not rolling back as it should, since according to the system this doesn’t appear to be a synchronous update, just an OS update. Basically the file /var/sota/storage/docker-compose/docker-compose.yml exists on the system, yet somehow it got written without the flag for docker-compose update being set.

Looking at your logs before the reboot. There is obviously an issue with fetching your compose file from the Lockbox as indicated by these lines here:

Jan 17 14:32:51 verdin-imx8mm-07218224 aktualizr-torizon[853]: Initiating fetching of file docker-compose.lock.yml-2023-01-11-H15M29
Jan 17 14:32:51 verdin-imx8mm-07218224 aktualizr-torizon[853]: Unable to read filesystem statistics: error code -1

Seems like maybe an incomplete write occurred. Maybe /var/sota/storage/docker-compose/docker-compose.yml was only partially written in such a way that the file exists, but since it wasn’t a complete write the rest of the update failed. That might explain how the file exists but the update flag wasn’t set after the reboot.

My initial assumption here is that there’s some issue with your USB drive due to the log output: Unable to read filesystem statistics: error code -1

Now backing up a bit you said the OS and application portions of this update succeed individually correct? You only see this issue when combining them into a single Lockbox for a synchronous update, yes?

And does the issue happen every time? Even when you generate the Lockbox again from scratch? Also does this only happen with this specific Lockbox, or does it happen with any Lockbox you use?

Are you using the same USB drive for all these Lockboxes? Also what kind of filesystem is formatted on this USB drive?

Best Regards,
Jeremias

3

Hi @jeremias.tx,

Thanks for the timely reply.

I’ve performed each test in my original post with a fresh, but older, image, installed via TEZI. So the docker-compose file would not have been touched by an update yet, nor by anything else.

Yes, I only see this issue with synchronous updates. At first my concern was that the way I automate the lockbox creation on the Torizon Platform was wrong, since I just push both the OS and app update in a POST request without anything to indicate it’s a synchronous update. I can share this code if you want. But that’s the way I noticed my browser doing it also, and I’ve repeated all tests in the first post by manually initialising a lockbox on the platform and then generating it via TCB without any automation.

Yes, it happens every time. In fact, I’ve never gotten synchronous updates to work in the last few months. Even when I generate them from scratch. I will have to try different lockboxes generated from a different compose file. I’ve tested many lockboxes, but all with a similar compose file (just small edits as we update our applications, different mounts and permissions, an extra container, etc.).

I’ve used the same drive most of the time, but we have also used different drives to no avail. I’ve now reformatted the drive (FAT32 filesystem, same as before) and tried again, the same Unable to read filesystem statistics: error code -1 appears. But what’s interesting to me is that after the reboot, if I insert the drive again and the compose update begins, that error is not there. If it is a drive error, that surprises me. Relevant snippet from the start of that update procedure:

Sep 06 16:25:17 verdin-imx8mm-07218224 aktualizr-torizon[862]: Offline Updates are enabled
Sep 06 16:25:17 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: starting thread.
Sep 06 16:25:17 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: listening to connections...
Sep 06 16:30:21 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: unexpected error when waiting for data!
Sep 06 16:35:23 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: unexpected error when waiting for data!
Sep 06 16:40:25 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: unexpected error when waiting for data!
Sep 06 16:45:27 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: unexpected error when waiting for data!
Sep 06 16:50:29 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: unexpected error when waiting for data!
Sep 06 16:50:32 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: maximum epoll errors reached. Exiting thread!
Sep 06 16:50:32 verdin-imx8mm-07218224 aktualizr-torizon[862]: PROXY: sending device data to Torizon OTA.
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: fetchMetaOffUpd() called with source_path: "/media/JABBLA-USB/update/"
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Current version for ECU ID: f82e870baba06082c7755214c4de4edd1bf68e37aa9609dba72b680feeefe95f is unknown
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: New updates found in Director metadata. Checking Image repo metadata...
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: 1 new update found in both Director and Image repo metadata.
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Event: UpdateCheckComplete, Result - Updates available
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Update available. Acquiring the update lock...
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Current version for ECU ID: f82e870baba06082c7755214c4de4edd1bf68e37aa9609dba72b680feeefe95f is unknown
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Image already fetched; skipping fetching
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Event: DownloadTargetComplete, Result - Success
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Event: AllDownloadsComplete, Result - Success
Sep 06 17:59:48 verdin-imx8mm-07218224 aktualizr-torizon[862]: Current version for ECU ID: f82e870baba06082c7755214c4de4edd1bf68e37aa9609dba72b680feeefe95f is unknown
Sep 06 17:59:49 verdin-imx8mm-07218224 aktualizr-torizon[862]: Waiting for Secondaries to connect to start installation...
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: No update to install on Primary
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Event: InstallStarted
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Use existing SQL storage: "/var/sota/sql.db"
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: docker-compose file matches expected digest
Sep 06 17:59:50 verdin-imx8mm-07218224 aktualizr-torizon[862]: Loading metadata from tarball: /media/JABBLA-USB/update/images/acabe145ed192ce110dbb32b832730cba19b5eac77034748e8e055caa630af41.images/66cd4908444fd0a62337b8b87493ec19855b0c72747a60415d8cdb7ddc1d96ab.tar
Sep 06 18:00:05 verdin-imx8mm-07218224 aktualizr-torizon[2992]: Loaded image: jabbla/allora3-bt:digest_sha256_66cd4908444fd0a62337b8b87493ec19855b0c72747a60415d8cdb7ddc1d96ab
Sep 06 18:00:06 verdin-imx8mm-07218224 aktualizr-torizon[862]: Loading of "/media/JABBLA-USB/update/images/acabe145ed192ce110dbb32b832730cba19b5eac77034748e8e055caa630af41.images/66cd4908444fd0a62337b8b87493ec19855b0c72747a60415d8cdb7ddc1d96ab.tar" finished, code: 0, status: success
Sep 06 18:00:06 verdin-imx8mm-07218224 aktualizr-torizon[862]: Loading metadata from tarball: /media/JABBLA-USB/update/images/acabe145ed192ce110dbb32b832730cba19b5eac77034748e8e055caa630af41.images/eb8a8af46ce73a26a6f7fd3f6eaa794cd6e51df85b640dc0bc6c77b7ecbec443.tar

I have now repeated the process many times, formatting the drive each time, starting from a clean TorizonCore image (preprovisioned for offline updates and with our other changes) and the behaviour is exactly the same. I created the lockbox from scratch now, just applying my symlink patch. I’ve edited the update image to allow for persistent logging. This reveals more. Something does fail with the drive, but I do not think it is specific to my drive. The full, fairly large, log starting from when I inserted the drive (via a USB hub that plugs into our USB Type C port, but I’ve also tried with a normal USB Type C drive without the hub) is attached. These FAT errors do not appear to always be the same, as I’ve only noticed this one once before. But that might just be a measurement problem since it does seem to cause a kernel panic.

fat_failure_log.txt (101.7 KB)

I’ve also included the log from the following boot below, but only the aktualizr-torizon process as I didn’t spot any other relevant information. You can see that it detects an ‘incomplete update’ but after some time (this seems random) it decides to update the containers. This usually doesn’t happen so soon.

Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Aktualizr version 2020.8 starting
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Use existing SQL storage: "/var/sota/sql.db"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Couldn`t import data: empty path received
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Couldn't import client certificate: "/var/sota/import/client.pem" doesn't exist.
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Couldn't import server CA certificate: "/var/sota/import/root.crt" doesn't exist.
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Couldn't import client TLS key: "/var/sota/import/pkey.pem" doesn't exist.
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Initializing docker-compose Secondaries...
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Use existing SQL storage: "/var/sota/storage/docker-compose/sql.db"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: No valid metadata found in storage.
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Use existing SQL storage: "/var/sota/sql.db"
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Incomplete update detected.
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Rolling back container update
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Running docker-compose up
Jan 18 15:23:52 verdin-imx8mm-07276186 aktualizr-torizon[885]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml -p torizon up --detach --remove-orphans
Jan 18 15:23:55 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating network "torizon_default" with the default driver
Jan 18 15:23:56 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-skippy ...
Jan 18 15:23:56 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-mqtt   ...
Jan 18 15:23:56 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating siab           ...
Jan 18 15:23:56 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating weston         ...
Jan 18 15:23:58 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating weston         ... done
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-skippy ... done
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-mqtt   ... done
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-speech ...
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-bt     ...
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-web    ...
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-hw     ...
Jan 18 15:23:59 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-wifi   ...
Jan 18 15:24:01 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-bt     ... done
Jan 18 15:24:03 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-speech ... done
Jan 18 15:24:03 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-wifi   ... done
Jan 18 15:24:04 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating allora3-hw     ... done
Jan 18 15:24:04 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating torizon_kiosk_1 ...
Jan 18 15:24:06 verdin-imx8mm-07276186 aktualizr-torizon[925]: Creating torizon_kiosk_1 ... done
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Removing not used containers, networks and images
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Running command: docker system prune -a --force
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[1835]: Total reclaimed space: 0B
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Adding Secondary with ECU serial: 8cd554796e9284d802bbc588840c9ea14bdb240847ce7f73b86b6d44256da8eb with hardware ID: docker-compose
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Checking for a pending update to apply for Primary ECU
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Pending update for Primary ECU was found, trying to apply it...
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Checking installation of new OSTree sysroot
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Current versions in storage and reported by OSTree do not match
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: No ECU version report counter, please check the database!
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: Failed to store Secondary manifest: no more rows available
Jan 18 15:24:07 verdin-imx8mm-07276186 aktualizr-torizon[885]: curl error 3 (http code 0): URL using bad/illegal format or missing URL
Jan 18 15:24:08 verdin-imx8mm-07276186 aktualizr-torizon[885]: curl error 3 (http code 0): URL using bad/illegal format or missing URL
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: curl error 3 (http code 0): URL using bad/illegal format or missing URL
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: Put manifest request failed: 3 URL using bad/illegal format or missing URL HTTP 0
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: PROXY: initializing...
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: PROXY: using TCP port 8850.
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: Offline Updates are enabled
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: PROXY: starting thread.
Jan 18 15:24:09 verdin-imx8mm-07276186 aktualizr-torizon[885]: PROXY: listening to connections...
Jan 18 15:26:02 verdin-imx8mm-07276186 aktualizr-torizon[885]: fetchMetaOffUpd() called with source_path: "/media/JABBLA-USB/update/"
Jan 18 15:26:02 verdin-imx8mm-07276186 aktualizr-torizon[885]: Current version for ECU ID: 8cd554796e9284d802bbc588840c9ea14bdb240847ce7f73b86b6d44256da8eb is unknown
Jan 18 15:26:02 verdin-imx8mm-07276186 aktualizr-torizon[885]: New updates found in Director metadata. Checking Image repo metadata...
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: 1 new update found in both Director and Image repo metadata.
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Event: UpdateCheckComplete, Result - Updates available
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Update available. Acquiring the update lock...
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Current version for ECU ID: 8cd554796e9284d802bbc588840c9ea14bdb240847ce7f73b86b6d44256da8eb is unknown
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Image already fetched; skipping fetching
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Event: DownloadTargetComplete, Result - Success
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Event: AllDownloadsComplete, Result - Success
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Current version for ECU ID: 8cd554796e9284d802bbc588840c9ea14bdb240847ce7f73b86b6d44256da8eb is unknown
Jan 18 15:26:03 verdin-imx8mm-07276186 aktualizr-torizon[885]: Waiting for Secondaries to connect to start installation...
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: No update to install on Primary
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Event: InstallStarted
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Use existing SQL storage: "/var/sota/sql.db"
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: docker-compose file matches expected digest
Jan 18 15:26:04 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading metadata from tarball: /media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/66cd4908444fd0a62337b8b87493ec19855b0c72747a60415d8cdb7ddc1d96ab.tar
Jan 18 15:26:21 verdin-imx8mm-07276186 aktualizr-torizon[1939]: Loaded image: jabbla/allora3-bt:digest_sha256_66cd4908444fd0a62337b8b87493ec19855b0c72747a60415d8cdb7ddc1d96ab
Jan 18 15:26:21 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading of "/media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/66cd4908444fd0a62337b8b87493ec19855b0c72747a60415d8cdb7ddc1d96ab.tar" finished, code: 0, status: success
Jan 18 15:26:21 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading metadata from tarball: /media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/eb8a8af46ce73a26a6f7fd3f6eaa794cd6e51df85b640dc0bc6c77b7ecbec443.tar
Jan 18 15:26:33 verdin-imx8mm-07276186 aktualizr-torizon[1957]: Loaded image: jabbla/allora3-hw:digest_sha256_eb8a8af46ce73a26a6f7fd3f6eaa794cd6e51df85b640dc0bc6c77b7ecbec443
Jan 18 15:26:33 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading of "/media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/eb8a8af46ce73a26a6f7fd3f6eaa794cd6e51df85b640dc0bc6c77b7ecbec443.tar" finished, code: 0, status: success
Jan 18 15:26:33 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading metadata from tarball: /media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/e3119fbc75341e4ae07c6e10187534739973be5109b780d715e31d93a3105f76.tar
Jan 18 15:26:34 verdin-imx8mm-07276186 aktualizr-torizon[2004]: Loaded image: eclipse-mosquitto:digest_sha256_e3119fbc75341e4ae07c6e10187534739973be5109b780d715e31d93a3105f76
Jan 18 15:26:34 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading of "/media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/e3119fbc75341e4ae07c6e10187534739973be5109b780d715e31d93a3105f76.tar" finished, code: 0, status: success
Jan 18 15:26:34 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading metadata from tarball: /media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/32e21ceda65ee8082e24684f2560c914983eeb249110986f9a24eb755a0a3d0e.tar
Jan 18 15:26:54 verdin-imx8mm-07276186 aktualizr-torizon[2019]: Loaded image: jabbla/allora3-skippy:digest_sha256_32e21ceda65ee8082e24684f2560c914983eeb249110986f9a24eb755a0a3d0e
Jan 18 15:26:54 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading of "/media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/32e21ceda65ee8082e24684f2560c914983eeb249110986f9a24eb755a0a3d0e.tar" finished, code: 0, status: success
Jan 18 15:26:54 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading metadata from tarball: /media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/fb3135d78adef34128e8f00a33dd005573e0d7420e791a0255bf0be29a36c43c.tar
Jan 18 15:27:08 verdin-imx8mm-07276186 aktualizr-torizon[2092]: Loaded image: jabbla/allora3-speech:digest_sha256_fb3135d78adef34128e8f00a33dd005573e0d7420e791a0255bf0be29a36c43c
Jan 18 15:27:08 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading of "/media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/fb3135d78adef34128e8f00a33dd005573e0d7420e791a0255bf0be29a36c43c.tar" finished, code: 0, status: success
Jan 18 15:27:08 verdin-imx8mm-07276186 aktualizr-torizon[885]: Loading metadata from tarball: /media/JABBLA-USB/update/images/9e09b624ffc9ed5cfb13310d73da4a12d5f3b63f86e4de917fae840185cf7c67.images/d0b3d3bf914c481c4e640d37a46f5e5a5ffe213697fcccb49a1c6074bfbb110a.tar

Kind regards,

Ernest Van Hoecke

4

Okay so I went ahead and spent some time running further tests and trying to see if I can reproduce your issue here. In summary, I could not. Every offline synchronous update I attempted succeeded. Let me break down what I did.

  • Verdin i.MX8MM running TorizonCore 5.7.0
  • My Lockbox contained an OS update for version “5.7.1-devel-20220810+build.689”. Which came from our nightly feeds. The docker-compose portion doesn’t matter too much here but I used a simple container that prints a message then exits:
docker-compose.yml 
services:
  hello:
    image: torizon/testupdateapp@sha256:ce6dbed2add73347c3dc314fd1550cfc15e712717ff5765367d767b84794ce73
    scale: 1
version: '2.4'

I then offline provisioned my device and plugged in my USB containing the Lockbox. Here are my resulting logs:

Before Reboot 
Jan 01 00:03:25 verdin-imx8mm-06827778 systemd[1]: Started Aktualizr SOTA Client.
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Aktualizr version 2020.8 starting
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Bootstrap empty SQL storage
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Bootstraping DB to version 26
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Couldn`t import data: empty path received
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Couldn't import client certificate: "/var/sota/import/client.pem" doesn't exist.
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Couldn't import server CA certificate: "/var/sota/import/root.crt" doesn't exist.
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Couldn't import client TLS key: "/var/sota/import/pkey.pem" doesn't exist.
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Imported initial image root keys from "/var/sota/import/repo/root.json"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Imported initial director root keys from "/var/sota/import/director/root.json"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Initializing docker-compose Secondaries...
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: created: /var/sota/storage/docker-compose/metadata
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Bootstrap empty SQL storage
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Bootstraping DB to version 26
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: No valid metadata found in storage.
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Use existing SQL storage: "/var/sota/sql.db"
Jan 01 00:03:25 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Adding Secondary with ECU serial: ec9c2e240e9d27db9c7a57d8a1a861e3b73aabd59713ba3d1a5dca9568f30439 with hardware ID: docker-compose
Jan 01 00:03:26 verdin-imx8mm-06827778 aktualizr-torizon[1311]: PROXY: initializing...
Jan 01 00:03:26 verdin-imx8mm-06827778 aktualizr-torizon[1311]: PROXY: using TCP port 8850.
Jan 01 00:03:26 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Offline Updates are enabled
Jan 01 00:03:26 verdin-imx8mm-06827778 aktualizr-torizon[1311]: PROXY: starting thread.
Jan 01 00:03:26 verdin-imx8mm-06827778 aktualizr-torizon[1311]: PROXY: listening to connections...
Jan 01 00:03:48 verdin-imx8mm-06827778 aktualizr-torizon[1311]: fetchMetaOffUpd() called with source_path: "/media/COSTCO_USB/update/"
Jan 01 00:03:48 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Current version for ECU ID: 15e215bca62eff78f73374a08d955c2df86dffb403e14a1cb508524e0224930b is unknown
Jan 01 00:03:48 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Current version for ECU ID: ec9c2e240e9d27db9c7a57d8a1a861e3b73aabd59713ba3d1a5dca9568f30439 is unknown
Jan 01 00:03:48 verdin-imx8mm-06827778 aktualizr-torizon[1311]: New updates found in Director metadata. Checking Image repo metadata...
Jan 01 00:03:50 verdin-imx8mm-06827778 aktualizr-torizon[1311]: 2 new updates found in both Director and Image repo metadata.
Jan 01 00:03:50 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Event: UpdateCheckComplete, Result - Updates available
Jan 01 00:03:50 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Update available. Acquiring the update lock...
Jan 01 00:03:50 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Current version for ECU ID: 15e215bca62eff78f73374a08d955c2df86dffb403e14a1cb508524e0224930b is unknown
Jan 01 00:03:50 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Current version for ECU ID: ec9c2e240e9d27db9c7a57d8a1a861e3b73aabd59713ba3d1a5dca9568f30439 is unknown
Jan 01 00:03:52 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Performing a local pull from file:///media/COSTCO_USB/update/images/ostree
Jan 01 00:03:54 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: Writing objects: 7
Jan 01 00:03:55 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: Writing objects: 52
Jan 01 00:03:56 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: Writing objects: 25
Jan 01 00:03:57 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: Writing objects: 10
Jan 01 00:03:58 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: Writing objects: 4
Jan 01 00:04:00 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: Writing objects: 3
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: ostree-pull: 278 metadata, 1004 content objects imported
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Event: DownloadTargetComplete, Result - Success
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Initiating fetching of file update-tests.lock.yml_1.0
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Unable to read filesystem statistics: error code -1
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Event: DownloadProgressReport, Progress at 100%
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Event: DownloadTargetComplete, Result - Success
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Event: AllDownloadsComplete, Result - Success
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Current version for ECU ID: 15e215bca62eff78f73374a08d955c2df86dffb403e14a1cb508524e0224930b is unknown
Jan 01 00:04:02 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Current version for ECU ID: ec9c2e240e9d27db9c7a57d8a1a861e3b73aabd59713ba3d1a5dca9568f30439 is unknown
Jan 01 00:04:04 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Waiting for Secondaries to connect to start installation...
Jan 01 00:04:05 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Event: InstallStarted
Jan 01 00:04:05 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Installing package using ostree package manager
Jan 01 00:04:08 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Copying /etc changes: 5 modified, 2 removed, 12 added
Jan 01 00:04:15 verdin-imx8mm-06827778 aktualizr-torizon[1311]: Transaction complete; bootconfig swap: yes; deployment count change: 1
[  272.609671] imx2-wdt 30280000.watchdog: Device shutdown: Expect reboot!
[  272.616703] reboot: Restarting system
After Reboot 
Jan 01 00:00:16 verdin-imx8mm-06827778 systemd[1]: Started Aktualizr SOTA Client.
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Aktualizr version 2020.8 starting
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Use existing SQL storage: "/var/sota/sql.db"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Couldn`t import data: empty path received
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Couldn't import client certificate: "/var/sota/import/client.pem" doesn't exist.
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Couldn't import server CA certificate: "/var/sota/import/root.crt" doesn't exist.
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Couldn't import client TLS key: "/var/sota/import/pkey.pem" doesn't exist.
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Initializing docker-compose Secondaries...
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Use existing SQL storage: "/var/sota/storage/docker-compose/sql.db"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: No valid metadata found in storage.
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Use existing SQL storage: "/var/sota/sql.db"
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Finishing pending container updates via docker-compose
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Checking rollback status
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Running command: /usr/bin/fw_printenv rollback
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Running docker-compose down
Jan 01 00:00:16 verdin-imx8mm-06827778 aktualizr-torizon[871]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml -p torizon down
Jan 01 00:00:19 verdin-imx8mm-06827778 aktualizr-torizon[904]: Removing network torizon_default
Jan 01 00:00:19 verdin-imx8mm-06827778 aktualizr-torizon[904]: Network torizon_default not found.
Jan 01 00:00:19 verdin-imx8mm-06827778 aktualizr-torizon[871]: Running docker-compose up
Jan 01 00:00:19 verdin-imx8mm-06827778 aktualizr-torizon[871]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml.tmp -p torizon up --detach --remove-orphans
Jan 01 00:00:21 verdin-imx8mm-06827778 aktualizr-torizon[915]: Creating network "torizon_default" with the default driver
Jan 01 00:00:21 verdin-imx8mm-06827778 aktualizr-torizon[915]: Creating torizon_hello_1 ...
Jan 01 00:00:23 verdin-imx8mm-06827778 aktualizr-torizon[915]: Creating torizon_hello_1 ... done
Jan 01 00:00:23 verdin-imx8mm-06827778 aktualizr-torizon[871]: Removing not used containers, networks and images
Jan 01 00:00:23 verdin-imx8mm-06827778 aktualizr-torizon[871]: Running command: docker system prune -a --force
Jan 01 00:00:23 verdin-imx8mm-06827778 aktualizr-torizon[1051]: Deleted Containers:
Jan 01 00:00:23 verdin-imx8mm-06827778 aktualizr-torizon[1051]: 168a942793e9d6fa994721fdd614921df031bfddcd4d1c4f07fdf23eba549326
Jan 01 00:00:24 verdin-imx8mm-06827778 aktualizr-torizon[1051]: Deleted Networks:
Jan 01 00:00:24 verdin-imx8mm-06827778 aktualizr-torizon[1051]: torizon_default
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: Deleted Images:
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: torizon/testupdateapp:digest_sha256_0d0967edc753582bcf96c6933ae8824e06270ae9aba7e82aacd15cc286f29071
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:acf51f7a86bc0007080929ea8e352c059349079ba61a8edc28b692859a06f9fa
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:b7ad813d62f5d8be2afb88299bc81305a133bbcb653d5521b70b02c6403d2a65
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:6e9b2d2ac21bbe9e1eb9f2655634307230035679b749991646453c6940f4e213
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: portainer/portainer-ce:2.13.1
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: portainer/portainer-ce@sha256:52f9fdee1e4acfb1b5c4ddd15c88905287efb6e8f8058d2c5a2543ddc72e9dc0
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:ba1c6a880a3cace7ecda61ec0e27423734452fc1486049312588ab86eba5f2e2
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:6451099791957a76bec2efc019beff8f068eeae6426cb4ab1ead49ec326c16e1
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:7c7ac1e40924e1a857bca218ea9da787340892f832bee38c835dff8d5fdb4526
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:e0a46f5d05e1b93a7993c45aaea39729d111d7a096e02ac1656c721e39cb5222
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:8c004456aeb58b75f792fa091b194c20d6ed4f0d95dd25b0150d71c5c9ab601b
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: torizon/chromium:2
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: torizon/chromium@sha256:1736564d905555887426a983bc8dc3328a91105cbc48fdc54b87309e730ca84f
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:000ffa83b24320324c1fa924f48637931cb103dd9ef0388d2c7c71972ad918aa
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:ab722e1182675ea72d2bab5985b75590a20b5447001dbd3663f24a219da37de1
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:20abd42a65eb249333f1c29be91814fa1cdd9843f6bdae02dd27cbd8e2bd7784
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:f4c2dcdbf8e40568728b34e6621a0d40cd097cd0516e089c3f5202d994dba8b7
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:39a4dd5187d6bba9ec537449971a29b15dc1f80e73ef5f622fdbd256922128dc
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:617f4aef632dd87acecda451dda030502e64f2d765efc97a8cc407ac12432906
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:2db2e85294489631e2e977f5c44caa736d36a25247413c3d617c2a72bf733c23
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:19486d297e082e236cb612d6808a6b2451499ec7c52f09473d9633d2c206af35
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:27ef9b0da9fa86b59a435df755c436673a2f14ccd1e26d3cd8863ef634761745
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: torizon/weston-vivante:2
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: untagged: torizon/weston-vivante@sha256:8aab2dcc73fc45c429811235a38460992062f6023f9380d768d078f58a34ad50
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:717b9d1c7d4c6d76824e68515277f612d460e654e96979840639810b14dd35d7
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:54ddc53371ecadfc5ced98267a60b758868a6c8cc5582a649708067486197898
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:d0f563e60f6bee3042b3d782db44ebd65833850dd2d577ec8a56868e23df35f5
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:7de15409bfdbcccfc0b80820ac4798cf97ade692cedcf31fbd56f8d4d900a8f8
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:bfc4c7b21fa5373dfdf22fb77862ae632980655de292249a34398a6df7e3ee0d
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:a04f946791b5bb526fe58513b3216a98912b14376fd0953f4ed1e36e59dc0607
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:02964197bc30b905c4331aea55db23579b0dd89be51e82b46787e40d4f855e4f
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:533bcfc52a834e19b2243c504c4da8b4aac4a150fcc7d102478b923ec0023a6c
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:7abb24406e482604caed2337d7f6476dd02620663de29be0f2bdbfc72036c0aa
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:a13ebe552c3de4f1d08602e51f1d2d2837883fdaf3277959688c968eac0bc9a7
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:d7a1baab94112e8c4d6f22a7defd40cfec4789093a9b2b4fa946adbef1f1c122
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:07204d43bf26095f5e6bab072cee7ac534c91450768df0130896104cec3c1144
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:ee2e60f84c430ccd1fa8fd7f81a27e60b1b657eeac6019db92ead4512d932014
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:5ee1a6d9d7389876ed29ef492f8d4e56abef68850cab0530c2c0c1730a094a79
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:f32ce8d02c2f5bc6506d38e5db6dc9553db124c340104351d872ed3abccf9ebf
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:d0dc6be69490860f9759b6e01ae4cf74591e243a3f017578476098e16ae8e2f1
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:ccd1c77d968c28775cc26d41faef2c5f3b6711f68250bf425309335c8916fb19
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:b8f35974f0c0a50a260c7cc6233b22f399fe1cf51df7639d0b39308f50789902
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:e82e05abc97ff2c78c6e696be113df18f2fa997e3d4cf07f4d4f4d432c2790cf
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:4509513143fcf9a80054a6960e0bafe3b1dcfbd665262bd5e0ae5e88edc114a1
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:1dffccd84471ff29f623ae92804c24bb66f35862180ff9c6e02986ad1ce4eecc
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:234c4049dafd3877534bae06fcf9a0457f9c2af64a3ff687cf8ed89dfd7a832a
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:6ef060b9540c69fdcbdec3c597b2340f54e119916fbe4329ff0cc7944f20f948
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:13d2e0873f7aa2f499f54bc43297a39d7e57ece656c8567d4486bb30e15f52ad
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:f2fc21c6f89f532e86859c49bf41ba68763ed1ce3c5e748e01999f808d5e2ce0
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: deleted: sha256:62ed8ed20fdbb57a19639fc3a2dc8710dd66cb2364d61ec02e11cf9b35bc31dc
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[1051]: Total reclaimed space: 1.223GB
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: Adding Secondary with ECU serial: ec9c2e240e9d27db9c7a57d8a1a861e3b73aabd59713ba3d1a5dca9568f30439 with hardware ID: docker-compose
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: Checking for a pending update to apply for Primary ECU
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: Pending update for Primary ECU was found, trying to apply it...
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: Checking installation of new OSTree sysroot
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: PROXY: initializing...
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: PROXY: using TCP port 8850.
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: Offline Updates are enabled
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: PROXY: starting thread.
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: PROXY: listening to connections...
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: The current update is pending. Check if secondaries have already been updated
Jan 01 00:00:26 verdin-imx8mm-06827778 aktualizr-torizon[871]: The pending update Hash: 92E4BCE6FB908D801FC9E54C00B8F36A8A5830FD2F641BA6B192727CDB81169C has been installed on ec9c2e240e9d27db9c7a57d8a1a861e3b73aabd59713ba3d1a5dca9568f30439

As you can see before the reboot my logs look fairly similar to yours. I even found a USB drive that gave the same Unable to read filesystem statistics: error code -1 message. Though despite what I thought earlier this message doesn’t seem to indicate any major issue, as after the reboot my sync update finished installing properly as expected.

That said, there doesn’t seem to be an inherent issues with offline sync updates, they should work as intended. Now the question is why does it not work in your situation. Let’s see if we can get more information on what’s happening on your side.

  • First of all start with a freshly flashed TorizonCore.
  • Do the provisioning and other setup for offline updates as usual.
  • Run the commands detailed here: Aktualizr - Modifying the Settings of Torizon Update Client | Toradex Developer Center
    • This should disable the automatic reboot that occurs because of the OS update. This should allow us to poke around the system in the middle of the update process before the reboot.
  • With that done, go ahead and plug in your USB containing the Lockbox and monitor the logs.
    • Please provide the complete pre-reboot logs.
  • Once it looks like the logs have completed and the system is waiting for a reboot, I want you to poke around the system and get some information for me. Make sure to not reboot the system otherwise the update will try and complete
    • First what are the contents of this directory?: /var/sota/storage/docker-compose/
    • What are the contents of this file?: /var/sota/storage/docker-compose/docker-compose.yml.tmp
    • What is the output of sudo aktualizr-info?

Let’s start with that so I can try and get a better idea of what’s going on in your system while the update is happening. Then maybe we can narrow down a root cause.

Best Regards,
Jeremias

5

@Ernest, Actually disregard my last message.

I did further testing after I made my last post and I was finally able to reproduce your issue. In short there seems to be a sort of race condition occurring here. The race being the automatic reboot is happening before the docker-compose package finished installing. This is why you’re seeing the case where the new docker-compose file exists despite the update flag not being set. Basically the system is rebooting in the middle of the install process for the docker-compose package, leaving it in this weird state you see.

The reason I’m seeing this issue now is because I started to use bigger container images in my Lockbox. With bigger container images it takes more time for them to get unpacked from the Lockbox. Once the container images get too big the system can’t unpack them in time before the reboot occurs, which causes this race condition.

I appreciate you reporting this and bringing the issue to my attention. I’ll need to report this to our team for further investigation and fixing.

In the meantime there might be a workaround for you. This is the systemd service in TorizonCore that calls reboot after an OS update: meta-toradex-torizon/ostree-pending-reboot.service at kirkstone-6.x.y · toradex/meta-toradex-torizon · GitHub

You can try and modify the ExecStart command so that there is a delay before reboot is called. I haven’t tried this myself yet, but the idea is to delay the execution of the reboot command to give Aktualizr more time to properly finish.

Best Regards,
Jeremias

7

Hi @jeremias.tx,

Thanks a lot for your efforts and deeper investigation, I’m very glad you followed up and found the race condition before I had to run another batch of tests.

I’ll have to play around with that service to see if I can create a reliable workaround. Some quick tests show that it needs to be more than a few seconds in my case, so I don’t trust the reliability (yet).

Kind regards,
Ernest Van Hoecke

8

Some quick tests show that it needs to be more than a few seconds in my case, so I don’t trust the reliability (yet).

Yeah the workaround I suggested is not very precise as it relies on how big your container images are and how long it takes to unpack them from the Lockbox. Unfortunately I don’t have much of a better work-around at least until the team is able to investigate this issue further.

That said, if you find out anything else on your side please share as it could help our team with their investigations/fix.

Best Regards,
Jeremias

9

hello,
following the previous discussion for the offline updates, I am having the same issue with synchronous offline updates.
I’m not using the USB, I’m copying the lockbox via rsync and create a softlink to the folder containing the lockbox as suggested by Drew

11

Hi @RoccoBr,

The issue here is still fairly fresh only having been recently reported. Therefore there’s no formal solution yet from our team. The workaround I suggested previously is still the recommendation at the moment. If you can modify the reboot command used by the aforementioned systemd service to stall/delay the reboot then the issue should not occur. Pointing to a custom script instead of the reboot command might also offer better control of the issue rather than just adding a sleep or something similar.

Best Regards,
Jeremias

12

I’m confirming we’ve seen this issue too with larger (~500MB) container packages as part of the update.

13

For the purposes of the workaround, is there a good way to know at the OS level when the container update has been completed for the purpose of implementing a proper delay or wait script rather than guessing and hoping?

14

@bw908,

We actually have a new workaround now that should be a bit better than trying to guess an arbitrary delay.

You’ll want to create a new configuration file for Aktualizr as specified here: Aktualizr - Modifying the Settings of Torizon Update Client | Toradex Developer Center

The contents of this configuration file should look something like this:

[uptane]
force_install_completion = true

This enables a different reboot mechanism than what is currently used. With this the system should only reboot after all components in an update are done installing (i.e. docker-compose and OS). There are some minor bugs currently that make this method take a bit longer than it should before the system reboots. But these aren’t breaking bugs and only delay the reboot by a bit (on the scale of a few minutes).

Once that is done you need to also disable the current problematic reboot mechanism as shown here: Aktualizr - Modifying the Settings of Torizon Update Client | Toradex Developer Center

Best Regards,
Jeremias

2 Likes
15

I am pleased to report that the proposed workaround is working well.

1 Like
16

Thank you for confirming. A proper fix for this is planned to be released in the next TorizonCore 6.X Quarterly. We’re also discussing on back-porting the fix to a patch release of 5.7.Y if possible, though this decision isn’t final yet.

Best Regards,
Jeremias

1 Like
17

Hi @bw908 !

Could you please try using TorizonCore Monthly Release 6.2.0-devel-20230420+build.249

Please let us know the outcome :slight_smile:

Best regards,

EDIT: changed the recommendation to the latest nitghly just to be sure to grab the latest changes

18

Hi @henrique.tx ,

Have the devicetrees been updated for 6.x yet? When I last tried 6.1.x it was not possible to make any DTS modifications yet (Unable customize 6.1.0 or do any deploy on it)

19

HI @bw908,

You can now make use of device trees and overlays with TorizonCore Builder on TorizonCore 6.X. However, the workflow is a bit different now. The main difference is that you have to manually clone the overlay and device tree sources yourself instead of relying on the dt checkout command. This is documented and detailed here: Device Tree Overlays on Torizon | Toradex Developer Center

We realize this workflow is a bit clunky, especially compared to how it was before on 5.X. The team is working on improving this where possible, so this is a kind of stopgap workflow.

Best Regards,
Jeremias

20

Thanks - I will have a look soon since we are going to need 6.x shortly to bring up a board with a KSZ9897 DSA.

21

I just looked at the repository and the only available branches are for 5.6 and 5.7. Nothing for 6.x - so looks like it’s still unusable as far as I’m concerned.

22

I just looked at the repository and the only available branches are for 5.6 and 5.7. Nothing for 6.x - so looks like it’s still unusable as far as I’m concerned.

Did you read the entire section of the article I sent?

It states:

The device trees and overlays workflow is being reviewed. The torizoncore-builder dt checkout command is not available for TorizonCore 6 at the moment, and it may change or be deprecated. For TorizonCore 5, go to the corresponding version docs.

Then it shows you which repos need to be cloned:

### For i.MX 6/6ULL/7
$ git clone -b linux-6.0.y git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git
$ git clone -b master git://git.toradex.com/device-tree-overlays.git device-trees

### For i.MX 8/8X/8M Mini/8M Plus
$ git clone -b toradex_5.15-2.1.x-imx git://git.toradex.com/linux-toradex.git linux
$ git clone -b toradex_5.15-2.1.x-imx git://git.toradex.com/device-tree-overlays.git device-trees

The device-trees repo that you linked is only for TorizonCore 5.X.

Best Regards,
Jeremias

1 Like
23

OK, that does help. IMO the documentation could be improved by placing that info panel after the heading rather than its current placement (or linking both repositories in the snippet below), because it is off the bottom of the screen for a typical 1920x1080 resolution and the immediate sentence I saw and went to while skimming for a new repo URL was

Toradex provides source files of Device Trees and Device Tree Overlays for the add-on products available in the webshop. For information about these overlays, see the Toradex Device Tree Overlays repository on Github and …