Mender upate flag not set

GJim · January 13, 2023, 4:49am

Hello,

I am trying a mender update on an x86 device. The Mender server version is 3.1.1 and client 3.4.0.

The client downloads the image and then reboot to the new partition. However, it then immediately reboots to the previous partition.

Jan 10 15:55:01 cm50 mender[3436]: time="2023-01-10T15:55:01+01:00" level=info msg="Mender rebooting from active partition: /dev/mmcblk1p2" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Reboot"  

Jan 10 15:55:01 cm50 mender[3436]: time="2023-01-10T15:55:01+01:00" level=error msg="error forwarding from client to backend: websocket: close 1006 (abnormal closure): unexpected EOF" func="github.com/mendersoftware/mender/app/proxy.(*proxyControllerInner).DoWsUpgrade"  

Jan 10 15:55:01 cm50 systemd[1]: Stopping Mender OTA update service...

Jan 10 15:55:01 cm50 mender[3436]: time="2023-01-10T15:55:01+01:00" level=info msg="Daemon terminated with SIGTERM" func=main.doMain  

Jan 10 15:55:01 cm50 systemd[1]: Stopped Mender OTA update service.

-- Reboot --

Jan 10 15:55:08 cm50 mender[638]: time="2023-01-10T15:55:08+01:00" level=debug msg="Reading Mender configuration from file /var/lib/mender/mender.conf" func=github.com/mendersoftware/mender/conf.readConfigFile  

Jan 10 15:55:08 cm50 mender[638]: time="2023-01-10T15:55:08+01:00" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf" func=github.com/mendersoftware/mender/conf.loadConfigFile  


Jan 10 15:55:08 cm50 mender[638]: time="2023-01-10T15:55:08+01:00" level=debug msg="Verified configuration = &conf.MenderConfig{MenderConfigFromFile:conf.MenderConfigFromFile{ArtifactVerifyKey:\"/etc/mender/artifact-verify-key.pem\", HttpsClient:client.HttpsClient{Certificate:\"\", Key:\"\", SSLEngine:\"\"}, Security:client.Security{AuthPrivateKey:\"\", SSLEngine:\"\"}, Connectivity:client.Connectivity{DisableKeepAlive:false, IdleConnTimeoutSeconds:0}, RootfsPartA:\"/dev/mmcblk1p2\", RootfsPartB:\"/dev/mmcblk1p3\", BootUtilitiesSetActivePart:\"\", BootUtilitiesGetNextActivePart:\"\", DeviceTypeFile:\"/data/mender/device_type\", DBus:conf.DBusConfig{Enabled:true}, UpdateControlMapExpirationTimeSeconds:0, UpdateControlMapBootExpirationTimeSeconds:0, UpdatePollIntervalSeconds:300, InventoryPollIntervalSeconds:600, SkipVerify:false, RetryPollIntervalSeconds:300, RetryPollCount:0, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ModuleTimeoutSeconds:0, ServerCertificate:\"\", ServerURL:\"\", UpdateLogPath:\"\", TenantToken:\"\", Servers:[]client.MenderServer{client.MenderServer{ServerURL:\"https://****************\"}}}, ModulesPath:\"/usr/share/mender/modules/v3\", ModulesWorkPath:\"/var/lib/mender/modules/v3\", ArtifactInfoFile:\"/etc/mender/artifact_info\", ArtifactScriptsPath:\"/var/lib/mender/scripts\", RootfsScriptsPath:\"/etc/mender/scripts\"}" func="github.com/mendersoftware/mender/conf.(*MenderConfig).Validate"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Setting active partition from mount candidate: /dev/mmcblk1p2" func="github.com/mendersoftware/mender/installer.(*partitions).getAndCacheActivePartition"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="Mender running on partition: /dev/mmcblk1p2" func=github.com/mendersoftware/mender/cli.initDualRootfsDevice  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Loading update control maps from the store" func="github.com/mendersoftware/mender/app.(*ControlMapPool).loadFromStore"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="Handling loaded state: reboot" func="github.com/mendersoftware/mender/app.(*initState).Handle"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="Running Mender client version: 3.3.0" func="github.com/mendersoftware/mender/app.(*DeploymentLogManager).Enable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="State transition: init [none] -> after-reboot [ArtifactReboot_Leave]" func=github.com/mendersoftware/mender/app.transitionState  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Have U-Boot variable: mender_check_saveenv_canary=" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="List of U-Boot variables:map[mender_check_saveenv_canary:]" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Have U-Boot variable: upgrade_available=0" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="List of U-Boot variables:map[upgrade_available:0]" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=error msg="transient error: Reboot to the new update failed. Expected \"upgrade_available\" flag to be true but it was false. Either the switch to the new partition was unsuccessful, or the bootloader rolled back" func="github.com/mendersoftware/mender/app.(*updateState).HandleError"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="State transition: after-reboot [ArtifactReboot_Leave] -> rollback [ArtifactRollback]" func=github.com/mendersoftware/mender/app.transitionState  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Transitioning to error state" func=github.com/mendersoftware/mender/app.transitionState  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="Performing rollback" func="github.com/mendersoftware/mender/app.(*updateRollbackState).Handle"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Have U-Boot variable: mender_check_saveenv_canary=" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="List of U-Boot variables:map[mender_check_saveenv_canary:]" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Have U-Boot variable: upgrade_available=0" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="List of U-Boot variables:map[upgrade_available:0]" func="github.com/mendersoftware/mender/installer.(*UBootEnv).getEnvironmentVariable"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="No update available, so no rollback needed." func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Rollback"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="No update available, so no rollback needed." func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Rollback"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="Will try to rollback reboot the device" func="github.com/mendersoftware/mender/app.(*updateRollbackState).Handle"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="State transition: rollback [ArtifactRollback] -> rollback-reboot [ArtifactRollbackReboot_Enter]" func=github.com/mendersoftware/mender/app.transitionState  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="Rebooting device(s) after rollback" func="github.com/mendersoftware/mender/app.(*updateRollbackRebootState).Handle"  

