Mender 2.2 Problem with mender-wait-for-timesync

Hi community!

My first post here, I appreciate the discussions here, very informative!

My problem is that I can’t do any updates anymore after moving from Mender 1.7 to Mender 2.2 due to the time-sync problem on raspberrypi when not having network directly. This was never an issue before, since mender-wait-for-timesync solved this perfectly.

I have not migrated client and server from 1.7 -> 2.2. I started from scratch on 2.2 and added my own layers back to the yocto build.

IMAGE_INSTALL_append = " … mender-wait-for-timesync"

I have the following polling variables

MENDER_UPDATE_POLL_INTERVAL_SECONDS = “180”
MENDER_INVENTORY_POLL_INTERVAL_SECONDS = “180”
MENDER_RETRY_POLL_INTERVAL_SECONDS = “240”

(still in the mender_%.bbappend file, not moved to mender.conf yet)

I am not sure why mender-wait-for-timesync doesn’t work anymore for updates. Is this correct?

I have noticed that mender-state-scripts functionality will do the trick. But I don’t know where to place it so it follows along with the mender artifact file after the yocto build. I would need some guidance here!

I read this post but it didn’t help me all the way.
https://hub.mender.io/t/mender-2-0-update-failure-because-wifi-network-not-immediately-available/711

Thanks,
Markus

Below is the log from the failed update:

Error log

