Idempotency of Mender config files migration scripts

General Discussions
21

Also:
Similar errors? But not the exact same?
Can you post the error here also?

22

Have these devices, at any point during the manufacturing run a different image with a Mender 1.7 client?

One thing to test, and this is not something that you should do on remote device as this is experimental, is to clear out the data store:

rm /var/lib/mender/mender-store

The Mender client will generate a new one.

23

Just to be 100% sure:
The manufacturing devices, they have not received an update previously?
They are straight off the production line?
All failing devices have NOT received updates, they are straight of the production line, and in need of updating, but fail to take an OTA update.

I will generate a log of a failure to OTA update one of these v1.1.0 devices using an artifact that is identical to the other update artifact, other than it has the migration script directives removed from the conf/local.conf.
NOTE, there will be no change to the target device, I will simply be removing the migration script directives from the artifact being OTA deployed to it.
I’ll get back to you as soon as I set up and run this test…

24

OTA update fails using artifact WITH migration script integrated (note, the target device is already on mender version 2.1, so migration is not actually required). This case fails pretty much immediately

2020-05-26 06:00:24 +0000 UTC info: Running Mender version 2.1.1-dirty
2020-05-26 06:00:24 +0000 UTC debug: handle update fetch state
2020-05-26 06:00:24 +0000 UTC debug: status reported, response 204 No Content
2020-05-26 06:00:29 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[46405120] Content-Security-Policy:[block-all-mixed-content] Content-Type:[application/vnd.mender-artifact] Date:[Tue, 26 May 2020 06:00:26 GMT] Etag:[“943be2fdae469c7f1316500eb5714da4”] Last-Modified:[Mon, 27 Apr 2020 00:09:53 GMT] Server:[openresty/1.13.6.2] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] Vary:[Origin] X-Amz-Request-Id:[16127E9BDDB2EB7A] X-Content-Type-Options:[nosniff] X-Frame-Options:[DENY] X-Xss-Protection:[1; mode=block]] 0x9a6c80 46405120 false false map 0x876400 0x866960}+
2020-05-26 06:00:29 +0000 UTC info: State transition: update-fetch [Download_Enter] → update-store [Download_Enter]
2020-05-26 06:00:30 +0000 UTC debug: handle update install state
2020-05-26 06:00:31 +0000 UTC debug: status reported, response 204 No Content
2020-05-26 06:00:31 +0000 UTC debug: Read data from device manifest file: device_type=beaglebone-yocto
2020-05-26 06:00:31 +0000 UTC debug: Current manifest data: beaglebone-yocto
2020-05-26 06:00:31 +0000 UTC info: no public key was provided for authenticating the artifact
2020-05-26 06:00:31 +0000 UTC info: Update Module path “/usr/share/mender/modules/v3” could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available
2020-05-26 06:00:31 +0000 UTC debug: checking if device [beaglebone-yocto] is on compatible device list: [beaglebone-yocto]
2020-05-26 06:00:31 +0000 UTC debug: installer: processing script: ArtifactCommit_Enter_10_migrate-configuration
2020-05-26 06:00:31 +0000 UTC debug: installer: successfully read artifact [name: 01-02-00; version: 2; compatible devices: [beaglebone-yocto]]
2020-05-26 06:00:31 +0000 UTC debug: Trying to install update of size: 394264576
2020-05-26 06:00:31 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
2020-05-26 06:00:31 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
2020-05-26 06:00:31 +0000 UTC debug: MARC - Test saveenv canary variables: map[mender_check_saveenv_canary:1]
2020-05-26 06:00:31 +0000 UTC error: Artifact install failed: Payload: can not install Payload: core-image-minimal-beaglebone-yocto.ext4: No match between boot and root partitions.: Failed mender_saveenv_canary check. There is an error in the U-Boot setup. Likely causes are: 1) Mismatch between the U-Boot boot loader environment location and the location specified in /etc/fw_env.config. 2) ‘mender_setup’ is not run by the U-Boot boot script: exit status 1
2020-05-26 06:00:31 +0000 UTC info: State transition: update-store [Download_Enter] → cleanup [Error]
2020-05-26 06:00:31 +0000 UTC debug: transitioning to error state
2020-05-26 06:00:31 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-26 06:00:31 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-26 06:00:31 +0000 UTC debug: Handling Cleanup state
2020-05-26 06:00:31 +0000 UTC info: State transition: cleanup [Error] → update-status-report [none]
2020-05-26 06:00:31 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-26 06:00:31 +0000 UTC debug: handle update status report state
2020-05-26 06:00:32 +0000 UTC debug: status reported, response 204 No Content
2020-05-26 06:00:32 +0000 UTC debug: attempting to upload deployment logs for failed update