Jan 10 15:55:09 cm50 mender[638]: time="2023-01-10T15:55:09+01:00" level=info msg="Mender rebooting from inactive partition: /dev/mmcblk1p2" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).RollbackReboot"  

Jan 10 15:55:10 cm50 systemd[1]: Stopping Mender OTA update service...
Jan 10 15:55:10 cm50 mender[638]: time="2023-01-10T15:55:10+01:00" level=info msg="Daemon terminated with SIGTERM" func=main.doMain  

Jan 10 15:55:10 cm50 systemd[1]: mender-client.service: Succeeded.

Jan 10 15:55:10 cm50 systemd[1]: Stopped Mender OTA update service.
-- Reboot --

Jan 10 16:00:24 cm50 mender[647]: time="2023-01-10T16:00:24+01:00" level=debug msg="Reading Mender configuration from file /var/lib/mender/mender.conf" func=github.com/mendersoftware/mender/conf.readConfigFile

Any help would be deeply appreciated.

TheYoctoJester · January 13, 2023, 11:52am

Hi @GJim,

First guess would be the board integration being somewhat flaky or incomplete. What distribution / build are you using?

Greetz,
Josef

GJim · January 13, 2023, 2:02pm

Hi @TheYoctoJester

Thank you for your response. I am using Linux Debian 4.19.

TheYoctoJester · January 13, 2023, 2:09pm

Hi @GJim,

Hum, I guess we need quite a bit more than that. Debian, okay. The 4.19 probably refers to the kernel version then, this would mean the buster release. How did you install Mender? If you just pulled in the package through apt, then system updates will not work out of the box as they require an integration that involves the boot mechanism as well as partitioning, as described here.

So what kind of hardware is this, how did you install Mender?

Greetz,
Josef

daniel1 · January 13, 2023, 2:47pm

Hi. I’m a colleague from GJim.
We are using a x86_64 device and use mender-convert for creating the mender-compatible image and update-artifacts.
The basis-image has no mender-installation.
After a update the device is switching the partition, and is connecting to the mender-server with a new authentication-set and a new key . We have to accept this key. Then the status from deployment changes in webinterface from server to “failed - already installed” and the system stands on the new partition, with new firmware, with a entry “skipped”, but correct firmware-number in the server-gui.
After a manual triggered reboot the device switches back to the other partition (back to a).
Thanks for your reply!

TheYoctoJester · January 13, 2023, 3:10pm

Hi @daniel1,

a couple of things:

are you using the generic x84_64 configuration, or something custom?
again, which kind of hardware? Specifically, does it have a watchdog?
is it really the same device with a new authentication set, or a new device? The former would indicate that /data is not persistent. the latter that the device identity (usually the MAC address) is not persistent, or confused due to multiple network interfaces.

Greetz,
Josef

daniel1 · January 13, 2023, 4:12pm

it’s mostly generic. Only the partition-size is changed.
It has a watchdog. It’s a small IoT Industrial PC for Din Rail Mount
I only have this one device. The problem with the auth-set is now fixed. But after a update it shows again “already installed” and rolls back after a manual reboot.
The difference between both images (curent and update) is only the name. The content is identical. Could this be a reason? In earlier versions and on raspberry pi this never was a problem…

