Update fails on error: got invalid entrypoint into the state machine: state: update-store

aps · April 1, 2020, 11:27am

Mender downloads te artifact fine but when it starts after reboot I get log below. I dont have no idea where to start looking.

br,
AP

2020-04-01 10:46:23 +0000 UTC debug: handle update fetch state
2020-04-01 10:46:23 +0000 UTC debug: status reported, response 204 No Content
2020-04-01 10:46:24 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Content-Type:[application/vnd.mender-artifact] Connection:[keep-alive] Vary:[Origin] X-Xss-Protection:[1; mode=block] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] X-Frame-Options:[DENY] Accept-Ranges:[bytes] Content-Security-Policy:[block-all-mixed-content] Last-Modified:[Wed, 01 Apr 2020 09:32:33 GMT] X-Amz-Request-Id:[1601AC60CCD4F7C5] X-Content-Type-Options:[nosniff] Server:[openresty/1.13.6.2] Content-Length:[210984448] Date:[Wed, 01 Apr 2020 10:47:55 GMT] Etag:[“6c30ed82193ad15358277efeccff163e”]] 0x1b14590 210984448 [] false false map[] 0x1812a80 0x1c881e0}+
2020-04-01 10:46:24 +0000 UTC info: State transition: update-fetch [Download] -> update-store [Download]
2020-04-01 10:46:24 +0000 UTC debug: handle update install state
2020-04-01 10:46:24 +0000 UTC debug: status reported, response 204 No Content
2020-04-01 10:46:24 +0000 UTC debug: Read data from device manifest file: device_type=raspberrypi3
2020-04-01 10:46:24 +0000 UTC debug: Found needed line: device_type=raspberrypi3
2020-04-01 10:46:24 +0000 UTC debug: Current manifest data: raspberrypi3
2020-04-01 10:46:24 +0000 UTC info: installer: authenticated digital signature of artifact
2020-04-01 10:46:24 +0000 UTC debug: checking if device [raspberrypi3] is on compatibile device list: [raspberrypi3]
2020-04-01 10:46:24 +0000 UTC debug: installer: processing script: ArtifactFailure_Enter_10
2020-04-01 10:46:24 +0000 UTC debug: installing update rpi-bf-image-raspberrypi3.ext4 of size 2000683008
2020-04-01 10:46:24 +0000 UTC debug: Trying to install update of size: 2000683008
2020-04-01 10:46:24 +0000 UTC debug: Active partition: /dev/mmcblk0p2
2020-04-01 10:46:24 +0000 UTC debug: Detected inactive partition /dev/mmcblk0p3, based on active partition /dev/mmcblk0p2
2020-04-01 10:46:24 +0000 UTC info: opening device /dev/mmcblk0p3 for writing
2020-04-01 10:46:24 +0000 UTC info: partition /dev/mmcblk0p3 size: 2000683008
2020-04-01 10:59:51 +0000 UTC info: wrote 2000683008/2000683008 bytes of update to device /dev/mmcblk0p3
2020-04-01 10:59:53 +0000 UTC debug: installer: successfully read artifact [name: tc-0.11.0-20200401-110156; version: 2; compatible devices: [raspberrypi3]]
2020-04-01 10:59:54 +0000 UTC debug: status reported, response 204 No Content
2020-04-01 10:59:54 +0000 UTC info: State transition: update-store [Download] -> update-install [ArtifactInstall]
2020-04-01 10:59:54 +0000 UTC debug: start executing script: Download_Leave_10
2020-04-01 10:59:54 +0000 UTC debug: status reported, response 204 No Content
2020-04-01 11:01:36 +0000 UTC error: got invalid entrypoint into the state machine: state: update-store
2020-04-01 11:01:36 +0000 UTC info: State transition: init [none] -> update-error [ArtifactFailure]
2020-04-01 11:01:36 +0000 UTC debug: transitioning to error state
2020-04-01 11:01:36 +0000 UTC debug: start executing script: ArtifactFailure_Enter_10
2020-04-01 11:01:36 +0000 UTC error: got unexpected HTTP status when reporting status: 400
2020-04-01 11:01:36 +0000 UTC error: statescript: can not send start status to server: (request_id: ): reporting status failed, bad status 400 server error message: unknown status value
2020-04-01 11:01:39 +0000 UTC error: got unexpected HTTP status when reporting status: 400
2020-04-01 11:01:39 +0000 UTC error: statescript: can not send finished status to server: (request_id: ): reporting status failed, bad status 400 server error message: unknown status value
2020-04-01 11:01:39 +0000 UTC debug: handle update error state
2020-04-01 11:01:39 +0000 UTC info: State transition: update-error [ArtifactFailure] -> update-status-report [none]
2020-04-01 11:01:39 +0000 UTC debug: handle update status report state
2020-04-01 11:01:39 +0000 UTC debug: status reported, response 204 No Content
2020-04-01 11:01:39 +0000 UTC debug: attempting to upload deployment logs for failed update