OTA update fails using artifact WITHOUT migration script integrated (note, the target device is already on mender version 2.1, so migration is not actually required). This case will stream the entire artifact to ‘disk’, and attempt to reboot to the new image before failing

2020-05-27 06:15:20 +0000 UTC info: Running Mender version 2.1.1
2020-05-27 06:15:20 +0000 UTC debug: handle update fetch state
2020-05-27 06:15:20 +0000 UTC debug: status reported, response 204 No Content
2020-05-27 06:15:40 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[46146048] Content-Security-Policy:[block-all-mixed-content] Content-Type:[application/vnd.mender-artifact] Date:[Wed, 27 May 2020 06:15:37 GMT] Etag:[“1700f683644f7f1e7f81e6e24242201a”] Last-Modified:[Wed, 27 May 2020 05:49:48 GMT] Server:[openresty/1.13.6.2] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] Vary:[Origin] X-Amz-Request-Id:[1612CE0487D32ED0] X-Content-Type-Options:[nosniff] X-Frame-Options:[DENY] X-Xss-Protection:[1; mode=block]] 0xcbcc90 46146048 false false map 0x876380 0x866ba0}+
2020-05-27 06:15:40 +0000 UTC info: State transition: update-fetch [Download_Enter] → update-store [Download_Enter]
2020-05-27 06:15:40 +0000 UTC debug: handle update install state
2020-05-27 06:15:41 +0000 UTC debug: status reported, response 204 No Content
2020-05-27 06:15:41 +0000 UTC debug: Read data from device manifest file: device_type=beaglebone-yocto
2020-05-27 06:15:41 +0000 UTC debug: Current manifest data: beaglebone-yocto
2020-05-27 06:15:41 +0000 UTC info: no public key was provided for authenticating the artifact
2020-05-27 06:15:41 +0000 UTC info: Update Module path “/usr/share/mender/modules/v3” could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available
2020-05-27 06:15:41 +0000 UTC debug: checking if device [beaglebone-yocto] is on compatible device list: [beaglebone-yocto]
2020-05-27 06:15:41 +0000 UTC debug: installer: successfully read artifact [name: 01-02-01; version: 3; compatible devices: [beaglebone-yocto]]
2020-05-27 06:15:41 +0000 UTC debug: Trying to install update of size: 394264576
2020-05-27 06:15:41 +0000 UTC debug: Active partition: /dev/mmcblk1p2
2020-05-27 06:15:41 +0000 UTC debug: Detected inactive partition /dev/mmcblk1p3, based on active partition /dev/mmcblk1p2
2020-05-27 06:15:41 +0000 UTC info: native sector size of block device /dev/mmcblk1p3 is 512, we will write in chunks of 1048576
2020-05-27 06:15:47 +0000 UTC info: opening device /dev/mmcblk1p3 for writing
2020-05-27 06:15:47 +0000 UTC info: partition /dev/mmcblk1p3 size: 394264576
2020-05-27 07:52:10 +0000 UTC info: wrote 394264576/394264576 bytes of update to device /dev/mmcblk1p3
2020-05-27 07:52:17 +0000 UTC debug: status reported, response 204 No Content
2020-05-27 07:52:17 +0000 UTC info: State transition: update-store [Download_Enter] → update-after-store [Download_Leave]
2020-05-27 07:52:17 +0000 UTC info: State transition: update-after-store [Download_Leave] → update-install [ArtifactInstall]
2020-05-27 07:52:17 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:17 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:18 +0000 UTC debug: status reported, response 204 No Content
2020-05-27 07:52:18 +0000 UTC debug: Inactive partition: /dev/mmcblk1p3
2020-05-27 07:52:18 +0000 UTC debug: Marking inactive partition (/dev/mmcblk1p3) as the new boot candidate.
2020-05-27 07:52:18 +0000 UTC info: Enabling partition with new image installed to be a boot candidate: 3
2020-05-27 07:52:18 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
2020-05-27 07:52:18 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
2020-05-27 07:52:18 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
2020-05-27 07:52:18 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
2020-05-27 07:52:18 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
2020-05-27 07:52:18 +0000 UTC info: State transition: update-install [ArtifactInstall] → reboot [ArtifactReboot_Enter]
2020-05-27 07:52:18 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:18 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:18 +0000 UTC debug: handling reboot state
2020-05-27 07:52:18 +0000 UTC debug: status reported, response 204 No Content
2020-05-27 07:52:18 +0000 UTC info: rebooting device(s)
2020-05-27 07:52:18 +0000 UTC info: Mender rebooting from active partition: /dev/mmcblk1p2
2020-05-27 07:52:53 +0000 UTC info: Running Mender version 2.1.1
2020-05-27 07:52:53 +0000 UTC info: Update Module path “/usr/share/mender/modules/v3” could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available
2020-05-27 07:52:53 +0000 UTC error: Dual rootfs configuration not found when resuming update. Recovery may fail.
2020-05-27 07:52:53 +0000 UTC info: State transition: init [none] → after-reboot [ArtifactReboot_Leave]
2020-05-27 07:52:53 +0000 UTC error: transient error: Stub module: Cannot execute ArtifactVerifyReboot
2020-05-27 07:52:53 +0000 UTC info: State transition: after-reboot [ArtifactReboot_Leave] → rollback [ArtifactRollback]
2020-05-27 07:52:53 +0000 UTC debug: transitioning to error state
2020-05-27 07:52:53 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:53 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:53 +0000 UTC info: performing rollback
2020-05-27 07:52:53 +0000 UTC error: Unable to roll back with a stub module, but will try to reboot to restore state
2020-05-27 07:52:53 +0000 UTC debug: will try to rollback reboot the device
2020-05-27 07:52:53 +0000 UTC info: State transition: rollback [ArtifactRollback] → rollback-reboot [ArtifactRollbackReboot_Enter]
2020-05-27 07:52:53 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:53 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:52:53 +0000 UTC info: rebooting device(s) after rollback
2020-05-27 07:53:37 +0000 UTC info: Running Mender version 2.1.1
2020-05-27 07:53:37 +0000 UTC info: Update was interrupted in state: rollback-reboot
2020-05-27 07:53:37 +0000 UTC info: Update Module path “/usr/share/mender/modules/v3” could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available
2020-05-27 07:53:37 +0000 UTC info: State transition: init [none] → verify-rollback-reboot [ArtifactRollbackReboot_Leave]
2020-05-27 07:53:37 +0000 UTC debug: transitioning to error state
2020-05-27 07:53:37 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
2020-05-27 07:53:37 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
2020-05-27 07:53:37 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
2020-05-27 07:53:37 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
2020-05-27 07:53:37 +0000 UTC debug: Have U-Boot variable: upgrade_available=0
2020-05-27 07:53:37 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:0]
2020-05-27 07:53:37 +0000 UTC info: State transition: verify-rollback-reboot [ArtifactRollbackReboot_Leave] → after-rollback-reboot [ArtifactRollbackReboot_Leave]
2020-05-27 07:53:37 +0000 UTC debug: handling state after rollback reboot
2020-05-27 07:53:37 +0000 UTC info: State transition: after-rollback-reboot [ArtifactRollbackReboot_Leave] → update-error [ArtifactFailure]
2020-05-27 07:53:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:53:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:53:37 +0000 UTC debug: handle update error state
2020-05-27 07:53:37 +0000 UTC info: State transition: update-error [ArtifactFailure] → cleanup [Error]
2020-05-27 07:53:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:53:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:53:37 +0000 UTC debug: Handling Cleanup state
2020-05-27 07:53:37 +0000 UTC info: State transition: cleanup [Error] → update-status-report [none]
2020-05-27 07:53:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-05-27 07:53:37 +0000 UTC debug: handle update status report state
2020-05-27 07:53:54 +0000 UTC debug: status reported, response 204 No Content
2020-05-27 07:53:54 +0000 UTC debug: attempting to upload deployment logs for failed update

