OTA update failing with: Update was interrupted in state: update-store

We’re on mender client 2.0.0 and Open Source Server version 2.4. When doing an online update we occasionally get the failure below. Repeating the update after a failure is successful. I’m looking for a hint at what may have happened to cause this. Also, is this log a sign that the mender client restarted in the middle of storing the update?

2020-08-27 02:25:30 +0000 UTC info: Running Mender version 2.0.0-dirty
2020-08-27 02:25:30 +0000 UTC debug: handle update fetch state
2020-08-27 02:25:30 +0000 UTC debug: status reported, response 204 No Content
2020-08-27 02:25:30 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Date:[Thu, 27 Aug 2020 02:25:31 GMT] Last-Modified:[Mon, 01 Jun 2020 21:00:57 GMT] Accept-Ranges:[bytes] Content-Length:[145478144] Server:[AmazonS3] X-Amz-Id-2:[3s9mjKGpbc9CNnp/nuhjTzcxnMiTApMUvvmrv8vPE08yDYE170KPsFWe7RHSDS29W04DL/7OUww=] Etag:[“3d7810aac659d9fead4a3cab99e6f5db”] Content-Type:[application/vnd.mender-artifact] X-Amz-Request-Id:[E63553EBB20FFFCC]] 0x1175ea50 145478144 [] false false map[] 0x1167af00 0x119b4420}+
2020-08-27 02:25:30 +0000 UTC info: State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]
2020-08-27 02:25:30 +0000 UTC debug: handle update install state
2020-08-27 02:25:30 +0000 UTC debug: status reported, response 204 No Content
2020-08-27 02:25:30 +0000 UTC debug: Read data from device manifest file: device_type=pico-imx6ul
2020-08-27 02:25:30 +0000 UTC debug: Current manifest data: pico-imx6ul
2020-08-27 02:25:31 +0000 UTC info: installer: authenticated digital signature of artifact
2020-08-27 02:25:31 +0000 UTC debug: checking if device [pico-imx6ul] is on compatibile device list: [pico-imx6ul]
2020-08-27 02:25:31 +0000 UTC debug: installer: processing script: ArtifactCommit_Leave_50
2020-08-27 02:25:31 +0000 UTC debug: installer: processing script: ArtifactInstall_Leave_99
2020-08-27 02:25:31 +0000 UTC debug: installer: processing script: ArtifactReboot_Enter_50
2020-08-27 02:25:31 +0000 UTC debug: installer: processing script: ArtifactReboot_Leave_50
2020-08-27 02:25:31 +0000 UTC debug: Executing ModuleInstaller.Initialize
2020-08-27 02:25:31 +0000 UTC debug: Returning artifact name imx6ull-534 from database.
2020-08-27 02:25:31 +0000 UTC debug: Read data from device manifest file: artifact_name=imx6ull-534
2020-08-27 02:25:31 +0000 UTC debug: Read data from device manifest file: device_type=pico-imx6ul
2020-08-27 02:25:31 +0000 UTC debug: Current manifest data: pico-imx6ul
2020-08-27 02:25:31 +0000 UTC debug: installer: successfully read artifact [name: imx6ull_release-612; version: 3; compatible devices: [pico-imx6ul]]
2020-08-27 02:25:31 +0000 UTC debug: Executing ModuleInstaller.PrepareStoreUpdate
2020-08-27 02:25:31 +0000 UTC debug: Calling module: /usr/share/mender/modules/v3/rootfs-version-check Download /var/lib/mender/modules/v3/payloads/0000/tree
2020-08-27 02:25:31 +0000 UTC debug: Executing ModuleInstaller.StoreUpdate
2020-08-27 02:25:32 +0000 UTC info: Update module output: Allowing installation of imx6ull_release-612 over current version imx6ull-534.
2020-08-27 02:26:02 +0000 UTC info: Running Mender version 2.0.0-dirty
2020-08-27 02:26:02 +0000 UTC error: Update was interrupted in state: update-store
2020-08-27 02:26:02 +0000 UTC info: State transition: init [none] -> cleanup [Error]
2020-08-27 02:26:02 +0000 UTC debug: transitioning to error state
2020-08-27 02:26:02 +0000 UTC debug: Handling Cleanup state
2020-08-27 02:26:02 +0000 UTC debug: Executing ModuleInstaller.Cleanup
2020-08-27 02:26:02 +0000 UTC debug: Calling module: /usr/share/mender/modules/v3/rootfs-version-check Cleanup /var/lib/mender/modules/v3/payloads/0000/tree
2020-08-27 02:26:02 +0000 UTC info: State transition: cleanup [Error] -> update-status-report [none]
2020-08-27 02:26:02 +0000 UTC debug: handle update status report state
2020-08-27 02:26:03 +0000 UTC debug: status reported, response 204 No Content
2020-08-27 02:26:03 +0000 UTC debug: attempting to upload deployment logs for failed update

Also, is this log a sign that the mender client restarted in the middle of storing the update?

Exactly, Mender client restarting could also mean that the device restarted (e.g power-loss)