oleorhagen · April 1, 2020, 2:19pm

Just to establish a baseline, could you list the version your on?

aps · April 1, 2020, 2:25pm

Sorry, raspberry pi 3 + and mender 1.7 with own mender server

mirzak · April 1, 2020, 2:27pm

Can you also get the serial console output from the device?

2020-04-01 11:01:36 +0000 UTC error: got invalid entrypoint into the state machine: state: update-store

This typically means that a roll-back was performed in U-Boot because e.g it could not load the Linux kernel or something along those lines.

aps · April 1, 2020, 2:33pm

I can boot to updated partition setting fw_setenv mender_boot_part 3 there are no problems booting that partition. It is as good as new. works beautifully.

oleorhagen · April 2, 2020, 4:46am

And this exact same thing happens every time you try the udpate?

aps · April 2, 2020, 5:27am

Yes, every time. I had it working few months ago. I have not done anything to the u-boot. It is stock u-boot provided by mender. I don’t have access to the serial port so debugging is quite hard. I have no idea where to start looking what is going on.

br
AP Sihvonen

oleorhagen · April 2, 2020, 7:49am

That is odd indeed.

To expand on this a bit.

The invalid entrypoint into the state-machine error, means that the client started anew, with data showing that it got killed during an update run.

From the log you posted, if it is indeed the exact similar every time, it looks to me, like the client dies in Download Leave every time. How does the Download_leave_10 script look?

aps · April 2, 2020, 8:58am

Download_leave_10 wait user action to approve the update and sit in the loop and the device is rebooted elsewhere. However, I tried update without that and it did not help. In fact I removed all of the statescripts.

Have to look into fw_env if there is something wrong. Do you know where I can find working set off fw.

mirzak · April 2, 2020, 9:04am

I do not think anything is wrong the fw_env, as @oleorhagen pointed out, this is very strange behavior.

Something happens in Download_Leave_10 that “disables” the Mender client and it comes back 30 seconds later. This is also what a reboot might look like, so if your script Download_Leave_10 actually runs reboot command or reboot is run elsewhere while the Mender client is in Download_Leave_10, that would explain things. You need to pass control back to the Mender client when you think it is appropriate to reboot.

Also Download_Leave is probably not the correct state to do this, and more appropriate would be ArtifactReboot_Enter.

Can you share the errors you see when you have removed the state scripts from your Artifacts? Please also confirm that the Artifact does not have any statescripts by running mender-artifact read on it.

aps · April 2, 2020, 11:44am

Hello,
I removed all statescripts from partition that is about to be upgraded. The mender file contained Download_Leav_10 and ArtifactFailure_Enter_10. The logs looked pretty much the same

