Rollback from time mismatch (no hardware clock) before time sync

General Discussions
17

Sorry to bump the thread, after addressing some serverside issues with an update to 2.5 I’m able to turn more attention to this issue, and am encountering more instances of the subject matter of this topic.

I am unable to access terminal output for affected devices, however I have more logs available which show more variations of the circumstances.

 2021-02-17 19:34:55 +0000 UTC debug: handle update fetch state
2021-02-17 19:34:55 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 19:34:55 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[X-Amz-Id-2:[jt61fWA0A35ckYUsLmhCDPcLxsoR3ZOvIPGyRInbQsEt9n6lbST4qoLO8kxQpg7VyBW4nXzYy7I=] Last-Modified:[Wed, 30 Sep 2020 22:34:10 GMT] Content-Type:[application/vnd.mender-artifact] Server:[AmazonS3] X-Amz-Request-Id:[676C7E3BF9646448] Date:[Wed, 17 Feb 2021 19:34:56 GMT] Etag:["c9afb6b53e4fa71fc72e8d45eb1f5b31"] Accept-Ranges:[bytes] Content-Length:[760966144]] 0x44201a9cc0 760966144 [] false false map[] 0x442000ab00 0x44204162c0}+
2021-02-17 19:34:55 +0000 UTC info: State transition: update-fetch [Download] -> update-store [Download]
2021-02-17 19:34:55 +0000 UTC debug: handle update install state
2021-02-17 19:34:56 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 19:34:56 +0000 UTC debug: Read data from device manifest file: device_type=dragonboard-410c
2021-02-17 19:34:56 +0000 UTC debug: Found needed line: device_type=dragonboard-410c
2021-02-17 19:34:56 +0000 UTC debug: Current manifest data: dragonboard-410c
2021-02-17 19:34:56 +0000 UTC info: installer: authenticated digital signature of artifact
2021-02-17 19:34:56 +0000 UTC debug: checking if device [dragonboard-410c] is on compatibile device list: [dragonboard-410c]
2021-02-17 19:34:56 +0000 UTC debug: installing update rpb-console-image-dragonboard-410c-20200930183743-IMM.LE.1.0-8x16_36900.rootfs.ext4 of size 3078619136
2021-02-17 19:34:56 +0000 UTC debug: Trying to install update of size: 3078619136
2021-02-17 19:34:56 +0000 UTC debug: Active partition: /dev/mmcblk0p11
2021-02-17 19:34:56 +0000 UTC debug: Detected inactive partition /dev/mmcblk0p12, based on active partition /dev/mmcblk0p11
2021-02-17 19:34:56 +0000 UTC info: opening device /dev/mmcblk0p12 for writing
2021-02-17 19:34:56 +0000 UTC info: partition /dev/mmcblk0p12 size: 3221225472
2021-02-17 20:40:42 +0000 UTC info: wrote 3078619136/3078619136 bytes of update to device /dev/mmcblk0p12
2021-02-17 20:40:45 +0000 UTC debug: installer: successfully read artifact [name: Miku_03.04.19; version: 2; compatible devices: [dragonboard-410c]]
2021-02-17 20:40:45 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:40:45 +0000 UTC info: State transition: update-store [Download] -> update-install [ArtifactInstall]
2021-02-17 20:40:45 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds
2021-02-17 20:40:45 +0000 UTC debug: start executing script: Download_Leave_03_pipe-copy
2021-02-17 20:40:45 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:40:46 +0000 UTC debug: start executing script: Download_Leave_04_net-copy
2021-02-17 20:40:46 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:40:46 +0000 UTC debug: start executing script: Download_Leave_05_update-request
2021-02-17 20:40:46 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:08 +0000 UTC debug: start executing script: Download_Leave_06_install-uboot-gpio-toggle
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: start executing script: Download_Leave_07_all-copy
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds
2021-02-17 20:50:09 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:09 +0000 UTC debug: Inactive partition: /dev/mmcblk0p12
2021-02-17 20:50:09 +0000 UTC debug: Marking inactive partition (/dev/mmcblk0p12) as the new boot candidate.
2021-02-17 20:50:09 +0000 UTC info: Enabling partition with new image installed to be a boot candidate: 12
2021-02-17 20:50:10 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
2021-02-17 20:50:10 +0000 UTC info: State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]
2021-02-17 20:50:10 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds
2021-02-17 20:50:10 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds
2021-02-17 20:50:10 +0000 UTC debug: handling reboot state
2021-02-17 20:50:10 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 20:50:10 +0000 UTC info: rebooting device
2021-02-17 20:50:10 +0000 UTC info: Mender rebooting from active partition: /dev/mmcblk0p11
1970-01-01 00:00:09 +0000 UTC info: Running Mender version 2.1.2
1970-01-01 00:00:09 +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:09 +0000 UTC info: State transition: init [none] -> after-reboot [ArtifactReboot_Leave]
1970-01-01 00:00:09 +0000 UTC debug: Have U-Boot variable: upgrade_available=1
1970-01-01 00:00:09 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:1]
1970-01-01 00:00:09 +0000 UTC info: State transition: after-reboot [ArtifactReboot_Leave] -> after-reboot [ArtifactReboot_Leave]
1970-01-01 00:00:09 +0000 UTC debug: handling state after reboot
1970-01-01 00:00:09 +0000 UTC info: State transition: after-reboot [ArtifactReboot_Leave] -> update-commit [ArtifactCommit_Enter]
1970-01-01 00:00:09 +0000 UTC debug: handle update commit state
1970-01-01 00:00:09 +0000 UTC error: failed to report status: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:00:09 +0000 UTC error: error reporting update status: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:00:09 +0000 UTC error: Failed to send status report to server: transient error: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:00:09 +0000 UTC info: State transition: update-commit [ArtifactCommit_Enter] -> update-pre-commit-status-report-retry [ArtifactCommit_Enter]
1970-01-01 00:03:09 +0000 UTC debug: wait complete
1970-01-01 00:03:09 +0000 UTC info: State transition: update-pre-commit-status-report-retry [ArtifactCommit_Enter] -> update-commit [ArtifactCommit_Enter]
1970-01-01 00:03:09 +0000 UTC debug: handle update commit state
1970-01-01 00:03:09 +0000 UTC error: failed to report status: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:03:09 +0000 UTC error: error reporting update status: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:03:09 +0000 UTC error: Failed to send status report to server: transient error: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:03:09 +0000 UTC info: State transition: update-commit [ArtifactCommit_Enter] -> update-pre-commit-status-report-retry [ArtifactCommit_Enter]
1970-01-01 00:06:09 +0000 UTC debug: wait complete
1970-01-01 00:06:09 +0000 UTC info: State transition: update-pre-commit-status-report-retry [ArtifactCommit_Enter] -> update-commit [ArtifactCommit_Enter]
1970-01-01 00:06:09 +0000 UTC debug: handle update commit state
1970-01-01 00:06:09 +0000 UTC error: failed to report status: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:06:09 +0000 UTC error: error reporting update status: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:06:09 +0000 UTC error: Failed to send status report to server: transient error: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:06:09 +0000 UTC info: State transition: update-commit [ArtifactCommit_Enter] -> update-pre-commit-status-report-retry [ArtifactCommit_Enter]
1970-01-01 00:09:09 +0000 UTC debug: wait complete
1970-01-01 00:09:09 +0000 UTC info: State transition: update-pre-commit-status-report-retry [ArtifactCommit_Enter] -> update-commit [ArtifactCommit_Enter]
1970-01-01 00:09:09 +0000 UTC debug: handle update commit state
1970-01-01 00:09:09 +0000 UTC error: failed to report status: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:09:09 +0000 UTC error: error reporting update status: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:09:09 +0000 UTC error: Failed to send status report to server: transient error: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
1970-01-01 00:09:09 +0000 UTC info: State transition: update-commit [ArtifactCommit_Enter] -> update-pre-commit-status-report-retry [ArtifactCommit_Enter]
1970-01-01 00:09:09 +0000 UTC error: transient error: Tried sending status report maximum number of times.
1970-01-01 00:09:09 +0000 UTC info: State transition: update-pre-commit-status-report-retry [ArtifactCommit_Enter] -> rollback [ArtifactRollback]
1970-01-01 00:09:09 +0000 UTC debug: transitioning to error state
1970-01-01 00:09:09 +0000 UTC info: performing rollback
1970-01-01 00:09:09 +0000 UTC debug: Have U-Boot variable: upgrade_available=1
1970-01-01 00:09:09 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:1]
1970-01-01 00:09:09 +0000 UTC debug: Active partition: /dev/mmcblk0p12
1970-01-01 00:09:09 +0000 UTC debug: Detected inactive partition /dev/mmcblk0p11, based on active partition /dev/mmcblk0p12
1970-01-01 00:09:09 +0000 UTC debug: Marking inactive partition (/dev/mmcblk0p11) as the new boot candidate.
1970-01-01 00:09:09 +0000 UTC info: setting partition for rollback: 11
1970-01-01 00:09:09 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
1970-01-01 00:09:09 +0000 UTC debug: will try to rollback reboot the device
1970-01-01 00:09:09 +0000 UTC info: State transition: rollback [ArtifactRollback] -> rollback-reboot [ArtifactRollbackReboot_Enter]
1970-01-01 00:09:09 +0000 UTC info: rebooting device(s) after rollback
1970-01-01 00:09:09 +0000 UTC info: Mender rebooting from inactive partition: /dev/mmcblk0p12
2021-02-17 20:50:16 +0000 UTC error: got invalid entrypoint into the state machine: state: reboot
2021-02-17 20:50:16 +0000 UTC info: State transition: init [none] -> update-error [ArtifactFailure]
2021-02-17 20:50:16 +0000 UTC debug: transitioning to error state
2021-02-17 20:50:16 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds
2021-02-17 20:50:16 +0000 UTC debug: handle update error state
2021-02-17 20:50:16 +0000 UTC info: State transition: update-error [ArtifactFailure] -> update-status-report [none]
2021-02-17 20:50:16 +0000 UTC debug: handle update status report state
2021-02-17 20:50:16 +0000 UTC error: failed to report status: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
2021-02-17 20:50:16 +0000 UTC error: error reporting update status: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
2021-02-17 20:50:16 +0000 UTC error: failed to send status to server: transient error: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
2021-02-17 20:50:16 +0000 UTC info: State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]
2021-02-17 20:50:16 +0000 UTC error: got invalid entrypoint into the state machine: state: update-status-report
2021-02-17 20:50:16 +0000 UTC info: State transition: init [none] -> update-error [ArtifactFailure]
2021-02-17 20:50:16 +0000 UTC debug: transitioning to error state
2021-02-17 20:50:16 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds
2021-02-17 20:50:16 +0000 UTC debug: handle update error state
2021-02-17 20:50:16 +0000 UTC info: State transition: update-error [ArtifactFailure] -> update-status-report [none]
2021-02-17 20:50:16 +0000 UTC debug: handle update status report state
2021-02-17 20:50:16 +0000 UTC error: failed to report status: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
2021-02-17 20:50:16 +0000 UTC error: error reporting update status: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
2021-02-17 20:50:16 +0000 UTC error: failed to send status to server: transient error: reporting status failed: Put https://mender.mikucloud.com/api/devices/v1/deployments/device/deployments/3907a02b-60f9-42d4-bd59-827203bf30c7/status: dial tcp: lookup mender.mikucloud.com on [::1]:53: server misbehaving
2021-02-17 20:50:16 +0000 UTC info: State transition: update-status-report [ArtifactFailure] -> update-retry-report [none]
2021-02-17 21:09:38 +0000 UTC debug: wait complete
2021-02-17 21:09:38 +0000 UTC info: State transition: update-retry-report [ArtifactFailure] -> update-status-report [ArtifactFailure]
2021-02-17 21:09:38 +0000 UTC debug: handle update status report state
2021-02-17 21:09:39 +0000 UTC debug: status reported, response 204 No Content
2021-02-17 21:09:39 +0000 UTC debug: attempting to upload deployment logs for failed update

We’ve made adjustments to the StateScriptRetryTimeout, and have wait-for-timesync in place. There are indications of configuration issues regarding statescript timeouts:

2021-02-17 20:50:16 +0000 UTC debug: statescript: timeout for executing scripts is not defined; using default of 60 seconds

Any further advisement would be appreciated.