You can see a 30 second jump in the log here, which typically indicates a reset/reboot

@mirzak
Hi Mirza,

I just had 50 devices out of 61 fail with the following logs. We’re failing in update-store again and we can see that there is no power cycle in between.

2020-11-24 04:45:49 +0000 UTC info: Running Mender version 2.0.0-dirty
2020-11-24 04:45:49 +0000 UTC debug: handle update fetch state
2020-11-24 04:45:49 +0000 UTC debug: status reported, response 204 No Content
2020-11-24 04:45:49 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[X-Amz-Id-2:[A+q0xKufWjSkhR6ZVitQFdK2xoWNZ7Hbbb+jlgNPWnyo6B9F/d13zz2sftaCpJBYHEZs2KuQis8=] Last-Modified:[Mon, 09 Nov 2020 19:05:44 GMT] Etag:[“2a0293ba74679d1f25e6d05d82f34ba8-13”] Expires:[Mon, 09 Nov 2020 19:15:43 GMT] Accept-Ranges:[bytes] Content-Length:[134201856] Server:[AmazonS3] X-Amz-Request-Id:[E0CB940A6EC8FCC5] Date:[Tue, 24 Nov 2020 04:45:50 GMT] Content-Type:[application/vnd.mender-artifact]] 0x1235ffb0 134201856 [] false false map[] 0x1227b100 0x125f20c0}+
2020-11-24 04:45:49 +0000 UTC info: State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]
2020-11-24 04:45:49 +0000 UTC debug: handle update install state
2020-11-24 04:45:49 +0000 UTC debug: status reported, response 204 No Content
2020-11-24 04:45:49 +0000 UTC debug: Read data from device manifest file: device_type=pico-imx6ul
2020-11-24 04:45:49 +0000 UTC debug: Current manifest data: pico-imx6ul
2020-11-24 04:45:49 +0000 UTC info: installer: authenticated digital signature of artifact
2020-11-24 04:45:49 +0000 UTC debug: checking if device [pico-imx6ul] is on compatibile device list: [pico-imx6ul]
2020-11-24 04:45:49 +0000 UTC debug: installer: processing script: ArtifactCommit_Leave_50
2020-11-24 04:45:49 +0000 UTC debug: installer: processing script: ArtifactInstall_Leave_99
2020-11-24 04:45:49 +0000 UTC debug: installer: processing script: ArtifactReboot_Enter_50
2020-11-24 04:45:49 +0000 UTC debug: installer: processing script: ArtifactReboot_Leave_50
2020-11-24 04:45:49 +0000 UTC debug: Executing ModuleInstaller.Initialize
2020-11-24 04:45:49 +0000 UTC debug: Returning artifact name imx6ull-842 from database.
2020-11-24 04:45:49 +0000 UTC debug: Read data from device manifest file: artifact_name=imx6ull-842
2020-11-24 04:45:49 +0000 UTC debug: Read data from device manifest file: device_type=pico-imx6ul
2020-11-24 04:45:49 +0000 UTC debug: Current manifest data: pico-imx6ul
2020-11-24 04:45:49 +0000 UTC debug: installer: successfully read artifact [name: imx6ull_release_force-887; version: 3; compatible devices: [pico-imx6ul]]
2020-11-24 04:45:49 +0000 UTC debug: Executing ModuleInstaller.PrepareStoreUpdate
2020-11-24 04:45:49 +0000 UTC debug: Calling module: /usr/share/mender/modules/v3/rootfs-version-check Download /var/lib/mender/modules/v3/payloads/0000/tree
2020-11-24 04:45:49 +0000 UTC debug: Executing ModuleInstaller.StoreUpdate
2020-11-24 04:45:50 +0000 UTC info: Update module output: Allowing installation of imx6ull_release_force-887 over current version imx6ull-842.
2020-11-24 04:46:03 +0000 UTC info: Running Mender version 2.0.0-dirty
2020-11-24 04:46:03 +0000 UTC error: Update was interrupted in state: update-store
2020-11-24 04:46:03 +0000 UTC info: State transition: init [none] -> cleanup [Error]
2020-11-24 04:46:03 +0000 UTC debug: transitioning to error state
2020-11-24 04:46:03 +0000 UTC debug: Handling Cleanup state
2020-11-24 04:46:03 +0000 UTC debug: Executing ModuleInstaller.Cleanup
2020-11-24 04:46:03 +0000 UTC debug: Calling module: /usr/share/mender/modules/v3/rootfs-version-check Cleanup /var/lib/mender/modules/v3/payloads/0000/tree
2020-11-24 04:46:03 +0000 UTC info: State transition: cleanup [Error] -> update-status-report [none]
2020-11-24 04:46:03 +0000 UTC debug: handle update status report state
2020-11-24 04:46:03 +0000 UTC debug: status reported, response 204 No Content
2020-11-24 04:46:03 +0000 UTC debug: attempting to upload deployment logs for failed update

There is definitely a restart/reboot here

Does your Update Module reboot the system?