2020-04-02 11:07:49 +0000 UTC debug: handle update fetch state
2020-04-02 11:07:49 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:07:49 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[X-Amz-Request-Id:[1601FC0B65C41F8F] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] Server:[openresty/1.13.6.2] Content-Security-Policy:[block-all-mixed-content] Last-Modified:[Wed, 01 Apr 2020 09:32:33 GMT] Date:[Thu, 02 Apr 2020 11:07:49 GMT] X-Xss-Protection:[1; mode=block] X-Frame-Options:[DENY] Content-Length:[210984448] Etag:["6c30ed82193ad15358277efeccff163e"] Vary:[Origin] X-Content-Type-Options:[nosniff] Content-Type:[application/vnd.mender-artifact] Connection:[keep-alive] Accept-Ranges:[bytes]] 0x1b7ccf0 210984448 [] false false map[] 0x1a30380 0x1cc4ba0}+
2020-04-02 11:07:49 +0000 UTC info: State transition: update-fetch [Download] -> update-store [Download]
2020-04-02 11:07:49 +0000 UTC debug: handle update install state
2020-04-02 11:07:49 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:07:49 +0000 UTC debug: Read data from device manifest file: device_type=raspberrypi3
2020-04-02 11:07:49 +0000 UTC debug: Found needed line: device_type=raspberrypi3
2020-04-02 11:07:49 +0000 UTC debug: Current manifest data: raspberrypi3
2020-04-02 11:07:49 +0000 UTC info: installer: authenticated digital signature of artifact
2020-04-02 11:07:49 +0000 UTC debug: checking if device [raspberrypi3] is on compatibile device list: [raspberrypi3]
2020-04-02 11:07:49 +0000 UTC debug: installer: processing script: ArtifactFailure_Enter_10
2020-04-02 11:07:49 +0000 UTC debug: installing update rpi-bf-image-raspberrypi3.ext4 of size 2000683008
2020-04-02 11:07:49 +0000 UTC debug: Trying to install update of size: 2000683008
2020-04-02 11:07:49 +0000 UTC debug: Active partition: /dev/mmcblk0p2
2020-04-02 11:07:49 +0000 UTC debug: Detected inactive partition /dev/mmcblk0p3, based on active partition /dev/mmcblk0p2
2020-04-02 11:07:49 +0000 UTC info: opening device /dev/mmcblk0p3 for writing
2020-04-02 11:07:49 +0000 UTC info: partition /dev/mmcblk0p3 size: 2000683008
2020-04-02 11:23:38 +0000 UTC info: wrote 2000683008/2000683008 bytes of update to device /dev/mmcblk0p3
2020-04-02 11:23:39 +0000 UTC debug: installer: successfully read artifact [name: tc-0.11.0-20200401-110156; version: 2; compatible devices: [raspberrypi3]]
2020-04-02 11:23:39 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:23:39 +0000 UTC info: State transition: update-store [Download] -> update-install [ArtifactInstall]
2020-04-02 11:23:39 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:23:39 +0000 UTC debug: Inactive partition: /dev/mmcblk0p3
2020-04-02 11:23:39 +0000 UTC debug: Marking inactive partition (/dev/mmcblk0p3) as the new boot candidate.
2020-04-02 11:23:39 +0000 UTC info: Enabling partition with new image installed to be a boot candidate: 3
2020-04-02 11:23:39 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=1
2020-04-02 11:23:39 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:1]
2020-04-02 11:23:39 +0000 UTC debug: Have U-Boot variable: mender_saveenv_canary=1
2020-04-02 11:23:39 +0000 UTC debug: List of U-Boot variables:map[mender_saveenv_canary:1]
2020-04-02 11:23:39 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
2020-04-02 11:23:39 +0000 UTC info: State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]
2020-04-02 11:23:39 +0000 UTC debug: handling reboot state
2020-04-02 11:23:39 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:23:39 +0000 UTC info: rebooting device
2020-04-02 11:23:39 +0000 UTC info: Mender rebooting from active partition: /dev/mmcblk0p2
2020-04-02 11:26:07 +0000 UTC error: got invalid entrypoint into the state machine: state: reboot
2020-04-02 11:26:07 +0000 UTC info: State transition: init [none] -> update-error [ArtifactFailure]
2020-04-02 11:26:07 +0000 UTC debug: transitioning to error state
2020-04-02 11:26:07 +0000 UTC debug: start executing script: ArtifactFailure_Enter_10
2020-04-02 11:26:08 +0000 UTC error: got unexpected HTTP status when reporting status: 400
2020-04-02 11:26:08 +0000 UTC error: statescript: can not send start status to server: (request_id: ): reporting status failed, bad status 400 server error message: unknown status value
2020-04-02 11:26:11 +0000 UTC error: got unexpected HTTP status when reporting status: 400
2020-04-02 11:26:11 +0000 UTC error: statescript: can not send finished status to server: (request_id: ): reporting status failed, bad status 400 server error message: unknown status value
2020-04-02 11:26:11 +0000 UTC debug: handle update error state
2020-04-02 11:26:11 +0000 UTC info: State transition: update-error [ArtifactFailure] -> update-status-report [none]
2020-04-02 11:26:11 +0000 UTC debug: handle update status report state
2020-04-02 11:26:11 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:26:11 +0000 UTC debug: attempting to upload deployment logs for failed update