2020-03-18 12:47:30 +0000 UTC info: Running Mender version 2.2.0
2020-03-18 12:47:30 +0000 UTC debug: handle update fetch state
2020-03-18 12:47:30 +0000 UTC debug: status reported, response 204 No Content
2020-03-18 12:47:30 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[125207552] Content-Security-Policy:[block-all-mixed-content] Content-Type:[application/vnd.mender-artifact] Date:[Wed, 18 Mar 2020 12:47:30 GMT] Etag:[“8a2acc6c14ad93b6ff6b21b37ace8929”] Last-Modified:[Wed, 18 Mar 2020 12:46:52 GMT] Server:[openresty/1.13.6.2] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] Vary:[Origin] X-Amz-Request-Id:[15FD66C7765EFD4D] X-Content-Type-Options:[nosniff] X-Frame-Options:[DENY] X-Xss-Protection:[1; mode=block]] 0x1b797a0 125207552 [] false false map[] 0x18a2e80 0x19aa420}+
2020-03-18 12:47:30 +0000 UTC info: State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]
2020-03-18 12:47:30 +0000 UTC debug: handle update install state
2020-03-18 12:47:31 +0000 UTC debug: status reported, response 204 No Content
2020-03-18 12:47:31 +0000 UTC debug: Read data from device manifest file: device_type=raspberrypi3
2020-03-18 12:47:31 +0000 UTC debug: Current manifest data: raspberrypi3
2020-03-18 12:47:31 +0000 UTC info: no public key was provided for authenticating the artifact
2020-03-18 12:47: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-03-18 12:47:31 +0000 UTC debug: checking if device [raspberrypi3] is on compatible device list: [raspberrypi3]
2020-03-18 12:47:31 +0000 UTC debug: installer: processing script: ArtifactCommit_Enter_10_wait-for-timesync
2020-03-18 12:47:31 +0000 UTC debug: installer: processing script: ArtifactCommit_Enter_10_migrate-configuration
2020-03-18 12:47:31 +0000 UTC debug: installer: successfully read artifact [name: yocto-vfb-warrior-lte-biz-3; version: 3; compatible devices: [raspberrypi3]]
2020-03-18 12:47:31 +0000 UTC debug: Active partition: /dev/mmcblk0p2
2020-03-18 12:47:31 +0000 UTC debug: Detected inactive partition /dev/mmcblk0p3, based on active partition /dev/mmcblk0p2
2020-03-18 12:47:31 +0000 UTC info: opening device /dev/mmcblk0p3 for writing
2020-03-18 12:47:31 +0000 UTC debug: Open block-device for installing update of size: 767557632
2020-03-18 12:47:31 +0000 UTC debug: Device: /dev/mmcblk0p3 is a ubi device: false
2020-03-18 12:47:31 +0000 UTC info: native sector size of block device /dev/mmcblk0p3 is 512, we will write in chunks of 1048576
2020-03-18 12:47:31 +0000 UTC debug: Opening device: /dev/mmcblk0p3 for writing with flag: 2
2020-03-18 12:51:26 +0000 UTC info: 0 bytes remaining to be written
2020-03-18 12:51:26 +0000 UTC info: The optimized block-device writer wrote a total of 733 frames, where 193 frames did need to be rewritten
2020-03-18 12:51:27 +0000 UTC info: Wrote 767557632/767557632 bytes to the inactive partition
2020-03-18 12:51:27 +0000 UTC debug: status reported, response 204 No Content
2020-03-18 12:51:27 +0000 UTC info: State transition: update-store [Download_Enter] -> update-after-store [Download_Leave]
2020-03-18 12:51:27 +0000 UTC info: State transition: update-after-store [Download_Leave] -> update-install [ArtifactInstall]
2020-03-18 12:51:27 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:27 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:27 +0000 UTC debug: status reported, response 204 No Content
2020-03-18 12:51:27 +0000 UTC debug: Inactive partition: /dev/mmcblk0p3
2020-03-18 12:51:27 +0000 UTC debug: Marking inactive partition (/dev/mmcblk0p3) as the new boot candidate.
2020-03-18 12:51:27 +0000 UTC info: Enabling partition with new image installed to be a boot candidate: 3
2020-03-18 12:51:27 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
2020-03-18 12:51:27 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
2020-03-18 12:51:27 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
2020-03-18 12:51:27 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
2020-03-18 12:51:27 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
2020-03-18 12:51:27 +0000 UTC info: State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]
2020-03-18 12:51:27 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:27 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:27 +0000 UTC debug: handling reboot state
2020-03-18 12:51:27 +0000 UTC debug: status reported, response 204 No Content
2020-03-18 12:51:27 +0000 UTC info: rebooting device(s)
2020-03-18 12:51:27 +0000 UTC info: Mender rebooting from active partition: /dev/mmcblk0p2
1970-01-01 00:00:19 +0000 UTC info: Running Mender version 2.2.0
1970-01-01 00:00:19 +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
1970-01-01 00:00:19 +0000 UTC info: State transition: init [none] -> after-reboot [ArtifactReboot_Leave]
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: upgrade_available=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:1]
1970-01-01 00:00:19 +0000 UTC info: State transition: after-reboot [ArtifactReboot_Leave] -> after-reboot [ArtifactReboot_Leave]
1970-01-01 00:00:19 +0000 UTC debug: handling state after reboot
1970-01-01 00:00:19 +0000 UTC info: State transition: after-reboot [ArtifactReboot_Leave] -> update-commit [ArtifactCommit_Enter]
1970-01-01 00:00:19 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
1970-01-01 00:00:19 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
1970-01-01 00:00:19 +0000 UTC debug: start executing script: ArtifactCommit_Enter_10_migrate-configuration
1970-01-01 00:00:19 +0000 UTC error: failed to report status: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
1970-01-01 00:00:19 +0000 UTC error: statescript: can not send start status to server: reporting status failed: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
1970-01-01 00:00:19 +0000 UTC error: failed to report status: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
1970-01-01 00:00:19 +0000 UTC error: statescript: can not send finished status to server: reporting status failed: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
1970-01-01 00:00:19 +0000 UTC error: transient error: error calling enter script for (error) update-commit state: error running enter state script(s) for ArtifactCommit_Enter state: statescript: error executing ‘ArtifactCommit_Enter_10_migrate-configuration’: 1 : exit status 1
1970-01-01 00:00:19 +0000 UTC info: State transition: update-commit [ArtifactCommit_Enter] -> rollback [ArtifactRollback]
1970-01-01 00:00:19 +0000 UTC debug: transitioning to error state
1970-01-01 00:00:19 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
1970-01-01 00:00:19 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
1970-01-01 00:00:19 +0000 UTC info: performing rollback
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: upgrade_available=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:1]
1970-01-01 00:00:19 +0000 UTC debug: Active partition: /dev/mmcblk0p3
1970-01-01 00:00:19 +0000 UTC debug: Detected inactive partition /dev/mmcblk0p2, based on active partition /dev/mmcblk0p3
1970-01-01 00:00:19 +0000 UTC debug: Marking inactive partition (/dev/mmcblk0p2) as the new boot candidate.
1970-01-01 00:00:19 +0000 UTC info: setting partition for rollback: 2
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
1970-01-01 00:00:19 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
1970-01-01 00:00:19 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
1970-01-01 00:00:19 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
1970-01-01 00:00:19 +0000 UTC debug: will try to rollback reboot the device
1970-01-01 00:00:19 +0000 UTC info: State transition: rollback [ArtifactRollback] -> rollback-reboot [ArtifactRollbackReboot_Enter]
1970-01-01 00:00:19 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
1970-01-01 00:00:19 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
1970-01-01 00:00:19 +0000 UTC info: rebooting device(s) after rollback
1970-01-01 00:00:19 +0000 UTC info: Mender rebooting from inactive partition: /dev/mmcblk0p3
2020-03-18 12:51:36 +0000 UTC info: Running Mender version 2.2.0
2020-03-18 12:51:36 +0000 UTC info: Update was interrupted in state: rollback-reboot
2020-03-18 12:51: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-03-18 12:51:37 +0000 UTC info: State transition: init [none] -> verify-rollback-reboot [ArtifactRollbackReboot_Leave]
2020-03-18 12:51:37 +0000 UTC debug: transitioning to error state
2020-03-18 12:51:37 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
2020-03-18 12:51:37 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
2020-03-18 12:51:37 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
2020-03-18 12:51:37 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
2020-03-18 12:51:37 +0000 UTC debug: Have U-Boot variable: upgrade_available=0
2020-03-18 12:51:37 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:0]
2020-03-18 12:51:37 +0000 UTC info: State transition: verify-rollback-reboot [ArtifactRollbackReboot_Leave] -> after-rollback-reboot [ArtifactRollbackReboot_Leave]
2020-03-18 12:51:37 +0000 UTC debug: handling state after rollback reboot
2020-03-18 12:51:37 +0000 UTC info: State transition: after-rollback-reboot [ArtifactRollbackReboot_Leave] -> update-error [ArtifactFailure]
2020-03-18 12:51:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:37 +0000 UTC debug: handle update error state
2020-03-18 12:51:37 +0000 UTC info: State transition: update-error [ArtifactFailure] -> cleanup [Error]
2020-03-18 12:51:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:37 +0000 UTC debug: Handling Cleanup state
2020-03-18 12:51:37 +0000 UTC info: State transition: cleanup [Error] -> update-status-report [none]
2020-03-18 12:51:37 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 1h0m0s seconds
2020-03-18 12:51:37 +0000 UTC debug: handle update status report state
2020-03-18 12:51:37 +0000 UTC error: failed to report status: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
2020-03-18 12:51:37 +0000 UTC error: error reporting update status: reporting status failed: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
2020-03-18 12:51:37 +0000 UTC error: failed to send status to server: transient error: reporting status failed: Put https:///api/devices/v1/deployments/device/deployments/69e7388a-d210-4042-bc9f-98c2e8f3dd7c/status: dial tcp: lookup on [2001:4860:4860::8888]:53: dial udp [2001:4860:4860::8888]:53: connect: network is unreachable
2020-03-18 12:51:37 +0000 UTC info: State transition: update-status-report [none] -> update-retry-report [none]
2020-03-18 12:53:04 +0000 UTC debug: wait complete
2020-03-18 12:53:04 +0000 UTC info: State transition: update-retry-report [none] -> update-status-report [none]
2020-03-18 12:53:04 +0000 UTC debug: handle update status report state
2020-03-18 12:53:05 +0000 UTC debug: status reported, response 204 No Content
2020-03-18 12:53:05 +0000 UTC debug: attempting to upload deployment logs for failed

Hi @markus4dev welcome to the discussions. Glad you find this info useful.

I don’t see any logs indicating that the wait-for-timesync state script is executing. I do see it running your ArtifactCommit_Enter_10_migrate-configuration script which returns a value of 1 that indicates failure causing a rollback. I think that is the issue here and if you resolve that, then Mender will call the timesync script as usual.

Drew

Thanks Drew! You put me on the right track! It was a dirty tmp folder where old migration script was in the mender-state-script folder.

/Markus

1 Like