journalctl log for the above failure

.
.
.
May 27 06:15:20 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:20Z” level=info msg=“Correct request for getting image from: https://server.com:9000/mender-artifact-storage/7ed02137-b6cf-4316-850e-1afdbe69d5a3?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Content-Sha256=UNSIGNED-PAYLOAD&X-Amz-Credential=mender-deployments%2F20200527%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20200527T061520Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=396df5b1b48bd73d759525ed573ad4d38eb5d98635fc1297cae188bed42b4b24 [name: 01-02-01; devices: [beaglebone-yocto]]” module=client_update
May 27 06:15:20 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:20Z” level=info msg=“State transition: update-check [Sync] → update-fetch [Download_Enter]” module=mender
May 27 06:15:20 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:20Z” level=info msg=“Running Mender version 2.1.1” module=deployment_logger
May 27 06:15:40 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:40Z” level=info msg=“State transition: update-fetch [Download_Enter] → update-store [Download_Enter]” module=mender
May 27 06:15:41 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:41Z” level=info msg=“no public key was provided for authenticating the artifact” module=installer
May 27 06:15:41 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:41Z” level=info msg=“Update Module path "/usr/share/mender/modules/v3" could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available” module=modules
May 27 06:15:41 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:41Z” level=info msg=“native sector size of block device /dev/mmcblk1p3 is 512, we will write in chunks of 1048576” module=dual_rootfs_device
May 27 06:15:47 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:47Z” level=info msg=“opening device /dev/mmcblk1p3 for writing” module=block_device
May 27 06:15:47 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T06:15:47Z” level=info msg=“partition /dev/mmcblk1p3 size: 394264576” module=block_device
May 27 07:52:10 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:10Z” level=info msg=“wrote 394264576/394264576 bytes of update to device /dev/mmcblk1p3” module=dual_rootfs_device
May 27 07:52:17 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:17Z” level=info msg=“State transition: update-store [Download_Enter] → update-after-store [Download_Leave]” module=mender
May 27 07:52:17 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:17Z” level=info msg=“State transition: update-after-store [Download_Leave] → update-install [ArtifactInstall]” module=mender
May 27 07:52:18 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:18Z” level=info msg=“Enabling partition with new image installed to be a boot candidate: 3” module=dual_rootfs_device
May 27 07:52:18 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:18Z” level=info msg=“State transition: update-install [ArtifactInstall] → reboot [ArtifactReboot_Enter]” module=mender
May 27 07:52:18 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:18Z” level=info msg=“rebooting device(s)” module=state
May 27 07:52:18 redaptive-0c1c57f50f6a mender[4683]: time=“2020-05-27T07:52:18Z” level=info msg=“Mender rebooting from active partition: /dev/mmcblk1p2” module=dual_rootfs_device

Ultimately, the raised errors seem the same.

Oh, and I did a
rm /var/lib/mender/mender-store

…but realised no differing effect.

25

Why does the WITH case report Mender-version: 2.1.1-dirty
and the WITHOUT case not?

26

  1. The migration is a property of Yocto, not of Mender. The 1.7 client also supports split-mender-config files, so whether it’s running 1.7 or 2.1 is not important. The image that you get will be either a split-mender-config image or not. It seems like the image you start with does indeed have this enabled though, so this part is correct.

  2. However, the log that you posted seems to indicate that the image you are updating to does not have split-mender-config enabled, in other words it will not work for a device that already uses split-mender-config. This is apparent from this message:

    error: Dual rootfs configuration not found when resuming update. Recovery may fail.

    This message appears after the device has rebooted, and means that neither /etc/mender/mender.conf nor /data/mender/mender.conf contains any dual rootfs configuration. If you fix this Artifact to have split-mender-config set, but not mender-migrate-configuration, this should in theory work.

1 Like