Mender-update 5.0.4 — malformed timestamp on non-UTC systems causes HTTP 400 on log upload

General Discussions
1

Hi, I just started setting up mender client on our Jetson Devices running 22.04 Linux for Tegra and ran into an issue:

Running mender-update 5.0.4 on Ubuntu 22.04 (Jammy) / ARM64 with system timezone
set to Europe/Berlin. Every deployment fails to upload logs to the server with:

Could not send deployment status: Bad response error: Got unexpected response 400
from logs API: parsing time “2026-03-02T17:20:05.293319Z00Z”: extra text: “00Z”

The timestamp “Z00Z” is malformed — it looks like the client formats the UTC time
with a trailing “Z” and then appends a UTC offset string on top, producing an invalid
RFC3339 timestamp that the server rejects.

Environment:

  • mender-update 5.0.4, installed via ubuntu/jammy/stable APT repo
  • Ubuntu 22.04, ARM64 (NVIDIA Jetson Orin Nano)
  • Timezone: Europe/Berlin (CET, +0100), NTP synced, TZ env var not set
  • date -u +"%Y-%m-%dT%H:%M:%S.%6NZ" produces a clean timestamp — issue is in
    the client’s formatting, not the system

Impact: deployment logs never reach the server, status reporting broken.

Workaround: unknown — does setting the system timezone to UTC fix this?

Has anyone else seen this on non-UTC systems? Is there a known fix or preferred
channel for client bugs?

Edit: i tried switching to UTC but still no luck unfortunately :frowning:

2

I tried downgrading to 5.0.1 and that works - so maybe a regression?

3

Hello @sandesh-nomadic and thank you for report.

Indeed this is a regression introduced in 5.0.4. Versions 5.0.3 and earlier are not affected.

I was able to reproduce and we created this ticket to follow it up:

One detail is that this bug only triggers if there is a corrupted log in the system. Or at least if mender-update detects that the log is corrupted.

So either your log is corrupted for some other reason or our the mechanism from mender-update to detect corruption in the log is flawed for some other issue.

If you have access to the device, would you mind sharing the deployment logs with us?

ls /var/lib/mender/deployments.*.log
cat /var/lib/mender/deployments.*.log

Thank you!

Lluís

4

Hello @lluiscampos ,

thank you for the answer and that you are able to reproduce - that’s great!

As I was just setting up mender I ran into a number of issues which I could not validate individually. I was already wondering how this was not yet reported if it was happening for all logs. I later found out that the log was indeed corrupt, because I ran a pip install inside a script and that printed non-ASCII characters (e.g. green progress bar etc.).

I fixed this by updating my update module to strip all non-ASCII characters and set pip to –no-color but did not know that this specifically then caused the time error. So I cannot share the logs right now but you can reproduce by just running a pip install that logs color to the terminal.

This means I should be able to update to 5.0.4 now that I have fixed the corrupt log, right?

What is the behavior if I encounter a corrupt log again?

  • on 5.0.3 it is not published because it is corrupt? Or will it still be uploaded somehow?
  • on 5.0.4 it is not published because we get this server rejected error

I am just wondering whether I can safely update because I don’t lose any logs with the new version.

Thanks,

Sandesh

5

Hello,

Sorry for my last response.

Before 5.0.4 the a client with corrupted logs will just fail to report them to the server, getting 400 by the server. We had bug forever, at least since 4.0.0.

Now, 5.0.4 has for the first time an attempted fix for this issue, which as you experienced is buggy. So in this regard the attempt to rescue the valid logs fails and ends up with also 400 errors from the server (what an irony, isn’t it?)

In short it is safe for you to run 5.0.4 as long as you don’t use that pip install command. It is as safe as 5.0.3 or earlier, meaning both will fail to report logs if there is binary data there.

We are working on a better fix as we speak, you can see the PR here:

So hopefully you will get this fix in 5.0.5 and 5.1.1 soon enough :wink:

Cheers,
Lluís

6

Hey Lluis,

I have a follow-up question: When I experience this issue, next to not seeing the log, the device also does not accept any further updates. Will this also be fixed in the issue you linked? Thank you!

Cheers,

Sandesh

7

Hi @sandesh-nomadic,

I have just discussed this with the developers, and the second issue you describe does not seem to be related. Can you provide a bit more detail on what you are seeing? Obvious things to check:

  • does the device check correctly for deployments?
  • or does the installation fail?
  • can you obtain the logs manually from a local device?

On which version are you now, specifically? Did you bump the Mender Client version manually via compilation, or did you stay with 5.0.4?

Greetz,
Josef

8

Hi Josef,