br,
AP

Edit: @mirzak: formatting

aps · April 2, 2020, 1:03pm

The boot.scr seems to be corrupt. It has non printing characters in start of the file. Could it be the reason that u-boot fails and rolls-back
boot.scr
'V�W&{^�}��y�:�Boot script�fdt addr {fdt_addr} && fdt get value bootargs /chosen bootargs run mender_setup mmc dev {mender_uboot_dev}
load {mender_uboot_root} {kernel_addr_r} /boot/uImage
bootm {kernel_addr_r} - {fdt_addr}
run mender_try_to_recover

Now I wonder why baking mender this garbage is produced.

br,
AP

mirzak · April 2, 2020, 1:06pm

Please note that states that are not prefixed with Artifact*, should have their script put in the rootfs. I do not know if this is related to the issues but wanted to bring this up. You can read more here,

https://docs.mender.io/2.3/artifacts/state-scripts#root-file-system-and-artifact-scripts

2020-04-02 11:23:39 +0000 UTC info: State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]
2020-04-02 11:23:39 +0000 UTC debug: handling reboot state
2020-04-02 11:23:39 +0000 UTC debug: status reported, response 204 No Content
2020-04-02 11:23:39 +0000 UTC info: rebooting device
2020-04-02 11:23:39 +0000 UTC info: Mender rebooting from active partition: /dev/mmcblk0p2
2020-04-02 11:26:07 +0000 UTC error: got invalid entrypoint into the state machine: state: reboot
2020-04-02 11:26:07 +0000 UTC info: State transition: init [none] -> update-error [ArtifactFailure]
2020-04-02 11:26:07 +0000 UTC debug: transitioning to error state

Even though the error message is the same, now I think it is behaving somewhat as expected. I think your best chance to debug this is to connect to the serial port which you would need to verify the integration (e.g fw_env) according to our docs,

https://docs.mender.io/2.3/devices/yocto-project/bootloader-support/u-boot/integration-checklist

mirzak · April 2, 2020, 1:08pm

This is expected. This file is an executable U-boot script and the “garbage” is binary data needed for U-Boot to understand it.

It is created here,

github.com

agherzan/meta-raspberrypi/blob/master/recipes-bsp/rpi-u-boot-scr/rpi-u-boot-scr.bb#L16


      
          DEPENDS = "u-boot-mkimage-native"
          
          INHIBIT_DEFAULT_DEPS = "1"
          
          SRC_URI = "file://boot.cmd.in"
          
          do_compile() {
              sed -e 's/@@KERNEL_IMAGETYPE@@/${KERNEL_IMAGETYPE}/' \
                  -e 's/@@KERNEL_BOOTCMD@@/${KERNEL_BOOTCMD}/' \
                  "${WORKDIR}/boot.cmd.in" > "${WORKDIR}/boot.cmd"
              mkimage -A ${UBOOT_ARCH} -T script -C none -n "Boot script" -d "${WORKDIR}/boot.cmd" boot.scr
          }
          
          inherit kernel-arch deploy nopackages
          
          do_deploy() {
              install -d ${DEPLOYDIR}
              install -m 0644 boot.scr ${DEPLOYDIR}
          }
          
          addtask do_deploy after do_compile before do_build

aps · April 3, 2020, 6:19am

Sorry for wasting your time and thank you for trying. It was my mistake, the device rebooted before mender reboot. It works well now when I removed the reboot.

mirzak · April 3, 2020, 6:33am

No problems, and glad you where able to resolve it

Topic		Replies	Views
Update is succesfull but mender announces to the server that it failed General Discussions	5	786	November 11, 2019
OTA update failing with: Update was interrupted in state: update-store General Discussions	3	744	November 25, 2020
Start-update-notifier fails General Discussions	2	409	June 24, 2019
Update Fails General Discussions	8	1562	March 4, 2021
Raspberry Pi 4 update failed General Discussions raspberry-pi-4	4	922	April 27, 2020

Update fails on error: got invalid entrypoint into the state machine: state: update-store

Related topics