daniel1 · January 16, 2023, 5:27am

Here are some logfiles.
Server-Side Log on GUI

2023-01-13 19:34:51 +0000 UTC info: Running Mender client version: 3.4.0
2023-01-13 19:34:51 +0000 UTC debug: Handling update fetch state
2023-01-13 19:34:51 +0000 UTC debug: Connecting to server http://127.0.0.1:38561
2023-01-13 19:34:51 +0000 UTC debug: Request: “” “” “https” “mender.CHANGED_BUT_URL_WAS_OK.de” “/api/devices/v1/deployments/device/deployments/8a4c244b-6074-416e-9b66-cd198e9f3214/status”
2023-01-13 19:34:51 +0000 UTC debug: Status reported, response 204 No Content
2023-01-13 19:34:51 +0000 UTC debug: Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[1724077056] Content-Security-Policy:[block-all-mixed-content] Content-Type:[application/vnd.mender-artifact] Date:[Fri, 13 Jan 2023 19:34:51 GMT] Etag:[“85e4788bae0df05fef8879f6d4d17bf4-165”] Expires:[Fri, 13 Jan 2023 13:48:25 GMT] Last-Modified:[Fri, 13 Jan 2023 12:52:14 GMT] Server:[MinIO] Set-Cookie:[AWSALB=xKBFn1wWoxWPlJdNmzSy+FIippkyBFXKB8khkLs2ZZ3Fu/yv+TjWLBXF2C0pfgg5Ubn6UHglWp/nA+r2LDP0y8DE3XByFOSgLhVwQLpNjjmxDdZ431drK+QItjay; Expires=Fri, 20 Jan 2023 19:34:51 GMT; Path=/ AWSALBCORS=xKBFn1wWoxWPlJdNmzSy+FIippkyBFXKB8khkLs2ZZ3Fu/yv+TjWLBXF2C0pfgg5Ubn6UHglWp/nA+r2LDP0y8DE3XByFOSgLhVwQLpNjjmxDdZ431drK+QItjay; Expires=Fri, 20 Jan 2023 19:34:51 GMT; Path=/; SameSite=None; Secure] Strict-Transport-Security:[max-age=31536000; includeSubDomains] Vary:[Origin Accept-Encoding] X-Amz-Request-Id:[1739F5573C045896] X-Content-Type-Options:[nosniff] X-Xss-Protection:[1; mode=block]] 0xc00002c820 1724077056 false false map 0xc000520600 }+
2023-01-13 19:34:51 +0000 UTC info: State transition: update-fetch [Download_Enter] → update-store [Download_Enter]
2023-01-13 19:34:51 +0000 UTC debug: Handling update install state
2023-01-13 19:34:51 +0000 UTC debug: Connecting to server http://127.0.0.1:38561
2023-01-13 19:34:51 +0000 UTC debug: Request: “” “” “https” “mender.CHANGED_BUT_URL_WAS_OK.de” “/api/devices/v1/deployments/device/deployments/8a4c244b-6074-416e-9b66-cd198e9f3214/status”
2023-01-13 19:34:51 +0000 UTC debug: Status reported, response 204 No Content
2023-01-13 19:34:51 +0000 UTC debug: Reading data from the device manifest file: /data/mender/device_type
2023-01-13 19:34:51 +0000 UTC debug: device_type=x86_64
2023-01-13 19:34:51 +0000 UTC debug: Current manifest data: x86_64
2023-01-13 19:34:51 +0000 UTC info: No public key was provided for authenticating the artifact
2023-01-13 19:34:51 +0000 UTC debug: Checking if device [x86_64] is on compatible device list: [x86_64]
2023-01-13 19:34:51 +0000 UTC debug: Installer: Successfully read artifact [name: mender-test_13_01_2023_2; version: 3; compatible devices: [x86_64]]
2023-01-13 19:34:51 +0000 UTC warning: Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before.
2023-01-13 19:34:51 +0000 UTC debug: Reading data from the device manifest file: /etc/mender/artifact_info
2023-01-13 19:34:51 +0000 UTC debug: artifact_name=mender-test_13_01_2023
2023-01-13 19:34:51 +0000 UTC debug: Current manifest data: mender-test_13_01_2023
2023-01-13 19:34:52 +0000 UTC debug: Active partition: /dev/mmcblk1p2
2023-01-13 19:34:52 +0000 UTC debug: Detected inactive partition /dev/mmcblk1p3, based on active partition /dev/mmcblk1p2
2023-01-13 19:34:52 +0000 UTC info: Opening device “/dev/mmcblk1p3” for writing
2023-01-13 19:34:52 +0000 UTC debug: Installing update of size: 5989721600
2023-01-13 19:34:52 +0000 UTC debug: Device: /dev/mmcblk1p3 is a ubi device: false
2023-01-13 19:34:52 +0000 UTC info: Native sector size of block device /dev/mmcblk1p3 is 512 bytes. Mender will write in chunks of 1048576 bytes
2023-01-13 19:34:52 +0000 UTC debug: Opening device: /dev/mmcblk1p3 for writing with flag: 2
2023-01-13 19:35:11 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:35:11 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:35:26 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:35:26 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:36:17 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:36:17 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:36:31 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:36:31 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:37:22 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:37:22 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:37:36 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:37:36 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:38:27 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:38:27 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:38:41 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:38:42 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:39:32 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:39:32 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:39:47 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:39:47 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:40:38 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:40:38 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:40:52 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:40:52 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:41:42 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:41:42 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:41:57 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:41:57 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:42:47 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:42:47 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:43:02 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:43:02 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:43:52 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:43:52 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:44:07 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:44:07 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:44:57 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:44:57 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:45:12 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:45:12 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:46:03 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:46:03 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:46:17 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:46:17 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:47:07 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:47:07 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:47:22 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:47:22 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:48:13 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:48:13 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:48:27 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:48:27 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:49:18 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:49:18 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:49:32 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:49:32 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:50:23 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:50:23 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:50:37 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:50:37 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:51:28 +0000 UTC error: error forwarding from backend to client: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:51:28 +0000 UTC warning: error while sending close message: connection closed
2023-01-13 19:51:42 +0000 UTC debug: received the GET_AUTH_TOKEN action
2023-01-13 19:51:42 +0000 UTC debug: Upgrading /api/devices/v1/deviceconnect/connect
2023-01-13 19:51:54 +0000 UTC info: All bytes were successfully written to the new partition
2023-01-13 19:51:54 +0000 UTC info: The optimized block-device writer wrote a total of 5713 frames, where 76 frames did need to be rewritten (i.e., skipped)
2023-01-13 19:51:54 +0000 UTC info: Wrote 5989721600/5989721600 bytes to the inactive partition
2023-01-13 19:51:54 +0000 UTC debug: Connecting to server http://127.0.0.1:38561
2023-01-13 19:51:54 +0000 UTC debug: Request: “” “” “https” “mender.CHANGED_BUT_URL_WAS_OK.de” “/api/devices/v1/deployments/device/deployments/8a4c244b-6074-416e-9b66-cd198e9f3214/status”
2023-01-13 19:51:55 +0000 UTC debug: Status reported, response 204 No Content
2023-01-13 19:51:55 +0000 UTC info: State transition: update-store [Download_Enter] → update-after-store [Download_Leave]
2023-01-13 19:51:55 +0000 UTC info: State transition: update-after-store [Download_Leave] → mender-update-control-refresh-maps [none]
2023-01-13 19:51:55 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:51:55 +0000 UTC info: Executing script: Download_Leave_00
2023-01-13 19:51:57 +0000 UTC info: Output (stdout) from command “/etc/mender/scripts/Download_Leave_00”: target directorys exists: Start copy configurationfiles
2023-01-13 19:51:57 +0000 UTC info: Output (stdout) from command “/etc/mender/scripts/Download_Leave_00”: Copied Configuration
2023-01-13 19:51:57 +0000 UTC info: Output (stdout) from command “/etc/mender/scripts/Download_Leave_00”: Created symbolic link
2023-01-13 19:51:57 +0000 UTC info: Collected output (stderr) while running script /etc/mender/scripts/Download_Leave_00
artifact_name=mender-test_13_01_2023: Running Download_Leave_00