thank you for checking! The device does not check for updates, so the update always stays at pending in the platform. The logs just state the error in log upload (every few seconds) and nothing else, hence I assumed that it was stuck with a malformed log. I do not see the typical logs that it received a new update and starts installing it etc.

I found out that in one of these cases the log was just consisting of zeros \x00 and claude assumed it might be from a power outage during update which led to a file write. This then causes the log upload to fail and more importantly prevents further updates.

9

Hi @sandesh-nomadic,

That really sounds weird. Is the Mender service running? Can you check systemctl status on both mender-updated and mender-authd, and eventually the ownership/permission of the files in /data/mender? I’ve never heard of, or seen a similar situation so I really wonder what’s going on.

Greetz,
Josef

10

Hi Josef,

apologies for the late reply, I did not have time to look into this until now.

this is the log of update:

journalctl -u mender-updated.service -f
Mai 18 16:09:23 nomadic9020 mender-update[915]: record_id=53 severity=info time="2026-May-18 14:09:23.037859" name="Global" msg="Retrying status update after 1800 seconds"
Mai 18 16:39:23 nomadic9020 mender-update[915]: record_id=54 severity=info time="2026-May-18 14:39:23.038026" name="Global" msg="Sending status update to server"
Mai 18 16:39:24 nomadic9020 mender-update[915]: record_id=55 severity=error time="2026-May-18 14:39:24.106314" name="Global" msg="Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time "2026-05-12T16:42:53.043781Z00Z": extra text: "00Z""
Mai 18 16:39:24 nomadic9020 mender-update[915]: record_id=56 severity=info time="2026-May-18 14:39:24.106602" name="Global" msg="Retrying status update after 1800 seconds"
Mai 18 17:09:24 nomadic9020 mender-update[915]: record_id=57 severity=info time="2026-May-18 15:09:24.106804" name="Global" msg="Sending status update to server"
Mai 18 17:09:25 nomadic9020 mender-update[915]: record_id=58 severity=error time="2026-May-18 15:09:25.255668" name="Global" msg="Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time "2026-05-12T16:42:53.043781Z00Z": extra text: "00Z""
Mai 18 17:09:25 nomadic9020 mender-update[915]: record_id=59 severity=info time="2026-May-18 15:09:25.255917" name="Global" msg="Retrying status update after 1800 seconds"
Mai 18 17:39:25 nomadic9020 mender-update[915]: record_id=60 severity=info time="2026-May-18 15:39:25.256075" name="Global" msg="Sending status update to server"
Mai 18 17:39:26 nomadic9020 mender-update[915]: record_id=61 severity=error time="2026-May-18 15:39:26.365290" name="Global" msg="Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time "2026-05-12T16:42:53.043781Z00Z": extra text: "00Z""
Mai 18 17:39:26 nomadic9020 mender-update[915]: record_id=62 severity=info time="2026-May-18 15:39:26.365637" name="Global" msg="Retrying status update after 1800 seconds"

and of authd

l" msg="Termination signal received, shutting down gracefully"
Mai 15 18:12:37 nomadic9020 systemd[1]: mender-authd.service: Deactivated successfully.
Mai 15 18:12:37 nomadic9020 systemd[1]: Stopped Mender authentication service.
-- Boot 420ed8b3d3a84cedb5b933f9c46af976 --
Mai 18 14:37:05 nomadic9020 mender-auth[4541]: using interface /sys/class/net/enP8p1s0
Mai 18 14:37:05 nomadic9020 mender-auth[914]: record_id=8 severity=info time="2026-May-18 14:37:05.186142" name="Global" msg="Signing with: /var/lib/mender/mender-agent.pem"
Mai 18 14:37:05 nomadic9020 mender-auth[914]: record_id=9 severity=info time="2026-May-18 14:37:05.844573" name="Global" msg="Successfully received new authorization data"

