Unable to deploy artifacts after upgrading to mender 4 - "bad version"

[dguidali]

Hello,

We’re in the process of updating our image to use Mender 4.0.4. While the update appears to be successful so far and Mender Connect is operational, we’re encountering issues with deploying new artifacts. Below is the relevant log excerpt:

2024-11-12 12:27:34.371 +0000 UTC info: Running Mender client 4.0.4
2024-11-12 12:27:34.371 +0000 UTC info: Deployment with ID c386ad1b-542f-4e9f-9c2a-ab8d3e1f0d1c started.
2024-11-12 12:27:34.372 +0000 UTC info: Sending status update to server
2024-11-12 12:27:34.706 +0000 UTC warning: bad version: GET https://fleet.buhlergroup.io/604b82bba77083903ec22d9c/2babaf5e-8163-4acd-a570-6e6a4ba30182?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAQWI25QR6G4QXCGXC%2F20241112%2Feu-central-1%2Fs3%2Faws4_request&X-Amz-Date=20241112T122734Z&X-Amz-Expires=86400&X-Amz-Signature=cd47b8e0b0c4df86a279b99a6965aae29a8f8bd34dd0622159fde8c320630c1f&X-Amz-SignedHeaders=host&response-content-disposition=attachment%3B+filename%3D%22X2J6Z-configuration-2024-11-12T12%3A26%3A39.mender%22&response-content-type=application%2Fvnd.mender-artifact&x-id=GetObject: 
2024-11-12 12:27:34.706 +0000 UTC info: Resuming download after 60 seconds
2024-11-12 12:28:34.814 +0000 UTC warning: bad version: GET https://fleet.buhlergroup.io/604b82bba77083903ec22d9c/2babaf5e-8163-4acd-a570-6e6a4ba30182?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAQWI25QR6G4QXCGXC%2F20241112%2Feu-central-1%2Fs3%2Faws4_request&X-Amz-Date=20241112T122734Z&X-Amz-Expires=86400&X-Amz-Signature=cd47b8e0b0c4df86a279b99a6965aae29a8f8bd34dd0622159fde8c320630c1f&X-Amz-SignedHeaders=host&response-content-disposition=attachment%3B+filename%3D%22X2J6Z-configuration-2024-11-12T12%3A26%3A39.mender%22&response-content-type=application%2Fvnd.mender-artifact&x-id=GetObject: 
2024-11-12 12:28:34.815 +0000 UTC info: Resuming download after 60 seconds
2024-11-12 12:29:34.91 +0000 UTC warning: bad version: GET https://fleet.buhlergroup.io/604b82bba77083903ec22d9c/2babaf5e-8163-4acd-a570-6e6a4ba30182?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAQWI25QR6G4QXCGXC%2F20241112%2Feu-central-1%2Fs3%2Faws4_request&X-Amz-Date=20241112T122734Z&X-Amz-Expires=86400&X-Amz-Signature=cd47b8e0b0c4df86a279b99a6965aae29a8f8bd34dd0622159fde8c320630c1f&X-Amz-SignedHeaders=host&response-content-disposition=attachment%3B+filename%3D%22X2J6Z-configuration-2024-11-12T12%3A26%3A39.mender%22&response-content-type=application%2Fvnd.mender-artifact&x-id=GetObject: 
2024-11-12 12:29:34.91 +0000 UTC info: Resuming download after 60 seconds

Key Points:

