Lockbox docker-compose update untagged the app container incorrectly

cifengfang · December 8, 2022, 7:06pm

Hi, I was trying to test out the secure offline update features with a lockbox to achieve containers update. The lockbox was recognized just fine from the aktualizr log, but it doesn’t do the custom app container update correctly.
For the weston and cog containers, I can see it removes the old images and containers and update docker-compose.yml to start the new containers, but for our custom app container, the update tool somehow just removed the new images and keep the old one, while it modifies the docker-compose to start the new one (which is removed by the tool actually). As a result, the update doesn’t reboot at the end, and once I force reboot the device the container failed to start.

Please see the aktualizr-torizon log for details:

– Logs begin at Thu 1970-01-01 00:00:06 UTC. –

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Certificate issuer: CN=ota-devices-CA

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Certificate valid from: Dec 2 23:45:47 2022 GMT until: Nov 8 23:45:47 2121 GMT

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: initializing…

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: using TCP port 8850.

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Offline Updates are enabled

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: starting thread.

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: listening to connections…

Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete

Dec 08 02:52:40 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.

Dec 08 02:52:40 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: fetchMetaOffUpd() called with source_path: “/media/usb1/update”

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Current version for ECU ID: 918af54786776b6feed7cccb0d3b9626a9b28e22de5584fb6a249a4a572b865e is unknown

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: New updates found in Director metadata. Checking Image repo metadata…

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: 1 new update found in both Director and Image repo metadata.

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: UpdateCheckComplete, Result - Updates available

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Update available. Acquiring the update lock…

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Current version for ECU ID: 918af54786776b6feed7cccb0d3b9626a9b28e22de5584fb6a249a4a572b865e is unknown

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Image already fetched; skipping fetching

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: DownloadTargetComplete, Result - Success

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: AllDownloadsComplete, Result - Success

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Current version for ECU ID: 918af54786776b6feed7cccb0d3b9626a9b28e22de5584fb6a249a4a572b865e is unknown

Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Waiting for Secondaries to connect to start installation…

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: No update to install on Primary

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: InstallStarted

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: “/etc/sota/conf.d/100-offline-updates.toml”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: “/usr/lib/sota/conf.d/20-sota-device-cred.toml”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: “/usr/lib/sota/conf.d/30-rollback.toml”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: “/usr/lib/sota/conf.d/40-hardware-id.toml”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: “/usr/lib/sota/conf.d/50-secondaries.toml”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: “/usr/lib/sota/conf.d/60-polling-interval.toml”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Use existing SQL storage: “/var/sota/sql.db”

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: docker-compose file matches expected digest

Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading metadata from tarball: /media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2.tar

Dec 08 02:55:50 colibri-imx8x-06787895 aktualizr-torizon[1391]: Loaded image: cifengfang/cxldnabit-release:digest_sha256_68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2

Dec 08 02:55:50 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading of “/media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2.tar” finished, code: 0, status: success

Dec 08 02:55:50 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading metadata from tarball: /media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf.tar

Dec 08 02:57:40 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.

Dec 08 03:01:41 colibri-imx8x-06787895 aktualizr-torizon[1422]: Loaded image: therndgroup/kiosk-mode-browser-vivante-cog:digest_sha256_29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf

Dec 08 03:01:42 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading of “/media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf.tar” finished, code: 0, status: success

Dec 08 03:01:42 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading metadata from tarball: /media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45.tar

Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[1477]: Loaded image: torizon/weston-vivante:digest_sha256_b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45

Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading of “/media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45.tar” finished, code: 0, status: success

Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Updating containers via docker-compose

Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Running docker-compose down

Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml -p torizon down

Dec 08 03:05:10 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_web …

Dec 08 03:05:10 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_kiosk …

Dec 08 03:05:10 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_weston …

Dec 08 03:05:12 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_web … done

Dec 08 03:05:13 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_kiosk … done

Dec 08 03:05:13 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_weston … done

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_web …

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_kiosk …

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_weston …

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_weston … done

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_web … done

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_kiosk … done

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[950]: Running docker-compose up

Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[950]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml.tmp -p torizon up --detach --remove-orphans

Dec 08 03:05:18 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_weston …

Dec 08 03:05:20 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_weston … done

Dec 08 03:05:20 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_kiosk …

Dec 08 03:05:23 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_kiosk … done

Dec 08 03:05:23 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_web …

Dec 08 03:05:25 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_web … done

Dec 08 03:05:26 colibri-imx8x-06787895 aktualizr-torizon[950]: Removing not used containers, networks and images

Dec 08 03:05:26 colibri-imx8x-06787895 aktualizr-torizon[950]: Running command: docker system prune -a --force

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: Deleted Images:

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: untagged: cifengfang/cxldnabit-release:digest_sha256_68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: untagged: torizon/weston-vivante:2.5.1

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: Total reclaimed space: 0B

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: InstallTargetComplete, Result - Success

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: AllInstallsComplete, Result - OK

Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[950]: Update install completed. Releasing the update lock…

Dec 08 03:05:28 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete

Dec 08 03:05:31 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.

Dec 08 03:05:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete

Dec 08 03:07:40 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.

Dec 08 03:07:40 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete

jeremias.tx · December 8, 2022, 7:31pm

Greetings @cifengfang,

The issue you’re experiencing here sounds like what happened on this thread here: Offline Docker Compose updates do not tag images properly, docker-compose fails after successful update

Ultimately the issue is due to a bug with Docker where the “incorrect” container image gets pruned sometimes. But, just to make sure it really is the same issue, can you describe to me your exact process leading up to this.

If I understand your general process it went something like:

You started with a TorizonCore image that had your containers pre-loaded correct?
Then you performed an offline update to update just the containers.

Did I get the general idea?

If yes, then I have further questions:

What is the exact process you did to produce the TorizonCore image with your containers pre-loaded?
After booting this TorizonCore image with your containers pre-loaded what is the output of docker images on your system?
The offline update you were applying, were all 3 containers being changed in the update? Or were some going to stay the same?
After the failed offline update what is the output of docker images on your system?

Best Regards,
Jeremias

cifengfang · December 8, 2022, 8:03pm

Hi @jeremias.tx. Yes, I flashed a custom TorizonCore image, and all the containers pre-loaded were started correctly. I did do some docker-compose.yml file edits (remove the “port:” section to resolve app container network setting conflicts) to fix the container starting issue. After I make sure the containers autoboot correctly, I tried to perform the lockbox update for all three containers (weston, cog, and custom app, but it’s actually some containers on the device as I’m just quick testing it).
This is the docker ps result before the lockbox update:

And this is after the lockbox update:

Thanks for pointing me to the thread already been resolved. I think I’m also facing the same issues with using non-canonical docker-compose files to generate the bundle folder. If I understand your explanation correctly if the container to be updated has the same tag as existing containers, this container mis-untagge issue can happen, the best way to avoid this is to use sha-key to tag the containers?

cifengfang · December 8, 2022, 8:22pm

Hi @jeremias.tx. I have another question about the lockbox definition. How should I write the docker-compose.yml so that I’m only updating the custom app container? Should I just include the docker-compose config line for the new custom app container only?

Thanks for your help!

jeremias.tx · December 8, 2022, 8:38pm

Basically, so as an example imagine a compose file like so:

version: '2.4'

services:
  foo: 
    image: hello-world:latest

If you bundle the file as is without canonicalizing it first then on the system you’ll see this:

REPOSITORY          TAG                 IMAGE ID            CREATED             SIZE
hello-world         latest              46331d942d63        7 months ago        9.14kB

This makes sense the container image has the tag latest which matches the source compose file. Now let’s say we do an offline update but we’re not changing this container image. During the process of the offline update the system will end up like this:

REPOSITORY          TAG                                                                              IMAGE ID            CREATED             SIZE
hello-world         digest_sha256_432f982638b3aefab73cc58ab28f5c16e96fdb504e8c134fc58dff4bae8bf338   46331d942d63        7 months ago        9.14kB
hello-world         latest                                                                           46331d942d63        7 months ago        9.14kB

Now we have 2 container images that are the same (same “IMAGE ID”), but with different tags. One tag came from the initial bundling and the other came from the Lockbox. The problem is now due to that Docker bug I mentioned the “wrong” image gets removed which is the one that came from the Lockbox. Even though they’re the same image the issue as you noted is that the compose file references the image using the digest_sha256_432f982638b3aefab73cc58ab28f5c16e96fdb504e8c134fc58dff4bae8bf338 tag. This will cause docker-compose to fail cause it can’t find this tag.

To get around this what you want to do is use a canonicalized version of the compose file in the initial bundling stage. So let’s say we instead use the canonicalized form of the compose file like so:

services:
  foo:
    image: hello-world@sha256:18a657d0cc1c7d0678a3fbea8b7eb4918bba25968d3e1b0adebfa71caddbc346
version: '2.4'

If you do the bundle this time now the following shows up on the system:

REPOSITORY          TAG                 IMAGE ID            CREATED             SIZE
hello-world         <none>              46331d942d63        7 months ago        9.14kB

Now the container image doesn’t have any tag. This changes the behavior when an offline update is performed. If we do the same offline update in this scenario docker is smart enough to see the no-tag image is the same as the container image in the Lockbox, so this happens:

REPOSITORY          TAG                                                                              IMAGE ID            CREATED             SIZE
hello-world         digest_sha256_432f982638b3aefab73cc58ab28f5c16e96fdb504e8c134fc58dff4bae8bf338   46331d942d63        7 months ago        9.14kB

Unlike the previous case Docker won’t make another copy of the same image and instead just overwrite the existing copy with the new tag from the Lockbox. Now since there’s only 1 copy of this container image on the system the Docker bug can’t be confused and remove the “wrong” image.

I hope that helps somewhat clear up the issue, it’s a very strange interaction.

How should I write the docker-compose.yml so that I’m only updating the custom app container? Should I just include the docker-compose config line for the new custom app container only?

If you want to update the container image just upload a new compose file that’s pointing to the new container image for your application. Then when the Lockbox is created it will download the container images as they are defined in the compose file.

The update process completely replaces the compose file on the system with the new compose file. So you need to provide the entire compose file even if it’s just a one line change.

Best Regards,
Jeremias