status of the services
```

● mender-updated.service - Mender OTA update service
     Loaded: loaded (/lib/systemd/system/mender-updated.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mender-updated.service.d
             └─timezone.conf
     Active: active (running) since Thu 1970-01-01 01:00:37 CET; 56 years 4 months ago
   Main PID: 915 (mender-update)
      Tasks: 2 (limit: 8810)
     Memory: 8.4M
        CPU: 406ms
     CGroup: /system.slice/mender-updated.service
             └─915 /usr/bin/mender-update daemon

Mai 18 16:09:23 nomadic9020 mender-update[915]: record_id=53 severity=info time="2026-May-18 14:09:23.037859" name="Gl>
Mai 18 16:39:23 nomadic9020 mender-update[915]: record_id=54 severity=info time="2026-May-18 14:39:23.038026" name="Gl>
Mai 18 16:39:24 nomadic9020 mender-update[915]: record_id=55 severity=error time="2026-May-18 14:39:24.106314" name="G>
Mai 18 16:39:24 nomadic9020 mender-update[915]: record_id=56 severity=info time="2026-May-18 14:39:24.106602" name="Gl>
Mai 18 17:09:24 nomadic9020 mender-update[915]: record_id=57 severity=info time="2026-May-18 15:09:24.106804" name="Gl>
Mai 18 17:09:25 nomadic9020 mender-update[915]: record_id=58 severity=error time="2026-May-18 15:09:25.255668" name="G>
Mai 18 17:09:25 nomadic9020 mender-update[915]: record_id=59 severity=info time="2026-May-18 15:09:25.255917" name="Gl>
Mai 18 17:39:25 nomadic9020 mender-update[915]: record_id=60 severity=info time="2026-May-18 15:39:25.256075" name="Gl>
Mai 18 17:39:26 nomadic9020 mender-update[915]: record_id=61 severity=error time="2026-May-18 15:39:26.365290" name="G>
Mai 18 17:39:26 

● mender-authd.service - Mender authentication service
     Loaded: loaded (/lib/systemd/system/mender-authd.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 1970-01-01 01:00:39 CET; 56 years 4 months ago
   Main PID: 914 (mender-auth)
      Tasks: 2 (limit: 8810)
     Memory: 8.7M
        CPU: 767ms
     CGroup: /system.slice/mender-authd.service
             └─914 /usr/bin/mender-auth daemon

Jan 01 01:00:37 nomadic9020 mender-auth[914]: record_id=3 severity=info time="1970-Jan-01 01:00:37.683425" name="Globa>
Jan 01 01:00:39 nomadic9020 systemd[1]: Started Mender authentication service.
Jan 01 01:00:41 nomadic9020 mender-auth[2280]: using interface /sys/class/net/enP8p1s0
Jan 01 01:00:41 nomadic9020 mender-auth[914]: record_id=4 severity=info time="1970-Jan-01 01:00:41.963673" name="Globa>
Jan 01 01:00:47 nomadic9020 mender-auth[914]: record_id=5 severity=error time="1970-Jan-01 01:00:47.243602" name="http>
Jan 01 01:00:47 nomadic9020 mender-auth[914]: record_id=6 severity=info time="1970-Jan-01 01:00:47.245240" name="Globa>
Jan 01 01:00:47 nomadic9020 mender-auth[914]: record_id=7 severity=error time="1970-Jan-01 01:00:47.245358" name="Glob>
Mai 18 14:37:05 nomadic9020 mender-auth[4541]: using interface /sys/class/net/enP8p1s0
Mai 18 14:37:05 nomadic9020 mender-auth[914]: record_id=8 severity=info time="2026-May-18 14:37:05.186142" name="Globa>
Mai 18 14:37:05 nomadic9020 mender-auth[91

sudo ls -lh /data/mender
ls: cannot access '/data/mender': No such file or directory

checking a deployment log, maybe it is related to time being in 1970 on service launch, although the logs do not look like it:

{"timestamp":"1970-01-01T00:00:41.865489Z","level":"info","message":"Running mender-update 5.1.0"}
{"timestamp":"1970-01-01T00:00:41.868909Z","level":"info","message":"The update client daemon is now ready to handle incoming deployments"}
{"timestamp":"1970-01-01T00:00:41.869071Z","level":"info","message":"Sending status update to server"}
{"timestamp":"1970-01-01T00:00:47.246727Z","level":"error","message":"Failed to set new authentication data on HTTP request"}
{"timestamp":"1970-01-01T00:00:47.246925Z","level":"error","message":"Request to push status data failed: Cannot submit API request"}
{"timestamp":"1970-01-01T00:00:47.246983Z","level":"error","message":"Could not send deployment status: Unauthorized error: Cannot submit API request"}
{"timestamp":"1970-01-01T00:00:47.247022Z","level":"info","message":"Retrying status update after 60 seconds"}
{"timestamp":"2026-05-18T12:37:05.106650Z","level":"info","message":"Sending status update to server"}
{"timestamp":"2026-05-18T12:37:08.360317Z","level":"error","message":"Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time \"2026-05-12T16:42:53.043781Z00Z\": extra text: \"00Z\""}
{"timestamp":"2026-05-18T12:37:08.360562Z","level":"info","message":"Retrying status update after 60 seconds"}
{"timestamp":"2026-05-18T12:38:08.360754Z","level":"info","message":"Sending status update to server"}
{"timestamp":"2026-05-18T12:38:09.495374Z","level":"error","message":"Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time \"2026-05-12T16:42:53.043781Z00Z\": extra text: \"00Z\""}
{"timestamp":"2026-05-18T12:38:09.495666Z","level":"info","message":"Retrying status update after 60 seconds"}
{"timestamp":"2026-05-18T12:39:09.495908Z","level":"info","message":"Sending status update to server"}
{"timestamp":"2026-05-18T12:39:10.605006Z","level":"error","message":"Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time \"2026-05-12T16:42:53.043781Z00Z\": extra text: \"00Z\""}
{"timestamp":"2026-05-18T12:39:10.605291Z","level":"info","message":"Retrying status update after 120 seconds"}
{"timestamp":"2026-05-18T12:41:10.605468Z","level":"info","message":"Sending status update to server"}
{"timestamp":"2026-05-18T12:41:11.600372Z","level":"error","message":"Could not send deployment status: Bad response error: Got unexpected response 400 from logs API: parsing time \"2026-05-12T16:42:53.043781Z00Z\": extra text: \"00Z\""}
{"timestamp":"2026-05-18T12:41:11.600648Z","level":"info","message":"Retrying status update after 120 seconds"}
{"timestamp":"2026-05-18T12:43:11.600843Z","level":"info","message":"Sending status update to server"}

I did some digging with claude and found that potentially during shutdown the files contain a lot of empty zeroes

tr -d '\0' < /var/lib/mender/deployments.0000.67f88509-35fa-4c24-8cf5-a533fb5b91e8.log | cmp -s - ... && echo SAME || echo HAS-NULLS
HAS-NULLS

deleting these files with this script

#!/bin/bash

shopt -s nullglob
for f in /var/lib/mender/deployments.*.log; do
    if ! tr -d '\0' < "$f" | cmp -s - "$f"; then
        rm -f "$f" && echo "Removed corrupt deployment log: $f" | systemd-cat -t mender-clean
    fi
done
exit 0

leads to

ai 18 18:04:21 nomadic9020 systemd[1]: Stopped Mender OTA update service.
Mai 18 18:04:21 nomadic9020 systemd[1]: Started Mender OTA update service.
Mai 18 18:04:21 nomadic9020 mender-update[275540]: record_id=1 severity=error time="2026-May-18 16:04:21.054560" name="Global" msg="State loop detected. Forcefully aborting update."
Mai 18 18:04:21 nomadic9020 mender-update[275540]: record_id=2 severity=info time="2026-May-18 16:04:21.055048" name="Global" msg="Running mender-update 5.1.0"
Mai 18 18:04:21 nomadic9020 mender-update[275540]: record_id=3 severity=info time="2026-May-18 16:04:21.056020" name="Global" msg="The update client daemon is now ready to handle incoming deployments"
Mai 18 18:04:21 nomadic9020 mender-update[275540]: record_id=4 severity=info time="2026-May-18 16:04:21.056109" name="Global" msg="Sending status update to server"
Mai 18 18:04:22 nomadic9020 mender-update[275540]: record_id=5 severity=info time="2026-May-18 16:04:22.016751" name="Global" msg="Deployment with ID 67f88509-35fa-4c24-8cf5-a533fb5b91e8 finished with status: Failure"
Mai 18 18:04:22 nomadic9020 mender-update[275540]: record_id=6 severity=info time="2026-May-18 16:04:22.708925" name="Global" msg="Inventory data submitted successfully"
Mai 18 18:04:23 nomadic9020 mender-update[275540]: record_id=7 severity=info time="2026-May-18 16:04:23.192862" name="Global" msg="No update available"
Mai 18 18:04:23 nomadic9020 mender-update[275540]: record_id=8 severity=info time="2026-May-18 16:04:23.486221" name="Global" msg="Inventory data unchanged, not submitting"

and the device accepting updates again.

As quickfix, claude suggested adding this script to the systemd service definiton with ExecPreStart to ensure a clean start. I have not tried doing that but it seems plausible to me that this would work.

I hope this info helps and I am happy test more things report more specific things if you need to help fix it.

Best,

Sandesh

11

HI @sandesh-nomadic,

Thanks for getting back to it! Not sure yet what to make of it though. Especially the /data/mender thing makes me wonder. This is roughly how it should look like:

root@beagleplay-ti:~# ls -alh /data/mender
drwxr-xr-x    2 root     root        1.0K Apr  5  2011 .
drwxr-xr-x    5 root     root        1.0K Apr  5  2011 ..
-r--r--r--    1 root     root          26 Apr  5  2011 device_type
-rw-------    1 root     root         119 Apr  5  2011 mender-agent.pem
-rw-------    1 root     root       12.0K Apr  5  2011 mender-store
-rw-------    1 root     root        8.1K May 21 14:03 mender-store-lock
-rw-------    1 root     root          76 Apr  5  2011 mender.conf

So my question now is, where does the Mender Client store its persistent data and keys in your case? Can you provide the output of mount -a and the content of /etc/fstab?

Greetz,
Josef