---------- end of script output
2023-01-13 19:51:57 +0000 UTC debug: Handle fetchControlMap state
2023-01-13 19:51:57 +0000 UTC info: State transition: mender-update-control-refresh-maps [none] → mender-update-control [none]
2023-01-13 19:51:57 +0000 UTC debug: Handling update control state
2023-01-13 19:51:57 +0000 UTC debug: Querying Update Control maps. Currently active maps: ‘’
2023-01-13 19:51:57 +0000 UTC debug: Returning action “continue”
2023-01-13 19:51:57 +0000 UTC debug: controlMapState action: continue
2023-01-13 19:51:57 +0000 UTC info: State transition: mender-update-control [none] → update-install [ArtifactInstall]
2023-01-13 19:51:57 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:51:57 +0000 UTC debug: Connecting to server http://127.0.0.1:38561
2023-01-13 19:51:57 +0000 UTC debug: Request: “” “” “https” “mender.CHANGED_BUT_URL_WAS_OK.de” “/api/devices/v1/deployments/device/deployments/8a4c244b-6074-416e-9b66-cd198e9f3214/status”
2023-01-13 19:51:57 +0000 UTC debug: Status reported, response 204 No Content
2023-01-13 19:51:57 +0000 UTC debug: Inactive partition: /dev/mmcblk1p3
2023-01-13 19:51:57 +0000 UTC info: Enabling partition with new image installed to be a boot candidate: 3
2023-01-13 19:51:57 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=
2023-01-13 19:51:57 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:]
2023-01-13 19:51:57 +0000 UTC debug: Probing the Bootloader environment for which separator to use
2023-01-13 19:51:57 +0000 UTC debug: Writing map[mender_uboot_separator:1] to the U-Boot environment, using separator:
2023-01-13 19:51:57 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=
2023-01-13 19:51:57 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:]
2023-01-13 19:51:57 +0000 UTC debug: Have U-Boot variable: mender_uboot_separator=1
2023-01-13 19:51:57 +0000 UTC debug: List of U-Boot variables:map[mender_uboot_separator:1]
2023-01-13 19:51:58 +0000 UTC debug: Writing map[mender_uboot_separator:] to the U-Boot environment, using separator:
2023-01-13 19:51:58 +0000 UTC debug: Using ( ) as the bootloader environment separator
2023-01-13 19:51:58 +0000 UTC debug: Writing map[bootcount:0 mender_boot_part:3 mender_boot_part_hex:3 upgrade_available:1] to the U-Boot environment, using separator:
2023-01-13 19:51:58 +0000 UTC debug: Marking inactive partition as a boot candidate successful.
2023-01-13 19:51:58 +0000 UTC info: State transition: update-install [ArtifactInstall] → mender-update-control-refresh-maps [none]
2023-01-13 19:51:58 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:51:58 +0000 UTC debug: Handle fetchControlMap state
2023-01-13 19:51:58 +0000 UTC info: State transition: mender-update-control-refresh-maps [none] → mender-update-control [none]
2023-01-13 19:51:58 +0000 UTC debug: Handling update control state
2023-01-13 19:51:58 +0000 UTC debug: Querying Update Control maps. Currently active maps: ‘’
2023-01-13 19:51:58 +0000 UTC debug: Returning action “continue”
2023-01-13 19:51:58 +0000 UTC debug: controlMapState action: continue
2023-01-13 19:51:58 +0000 UTC info: State transition: mender-update-control [none] → reboot [ArtifactReboot_Enter]
2023-01-13 19:51:58 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:51:58 +0000 UTC debug: Handling reboot state
2023-01-13 19:51:58 +0000 UTC debug: Connecting to server http://127.0.0.1:38561
2023-01-13 19:51:58 +0000 UTC debug: Request: “” “” “https” “mender.CHANGED_BUT_URL_WAS_OK.de” “/api/devices/v1/deployments/device/deployments/8a4c244b-6074-416e-9b66-cd198e9f3214/status”
2023-01-13 19:51:58 +0000 UTC debug: Status reported, response 204 No Content
2023-01-13 19:51:58 +0000 UTC info: Rebooting device(s)
2023-01-13 19:51:58 +0000 UTC info: Mender rebooting from active partition: /dev/mmcblk1p2
2023-01-13 19:51:58 +0000 UTC error: error forwarding from client to backend: websocket: close 1006 (abnormal closure): unexpected EOF
2023-01-13 19:51:58 +0000 UTC warning: error while sending close message: write tcp 127.0.0.1:38561->127.0.0.1:34996: use of closed network connection
2023-01-13 19:51:58 +0000 UTC info: Daemon terminated with SIGTERM
2023-01-13 19:52:01 +0000 UTC info: Running Mender client version: 3.4.0
2023-01-13 19:52:01 +0000 UTC info: State transition: init [none] → after-reboot [ArtifactReboot_Leave]
2023-01-13 19:52:01 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=
2023-01-13 19:52:01 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:]
2023-01-13 19:52:01 +0000 UTC debug: Have U-Boot variable: upgrade_available=0
2023-01-13 19:52:01 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:0]
2023-01-13 19:52:01 +0000 UTC error: transient error: Reboot to the new update failed. Expected “upgrade_available” flag to be true but it was false. Either the switch to the new partition was unsuccessful, or the bootloader rolled back
2023-01-13 19:52:01 +0000 UTC info: State transition: after-reboot [ArtifactReboot_Leave] → rollback [ArtifactRollback]
2023-01-13 19:52:01 +0000 UTC debug: Transitioning to error state
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC info: Performing rollback
2023-01-13 19:52:01 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=
2023-01-13 19:52:01 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:]
2023-01-13 19:52:01 +0000 UTC debug: Have U-Boot variable: upgrade_available=0
2023-01-13 19:52:01 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:0]
2023-01-13 19:52:01 +0000 UTC info: No update available, so no rollback needed.
2023-01-13 19:52:01 +0000 UTC debug: Will try to rollback reboot the device
2023-01-13 19:52:01 +0000 UTC info: State transition: rollback [ArtifactRollback] → rollback-reboot [ArtifactRollbackReboot_Enter]
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC info: Rebooting device(s) after rollback
2023-01-13 19:52:01 +0000 UTC info: Mender rebooting from inactive partition: /dev/mmcblk1p2
2023-01-13 19:52:02 +0000 UTC info: Daemon terminated with SIGTERM
2023-01-13 19:52:01 +0000 UTC info: Running Mender client version: 3.4.0
2023-01-13 19:52:01 +0000 UTC info: Mender shut down in state: rollback-reboot
2023-01-13 19:52:01 +0000 UTC info: State transition: init [none] → verify-rollback-reboot [ArtifactRollbackReboot_Leave]
2023-01-13 19:52:01 +0000 UTC debug: Transitioning to error state
2023-01-13 19:52:01 +0000 UTC debug: Have U-Boot variable: mender_check_saveenv_canary=
2023-01-13 19:52:01 +0000 UTC debug: List of U-Boot variables:map[mender_check_saveenv_canary:]
2023-01-13 19:52:01 +0000 UTC debug: Have U-Boot variable: upgrade_available=0
2023-01-13 19:52:01 +0000 UTC debug: List of U-Boot variables:map[upgrade_available:0]
2023-01-13 19:52:01 +0000 UTC info: State transition: verify-rollback-reboot [ArtifactRollbackReboot_Leave] → after-rollback-reboot [ArtifactRollbackReboot_Leave]
2023-01-13 19:52:01 +0000 UTC debug: Handling state after rollback reboot
2023-01-13 19:52:01 +0000 UTC info: State transition: after-rollback-reboot [ArtifactRollbackReboot_Leave] → update-error [ArtifactFailure]
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: Handle update error state
2023-01-13 19:52:01 +0000 UTC info: State transition: update-error [ArtifactFailure] → cleanup [Error]
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: Handling Cleanup state
2023-01-13 19:52:01 +0000 UTC debug: Deleting all Update Control Maps with ID: 8a4c244b-6074-416e-9b66-cd198e9f3214
2023-01-13 19:52:01 +0000 UTC debug: ControlMapPool: Announcing update to the map
2023-01-13 19:52:01 +0000 UTC info: State transition: cleanup [Error] → update-status-report [none]
2023-01-13 19:52:01 +0000 UTC debug: statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds
2023-01-13 19:52:01 +0000 UTC debug: Handling update status report state
2023-01-13 19:52:01 +0000 UTC info: Device unauthorized; attempting reauthorization
2023-01-13 19:52:01 +0000 UTC debug: received the FETCH_AUTH_TOKEN action
2023-01-13 19:52:01 +0000 UTC info: Output (stderr) from command “/usr/share/mender/identity/mender-device-identity”: using interface /sys/class/net/enp3s0
2023-01-13 19:52:01 +0000 UTC debug: Tenant token:
2023-01-13 19:52:01 +0000 UTC debug: Authorization data: {{“mac”:“00:c0:3a:ec:04:12”} -----BEGIN PUBLIC KEY-----
THIS WAS MY KEY - I REMOVED IT IN THE LOG
-----END PUBLIC KEY-----
}
2023-01-13 19:52:01 +0000 UTC debug: Making an authorization request () to server https://mender.CHANGED_BUT_URL_WAS_OK.de
2023-01-13 19:52:07 +0000 UTC debug: Got response: &{200 OK 200 HTTP/1.1 1 1 map[Connection:[keep-alive] Content-Type:[application/json; charset=utf-8] Date:[Fri, 13 Jan 2023 20:01:09 GMT] Referrer-Policy:[no-referrer] Set-Cookie:[AWSALB=OxayyQ0wF73XIZLlv7qOO30ozFz8Eji2NymbamQk+GoOvR6uB/MRHWjrUYZMjOKHKAELEhu1EjbPRIlWmMwXal2qFNhMq/LBDuucavau/MlJ0H2ohh2r8O0DSk7W; Expires=Fri, 20 Jan 2023 20:01:09 GMT; Path=/ AWSALBCORS=OxayyQ0wF73XIZLlv7qOO30ozFz8Eji2NymbamQk+GoOvR6uB/MRHWjrUYZMjOKHKAELEhu1EjbPRIlWmMwXal2qFNhMq/LBDuucavau/MlJ0H2ohh2r8O0DSk7W; Expires=Fri, 20 Jan 2023 20:01:09 GMT; Path=/; SameSite=None; Secure] Strict-Transport-Security:[max-age=31536000; includeSubDomains; preload] Vary:[Accept-Encoding] X-Men-Requestid:[5c94faf2-7a16-49a8-9e70-7bc19ab251fd] X-Xss-Protection:[1; mode=block]] 0xc000268060 -1 false true map 0xc00032e200 }
2023-01-13 19:52:07 +0000 UTC debug: Receive response data
2023-01-13 19:52:07 +0000 UTC debug: Received response data: [101 121 74 104 98 71 99 105 79 105 74 83 85 122 73 49 78 105 73 115 73 110 82 53 99 67 73 54 73 107 112 88 86 67 74 57 46 101 121 74 113 100 71 107 105 79 105 73 120 90 71 73 51 77 84 108 107 79 67 48 52 89 122 99 51 76 84 82 104 90 106 81 116 79 84 85 52 78 121 49 107 77 68 99 53 90 71 77 48 89 106 108 106 78 106 81 105 76 67 74 122 100 87 73 105 79 105 74 109 78 106 99 52 89 50 73 48 89 105 48 51 77 109 85 121 76 84 81 49 90 68 73 116 79 71 77 49 79 67 49 106 77 50 77 50 79 84 66 108 89 122 73 121 78 68 77 105 76 67 74 112 99 51 77 105 79 105 74 78 90 87 53 107 90 88 73 105 76 67 74 108 101 72 65 105 79 106 69 50 78 122 81 121 78 68 81 52 78 106 107 115 73 109 108 104 100 67 73 54 77 84 89 51 77 122 89 48 77 68 65 50 79 83 119 105 98 109 74 109 73 106 111 116 78 106 73 120 77 122 85 49 79 84 89 52 77 68 65 115 73 109 49 108 98 109 82 108 99 105 53 107 90 88 90 112 89 50 85 105 79 110 82 121 100 87 85 115 73 109 49 108 98 109 82 108 99 105 53 119 98 71 70 117 73 106 111 105 90 87 53 48 90 88 74 119 99 109 108 122 90 83 73 115 73 109 49 108 98 109 82 108 99 105 53 48 99 109 108 104 98 67 73 54 90 109 70 115 99 50 85 115 73 109 49 108 98 109 82 108 99 105 53 104 90 71 82 118 98 110 77 105 79 108 116 55 73 109 53 104 98 87 85 105 79 105 74 106 98 50 53 109 97 87 100 49 99 109 85 105 76 67 74 108 98 109 70 105 98 71 86 107 73 106 112 48 99 110 86 108 102 83 120 55 73 109 53 104 98 87 85 105 79 105 74 48 99 109 57 49 89 109 120 108 99 50 104 118 98 51 81 105 76 67 74 108 98 109 70 105 98 71 86 107 73 106 112 48 99 110 86 108 102 83 120 55 73 109 53 104 98 87 85 105 79 105 74 116 98 50 53 112 100 71 57 121 73 105 119 105 90 87 53 104 89 109 120 108 90 67 73 54 100 72 74 49 90 88 49 100 102 81 46 73 121 49 106 49 114 98 109 77 81 113 108 106 84 75 105 69 66 57 66 68 88 100 101 78 54 76 95 49 89 122 111 87 74 117 86 55 113 105 112 50 108 116 87 51 50 54 54 85 105 73 82 106 103 104 74 71 68 98 108 105 112 80 45 86 75 113 110 98 109 100 52 122 71 118 53 56 108 70 81 45 109 80 120 108 99 83 52 117 55 56 110 54 67 85 106 50 114 65 119 84 81 66 121 114 52 111 105 75 52 73 54 52 117 112 78 45 45 103 89 77 112 122 79 97 104 108 76 102 50 119 117 97 56 66 111 104 78 81 120 99 112 98 98 67 100 55 117 82 71 98 99 51 70 115 118 97 108 109 87 76 49 86 54 122 49 54 53 50 49 99 74 113 117 49 111 120 73 56 70 111 65 80 54 88 109 54 95 110 100 115 49 101 76 109 82 98 80 57 79 97 117 72 121 48 74 56 81 81 66 120 117 56 111 81 103 88 97 113 103 45 72 70 54 90 45 45 108 110 65 120 122 98 57 101 76 53 67 79 103 52 122 51 118 81 57 108 71 100 49 74 66 97 77 104 81 86 65 120 57 45 109 52 83 57 71 119 103 50 55 120 53 70 83 45 49 78 66 101 49 51 85 111 120 90 108 122 76 88 48 97 86 73 120 90 73 117 86 101 68 101 69 89 122 119 83 99 99 54 88 87 120 69 119 103 71 66 114 67 98 52 109 106 54 81 112 78 86 76 83 111 71 66 113 90 89 67 75 104 110 70 70 119 114 52 120 70 50 66 99 48 97 97 120 79 67 54 113 52 100 107 103 114 53 103 102 55 50 102 101 90 104 67 109 85 88 50 68 121 90 121 101 87 81 115 45 103 48 78 106 71 45 112 77 49 104 79 55 53 83 98 56 65 69 116 90 121 65 88 72 116 120 72 57 76 111 80 112 69 83 109 66 53 68 81 98 116 49 77 84 108 122 55 122 83 52 108 115 84 108 102 89 120 115 83 120 68 113 119 122 108 56 98 55 103 79 113 115 52 121 70 71 98 89 104 109 65 57 51 76 82 109 53 95 65 74 120 88 111 81 76 113 90 90 51 53 107 69 108 45 117 115 102 53 109 70 54 48 103 53 84 75 55 70 73 109 120 98 90 80 84 48 95 115 76 120 68 79 68 83 118 68 74 56 121 77 98 111 101 100 108 110 97 82 83 108 119 115 68 105 56 50 89 86 77 48 83 73 78 117 121 83 109 112 52 52 70 75 86 101 101 112 107 87 100 113 101 78 97 83 111 72 95 85 118 49 114 112 103 120 77 99 53 98 106 105 68 73 101 83 99 114 76 106 100 73 87 111 73 112 51 99 113 72 116 69 106 104 56 70 84 76 73 95 69 105 45 116 116 116 49 80 81 68 83 81 117 76 106 101 112 117 121 109 80 83 73 54 48 90 67 87 70 78 75 108 85 111 49 95 122 82 84 90 70 116 78 72 108 51 68 72 104 52 50 103 120 88 97 108 98 50 78 77 110 67 77 52 51 109 110 54 89]
2023-01-13 19:52:07 +0000 UTC info: successfully received new authorization data from server https://mender.CHANGED_BUT_URL_WAS_OK.de
2023-01-13 19:52:07 +0000 UTC info: Local proxy started
2023-01-13 19:52:07 +0000 UTC info: Reauthorization successful
2023-01-13 19:52:07 +0000 UTC debug: Connecting to server http://127.0.0.1:43615
2023-01-13 19:52:07 +0000 UTC debug: Request: “” “” “https” “mender.CHANGED_BUT_URL_WAS_OK.de” “/api/devices/v1/deployments/device/deployments/8a4c244b-6074-416e-9b66-cd198e9f3214/status”
2023-01-13 19:52:07 +0000 UTC debug: Status reported, response 204 No Content
2023-01-13 19:52:08 +0000 UTC debug: Attempting to upload deployment logs for failed update

kacf · January 16, 2023, 7:35am

The second reboot is weird, it looks like it’s going back in time.

But it also sounds like the boot loader tools are not working correctly on the second partition. Can you add a state script, ArtifactReboot_Enter_00_Debug and ArtifactReboot_Leave_00_Debug where you execute grub-mender-grubenv-print, so that we can see what the environment is before and after the reboot?

Apart from that debugging, here are a few other things to try:

In general using an old server with a new client is not supported, only the opposite is (new server and old client). Try upgrading the server to the latest version.
Can you try installing a file update before you install a full rootfs-image update? Just install a dummy file in /tmp for example.

Topic		Replies	Views
Mender update - mender-client reverting back to previous boot partition in a loop General Discussions	0	458	January 25, 2022
Update-Loop - overwrite partition b, then a, again General Discussions	3	469	December 22, 2021
Getting "error: fw_setenv returned failure: exit status 2" after "Committing update" OTA update General Discussions debian , x86 , mender-client , ota	47	2221	June 22, 2021
Post-update reboot General Discussions	1	527	December 2, 2019
Partition didn't switch to another after Mender system update General Discussions mender-convert , mender-server , 340 , system , system-update , partition , switch , 300	3	389	November 8, 2022

Mender upate flag not set

Related topics