• We use a proxy (a simple YARP server in C#) to route our requests to the hosted Mender service. This proxy worked with the previous version of the Mender client without any issues and has not been modified.
• We use Hosted Mender (https://hosted.mender.io).
• No changes were made to the format or content of the artifacts.
• The artifacts are version 3.
• We can download the artifacts successfully using curl on the affected devices.
• This is not a network issue; we tested it on multiple networks.
• We performed a tcpdump and found that the client sends a “reset” flag for the request, but the root cause is still unclear.
• The logging levels for both mender-authd and mender-updated are set to trace, but we didn’t find any additional information.

Any insights or suggestions would be greatly appreciated.

[TheYoctoJester]

Hi @dguidali,

Thanks for reaching out! To understand the problem a bit better, can you describe if this is built from source, through Yocto or some other process? Or do you install the Mender Client from the Debian repositories?

Greetz,
Josef

[dguidali]

Hi @TheYoctoJester,

We’re installing it via Yocto using the https://github.com/mendersoftware/meta-mender.git repository. Do you have any insights into why downloading the artifact via curl works, but the mender client fails? Additionally, could you shed some light on where the “bad version” issue might be originating from?

I’ve found a similar issue here, but unfortunately there are no answers to this:

Mender-Client 4.0.1 is failing to update deployment status

I tried to create a deployment on a device with mender-client4 installed in it. The deployment started successfully and the state scripts ran too. But the client was not able to report the status to the server, and was giving the following error logs. Mar 12 17:37:50 ZenGateway-438 mender-update[23995]: record_id=2575 severity=info time="2024-Mar-12 17:37:50.962356" name="Global" msg="Sending status update to server" Mar 12 17:37:50 ZenGateway-438 mender-update[23995]: record_id=2576 severity=…

Thanks for your help!

[dguidali]

Mysterious Deployment Issue with Mender

I’ve encountered a puzzling issue: deploying the same artifact to the same device produced inconsistent results.

• The first two deployments succeeded without issues.
• The third deployment failed with the following log:

2024-11-29 10:32:58.165 +0000 UTC info: Running Mender client 4.0.4
2024-11-29 10:32:58.165 +0000 UTC info: Deployment with ID 9d15bae0-c9f8-41dc-ba7f-07bbdaef1012 started.
2024-11-29 10:32:58.165 +0000 UTC info: Sending status update to server
2024-11-29 10:32:58.525 +0000 UTC info: Installing artifact...
2024-11-29 10:32:58.569 +0000 UTC error: Error reading the next tar entry: Superfluous data at the end of the archive: Reached the end of the archive:
2024-11-29 10:32:58.569 +0000 UTC error: Parse error: Unexpected token: Unrecognized
2024-11-29 10:32:58.574 +0000 UTC info: Sending status update to server

• The fourth and fifth deployments returned the familiar “bad version” message mentioned earlier in this thread.

Could this be caused by the Mender client caching or storing state? We’re not using “Mender Gateway,” so there shouldn’t be any caching there.

What could be causing this erratic behavior?

[TheYoctoJester]

Hi @dguidali,

yeah, finding that specific third deployment log points to some caching issue. To my understanding there shouldn’t be any, but need to investigate here.

Greetz,
Josef

[dguidali]

Hi @TheYoctoJester

Here are some deployment IDs. Its on hosted mender, so I hope it’ll help you troubleshooting:

Deployment 1 (worked): 87ee6ac5-341e-4a73-af35-ede17f3d701f
Deployment 2 (worked): 3a29f9a6-afc8-4f0e-b953-8f53cd1b7263
Deployment 3 (did not work, superflous data error): 9d15bae0-c9f8-41dc-ba7f-07bbdaef1012
Deployment 4 (did not work, bad version error): f2de60f0-4391-4674-8677-01abb01eab7f
Deployment 5 (did not work, bad version error): 9c507366-6e4a-4cf9-a816-6ce4212efb8a

[lluiscampos]

Hi @dguidali and thanks for your good report (and your patience )

Have you tried restarting the device? To rule out that is a caching issue of some sort, once you get this error state if we restart it should do back to be able o successfully deploy. This will give use more clues on where to look for the problem.

Thanks,

Lluis

[dguidali]

Hi @lluiscampos
Thanks for your reply. Yes we tried to restart it multiple times, and we get this issue actually on most of our devices. Interestingly, we always get this error first, before we get the bad version error:

2024-11-29 10:32:58.569 +0000 UTC error: Error reading the next tar entry: Superfluous data at the end of the archive: Reached the end of the archive:

Is the hosted mender server maybe doing some caching? Or does mender store any data on the device which we might try to delete?

The Superfluous data error is anyway strange, since it happens for some deployments whereas it doesn’t or others, although the same artifacts are deployed.

[lluiscampos]

Let me ask differently.

A device with a pattern like above (success → superflous data → bad version), will recover after a reboot?

Recover in the sense that manages to have at least one successfuly deployment (before going again into superflous data, then bad version, etc).

Thanks

[dguidali]

The behavior we observe follows this pattern:

1. Success
2. Superfluous data
3. Bad version
4. Reboot
5. Superfluous data
6. Bad version

It seems the primary issue is related to the presence of superfluous data, but we have no idea why this occurs. We haven’t made any changes to the artifact generation process, and the same artifacts work perfectly fine with Mender 3.x. Moreover, it is possible to install and verify these artifacts using mender-artifact, which suggests that the problem might lie within the mender-update daemon.

I noticed that there’s some validation of the EOF (End of File) in src\artifact\tar\platform\libarchive\wrapper.cpp, where a respective error is returned. However, I’m not a C++ developer, and my expertise in that area is quite limited.

[dguidali]

This artifact gives me the error even after rebooting the device.

2024-12-01 10:51:45.595 +0000 UTC info: Running Mender client 4.0.4
2024-12-01 10:51:45.595 +0000 UTC info: Deployment with ID 061e6267-bb7e-4c4c-b5ce-ce36d8958c48 started.
2024-12-01 10:51:45.595 +0000 UTC trace: Entering state N6mender6update6daemon19deployment_tracking15NoFailuresStateE
2024-12-01 10:51:45.595 +0000 UTC trace: Entering state N6mender6update6daemon16StateScriptStateE
2024-12-01 10:51:45.595 +0000 UTC debug: Executing the  SyncLeave State Scripts...
2024-12-01 10:51:45.595 +0000 UTC debug: Successfully ran the SyncLeave State Scripts...
2024-12-01 10:51:45.595 +0000 UTC trace: Entering state N6mender6update6daemon21SendStatusUpdateStateE
2024-12-01 10:51:45.595 +0000 UTC info: Sending status update to server
2024-12-01 10:51:45.595 +0000 UTC debug: Pushing deployment status: downloading
2024-12-01 10:51:45.596 +0000 UTC debug: Got authentication token for server http://127.0.0.1:39767
2024-12-01 10:51:45.596 +0000 UTC trace: URL broken down into (protocol: http), (host: 127.0.0.1), (port: 39767), (path: /api/devices/v1/deployments/device/deployments/061e6267-bb7e-4c4c-b5ce-ce36d8958c48/status),(username: ), (password: )
2024-12-01 10:51:45.596 +0000 UTC trace: Setting HOST address: 127.0.0.1:39767
2024-12-01 10:51:45.596 +0000 UTC debug: Hostname 127.0.0.1 resolved to [127.0.0.1]
2024-12-01 10:51:45.596 +0000 UTC debug: Connected to 127.0.0.1
2024-12-01 10:51:45.596 +0000 UTC trace: Wrote 888 bytes of header data to stream.
2024-12-01 10:51:45.596 +0000 UTC trace: Wrote 24 bytes of body data to stream.
2024-12-01 10:51:45.855 +0000 UTC trace: Read 345 bytes of header data from stream.
2024-12-01 10:51:45.855 +0000 UTC debug: Received response: 204 No Content
2024-12-01 10:51:45.855 +0000 UTC debug: Received headers:
Date: Sun, 01 Dec 2024 09:51:45 GMT
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Server: Kestrel
Strict-Transport-Security: max-age=31536000
Request-Context: appId=cid-v1:1a80e9d5-9ca4-440d-a5e9-7adf7614b360
Referrer-Policy: no-referrer
x-men-requestid: 69cbb8bf-be38-45e5-b617-ff57417425a6
2024-12-01 10:51:45.855 +0000 UTC debug: Failed to get content length from the status API response headers: No such header: No such header: Content-Length
2024-12-01 10:51:45.856 +0000 UTC trace: Entering state N6mender6update6daemon20SaveStateScriptStateE
2024-12-01 10:51:45.856 +0000 UTC trace: Storing deployment state in the DB (database-string): update-store
2024-12-01 10:51:45.859 +0000 UTC debug: Executing the  DownloadEnter State Scripts...
2024-12-01 10:51:45.859 +0000 UTC debug: Successfully ran the DownloadEnter State Scripts...
2024-12-01 10:51:45.859 +0000 UTC trace: Entering state N6mender6update6daemon19UpdateDownloadStateE
2024-12-01 10:51:45.859 +0000 UTC debug: Entering Download state
2024-12-01 10:51:45.859 +0000 UTC trace: URL broken down into (protocol: https), (host: fleet.buhlergroup.io), (port: 443), (path: /604b82bba77083903ec22d9c/7c314c41-6854-446e-854a-76c4ce7b10b3?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAQWI25QR6G4QXCGXC%2F20241201%2Feu-central-1%2Fs3%2Faws4_request&X-Amz-Date=20241201T095145Z&X-Amz-Expires=86400&X-Amz-Signature=743493072ff20b3a1c4984ac39401f5fc75afa2a3c44e615c3d33fc491d35d60&X-Amz-SignedHeaders=host&response-content-disposition=attachment%3B+filename%3D%22N5H3Z-configuration-2024-12-01T09%3A37%3A26.mender%22&response-content-type=application%2Fvnd.mender-artifact&x-id=GetObject),(username: ), (password: )
2024-12-01 10:51:45.859 +0000 UTC trace: Setting HOST address: fleet.buhlergroup.io
2024-12-01 10:51:45.863 +0000 UTC debug: Hostname fleet.buhlergroup.io resolved to [20.105.216.11]
2024-12-01 10:51:45.919 +0000 UTC debug: https: Successful SSL handshake
2024-12-01 10:51:45.919 +0000 UTC debug: Connected to 20.105.216.11
2024-12-01 10:51:45.92 +0000 UTC trace: Wrote 560 bytes of header data to stream.
2024-12-01 10:51:46.041 +0000 UTC trace: Read 709 bytes of header data from stream.
2024-12-01 10:51:46.042 +0000 UTC debug: Received response: 200 OK
2024-12-01 10:51:46.042 +0000 UTC debug: Received headers:
Content-Length: 10240
Content-Type: application/vnd.mender-artifact
Date: Sun, 01 Dec 2024 09:51:46 GMT
Server: AmazonS3
Accept-Ranges: bytes
ETag: "860b4e9105429a9bb8162b85544ab72b"
Last-Modified: Sun, 01 Dec 2024 09:37:27 GMT
Strict-Transport-Security: max-age=31536000
Request-Context: appId=cid-v1:1a80e9d5-9ca4-440d-a5e9-7adf7614b360
x-amz-id-2: TT/zCnMC3k5NPNmbxNGi/D1cPGXFFWAFY6uLoKnbSJ63rsUoyHDCi/sI/aSEljn8hwMefzwFXwA=
x-amz-request-id: ET9PVGBXP0NNPANB
x-amz-replication-status: FAILED
x-amz-server-side-encryption: AES256
x-amz-version-id: PHKX6YyeGYrWpSA0jfC5SxGbRUOziTWL
Content-Disposition: attachment; filename="N5H3Z-configuration-2024-12-01T09:37:26.mender"
2024-12-01 10:51:46.042 +0000 UTC trace: Read 2111 bytes of body data from stream.
2024-12-01 10:51:46.042 +0000 UTC debug: read 2111 bytes
2024-12-01 10:51:46.042 +0000 UTC trace: Entry name: version
2024-12-01 10:51:46.042 +0000 UTC trace: Parsing Version
2024-12-01 10:51:46.042 +0000 UTC trace: Parsing the Manifest
2024-12-01 10:51:46.042 +0000 UTC trace: Entry name: manifest
2024-12-01 10:51:46.042 +0000 UTC trace: Read 2820 bytes of body data from stream.
2024-12-01 10:51:46.042 +0000 UTC debug: read 2820 bytes
2024-12-01 10:51:46.042 +0000 UTC trace: Entry name: manifest.sig
2024-12-01 10:51:46.042 +0000 UTC trace: Entry name: header.tar.gz
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the Header
2024-12-01 10:51:46.043 +0000 UTC trace: Entry name: header-info
2024-12-01 10:51:46.043 +0000 UTC trace: StringToType: header-info
2024-12-01 10:51:46.043 +0000 UTC trace: Parse(header-info)
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the payloads
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the header-info artifact_provides
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the header-info provides:artifact_name
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the header-info provides:artifact_group (if any)
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the header-info depends:artifact_depends (if any)
2024-12-01 10:51:46.043 +0000 UTC trace: Entry name: headers/0000/type-info
2024-12-01 10:51:46.043 +0000 UTC trace: StringToType: headers/0000/type-info
2024-12-01 10:51:46.043 +0000 UTC trace: Parsing the sub-header ...
2024-12-01 10:51:46.043 +0000 UTC trace: Parse(type-info)...
2024-12-01 10:51:46.043 +0000 UTC trace: type-info: Parsing the payload type
2024-12-01 10:51:46.044 +0000 UTC trace: type-info: Parsing the artifact_provides
2024-12-01 10:51:46.044 +0000 UTC trace: type-info: Parsing the artifact_depends
2024-12-01 10:51:46.044 +0000 UTC trace: No artifact_depends found in type-info
2024-12-01 10:51:46.044 +0000 UTC trace: type-info: Parsing the clears_artifact_provides
2024-12-01 10:51:46.044 +0000 UTC trace: Finished parsing the type-info..
2024-12-01 10:51:46.044 +0000 UTC trace: sub-header: looking for meta-data
2024-12-01 10:51:46.044 +0000 UTC trace: sub-header: parsed the meta-data
2024-12-01 10:51:46.044 +0000 UTC info: Installing artifact...
2024-12-01 10:51:46.076 +0000 UTC trace: Read 4096 bytes of body data from stream.
2024-12-01 10:51:46.076 +0000 UTC debug: read 4096 bytes
2024-12-01 10:51:46.076 +0000 UTC trace: Entry name: data/0000.tar.gz
2024-12-01 10:51:46.076 +0000 UTC trace: Parsing the payload
2024-12-01 10:51:46.077 +0000 UTC debug: Calling Update Module with command `/usr/share/mender/modules/v3/gateway-configuration Download /var/lib/mender/modules/v3/payloads/0000/tree`.
2024-12-01 10:51:46.079 +0000 UTC trace: Wrote 876 bytes to Update Module
2024-12-01 10:51:46.079 +0000 UTC debug: Downloaded all files to `files` directory.
2024-12-01 10:51:46.08 +0000 UTC trace: Read 1 bytes of body data from stream.
2024-12-01 10:51:46.08 +0000 UTC debug: read 1 bytes
2024-12-01 10:51:46.08 +0000 UTC error: Error reading the next tar entry: Superfluous data at the end of the archive: Reached the end of the archive: 
2024-12-01 10:51:46.08 +0000 UTC error: Parse error: Unexpected token: Unrecognized
2024-12-01 10:51:46.08 +0000 UTC trace: Entering state N6mender6update6daemon19deployment_tracking12FailureStateE
2024-12-01 10:51:46.08 +0000 UTC trace: Entering state N6mender6update6daemon16StateScriptStateE
2024-12-01 10:51:46.08 +0000 UTC debug: Executing the  DownloadError State Scripts...
2024-12-01 10:51:46.08 +0000 UTC debug: Successfully ran the DownloadError State Scripts...
2024-12-01 10:51:46.08 +0000 UTC trace: Entering state N6mender6update6daemon29UpdateRollbackSuccessfulStateE
2024-12-01 10:51:46.08 +0000 UTC trace: Entering state N6mender6update6daemon18UpdateCleanupStateE
2024-12-01 10:51:46.08 +0000 UTC trace: Storing deployment state in the DB (database-string): cleanup
2024-12-01 10:51:46.083 +0000 UTC debug: Entering ArtifactCleanup state
2024-12-01 10:51:46.086 +0000 UTC trace: Entering state N6mender6update6daemon21SendStatusUpdateStateE
2024-12-01 10:51:46.086 +0000 UTC info: Sending status update to server
2024-12-01 10:51:46.086 +0000 UTC debug: Pushing deployment status: failure
2024-12-01 10:51:46.087 +0000 UTC debug: Got authentication token for server http://127.0.0.1:39767
2024-12-01 10:51:46.087 +0000 UTC trace: URL broken down into (protocol: http), (host: 127.0.0.1), (port: 39767), (path: /api/devices/v1/deployments/device/deployments/061e6267-bb7e-4c4c-b5ce-ce36d8958c48/status),(username: ), (password: )
2024-12-01 10:51:46.087 +0000 UTC trace: Setting HOST address: 127.0.0.1:39767
2024-12-01 10:51:46.087 +0000 UTC debug: Hostname 127.0.0.1 resolved to [127.0.0.1]
2024-12-01 10:51:46.087 +0000 UTC debug: Connected to 127.0.0.1
2024-12-01 10:51:46.087 +0000 UTC trace: Wrote 888 bytes of header data to stream.
2024-12-01 10:51:46.087 +0000 UTC trace: Wrote 20 bytes of body data to stream.
2024-12-01 10:51:51.328 +0000 UTC trace: Read 345 bytes of header data from stream.
2024-12-01 10:51:51.328 +0000 UTC debug: Received response: 204 No Content
2024-12-01 10:51:51.33 +0000 UTC debug: Received headers:
Date: Sun, 01 Dec 2024 09:51:51 GMT
X-Content-Type-Options: nosniff
X-XSS-Protection: 1; mode=block
Server: Kestrel
Strict-Transport-Security: max-age=31536000
Request-Context: appId=cid-v1:1a80e9d5-9ca4-440d-a5e9-7adf7614b360
Referrer-Policy: no-referrer
x-men-requestid: 04f9449a-e412-45f6-bec2-076ff9593e93
2024-12-01 10:51:51.33 +0000 UTC debug: Failed to get content length from the status API response headers: No such header: No such header: Content-Length

It is easily reproducable after restarting the device and recreating the deployment, the error appears again. Is there something wrong with the artifact? I cant find an issue there.

[eystein]

We have a similar bug here, it’s private unfortunately due to containing some non-public user information: Jira

However if it’s the same issue then we are working on a fix now.

[dguidali]

Hi
We’re still testing it, but at the moment it looks like this PR fixed the issue:

fix: Allow blocks of zeroes after ArchiveEOF

[dguidali]

Our tests have been successful so far. We ran multiple tests on our hardware and various VM images and could no longer reproduce the error. I believe the issue can be closed.

Thanks for your help.