Cannot send inventory

General Discussions
1

Hello all,

we tried a deployment to a group of devices and got a failure with no option for log output.
Reading the journal from that device we repeatedly see these lines:

Dec 27 13:30:17 hostname mender[283]: time="2021-12-27T13:30:17Z" level=info msg="State transition: update-retry-report [none] -> update-status-report [none]"
Dec 27 13:30:20 hostname mender[283]: time="2021-12-27T13:30:20Z" level=error msg="Got unexpected HTTP status when uploading log: 400"
Dec 27 13:30:20 hostname mender[283]: time="2021-12-27T13:30:20Z" level=error msg="error uploading logs: (request_id: ): uploading logs failed, bad status 400 server error message: no messages: invalid deployment log"
Dec 27 13:30:20 hostname mender[283]: time="2021-12-27T13:30:20Z" level=error msg="Failed to report deployment logs: transient error: (request_id: ): uploading logs failed, bad status 400 server error message: no messages: invalid deployment log"
Dec 27 13:30:20 hostname mender[283]: time="2021-12-27T13:30:20Z" level=error msg="Failed to send deployment logs to server: transient error: failed to send deployment logs: transient error: (request_id: ): uploading logs failed, bad status 400 server error message: no messages: invalid deployment log"
Dec 27 13:30:20 hostname mender[283]: time="2021-12-27T13:30:20Z" level=info msg="State transition: update-status-report [none] -> update-retry-report [none]"

We had an older mender artifact on site so we performed a manual mender install artifact.mender, all went well, rebooted to new partition, committed successfully but same errors appear and mender cloud still reports previous version.

The command echo string | nc hosted.mender.io 443 reports correctly 400 Bad Request as it should. Also nslookup seems fine:

nslookup hosted.mender.io
Server:    8.8.8.8
Address 1: 8.8.8.8 dns.google

Name:      hosted.mender.io
Address 1: 3.217.79.33 ec2-3-217-79-33.compute-1.amazonaws.com
Address 2: 54.162.248.127 ec2-54-162-248-127.compute-1.amazonaws.com

Any idea how we can get out of this?

2

Something possibly timed-out and did send correct inventory to server so we retried another manual install with that same old artifact and it did reboot ok and committed and updated the server fine but once we started another cloud based deployment we got an instant failure and journal reported this:

Dec 27 14:17:21 hostname mender[284]: time="2021-12-27T14:17:21Z" level=info msg="Forced wake-up from sleep"
Dec 27 14:17:21 hostname mender[284]: time="2021-12-27T14:17:21Z" level=info msg="Forcing state machine to: update-check"
Dec 27 14:17:21 hostname mender[284]: time="2021-12-27T14:17:21Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Dec 27 14:17:22 hostname mender[284]: time="2021-12-27T14:17:22Z" level=info msg="Correct request for getting image from: https://s3.amazonaws.com/hosted-mender-artifacts/5f4cabcfxxx200f34/ad9051f8-1ce1-4b9xxxafb052b?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAQWI2xxxLMYE2%2F20xxx227%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20211227T141722Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=ee2a1984dxxx98f7e8e60e385a7c8bd0c467c3a2e2774e [name: base-1.0.0; devices: [ds-pi]]"
Dec 27 14:17:22 hostname mender[284]: time="2021-12-27T14:17:22Z" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]"
Dec 27 14:17:22 hostname mender[284]: time="2021-12-27T14:17:22Z" level=info msg="State transition: update-fetch [Download_Enter] -> update-status-report [none]"
Dec 27 14:17:29 hostname mender[284]: time="2021-12-27T14:17:29Z" level=error msg="Got unexpected HTTP status when uploading log: 400"
Dec 27 14:17:29 hostname mender[284]: time="2021-12-27T14:17:29Z" level=error msg="error uploading logs: (request_id: ): uploading logs failed, bad status 400 server error message: no messages: invalid deployment log"
Dec 27 14:17:29 hostname mender[284]: time="2021-12-27T14:17:29Z" level=error msg="Failed to report deployment logs: transient error: (request_id: ): uploading logs failed, bad status 400 server error message: no messages: invalid deployment log"
Dec 27 14:17:29 hostname mender[284]: time="2021-12-27T14:17:29Z" level=error msg="Failed to send deployment logs to server: transient error: failed to send deployment logs: transient error: (request_id: ): uploading logs failed, bad status 400 server error message: no messages: invalid deployment log"
Dec 27 14:17:29 hostname mender[284]: time="2021-12-27T14:17:29Z" level=info msg="State transition: update-status-report [none] -> update-retry-report [none]"

So we are still stuck… Please help :slight_smile:

3

Hi @bender

Just to start out, can you have a look at the deployment log files on the device?

These should be stored in /var/lib/mender/ and look like deployment.<time>.log.

4

Nothing found from the recent attempts. Actually only one log which seems to be when the problem started (but gone unnoticed until now) a few months ago:

# cat deployments.0002.47333005-770d-4522-bcde-3f562418a2ea.log 
{"level":"info","message":"Running Mender client version: 2.3.0-dirty","timestamp":"2021-07-12T11:26:38Z"}
{"level":"info","message":"State transition: update-fetch [Download_Enter] -\u003e update-store [Download_Enter]","timestamp":"2021-07-12T11:26:43Z"}
{"level":"info","message":"Installer: authenticated digital signature of artifact","timestamp":"2021-07-12T11:26:44Z"}
{"level":"error","message":"Cannot check update or update inventory while in update-after-store state","timestamp":"2021-07-12T11:48:13Z"}
{"level":"info","message":"State transition: update-store [Download_Enter] -\u003e update-after-store [Download_Leave]","timestamp":"2021-07-12T11:48:13Z"}
{"level":"info","message":"State transition: update-after-store [Download_Leave] -\u003e update-install [ArtifactInstall]","timestamp":"2021-07-12T11:48:13Z"}
{"level":"info","message":"State transition: update-install [ArtifactInstall] -\u003e reboot [ArtifactReboot_Enter]","timestamp":"2021-07-12T11:48:14Z"}
{"level":"info","message":"Rebooting device(s)","timestamp":"2021-07-12T11:48:15Z"}
{"level":"info","message":"Running Mender client version: 2.3.0-dirty","timestamp":"2021-07-12T11:49:16Z"}
{"level":"info","message":"State transition: init [none] -\u003e after-reboot [ArtifactReboot_Leave]","timestamp":"2021-07-12T11:49:16Z"}
{"level":"info","message":"State transition: after-reboot [ArtifactReboot_Leave] -\u003e after-reboot [ArtifactReboot_Leave]","timestamp":"2021-07-12T11:49:17Z"}
{"level":"info","message":"State transition: after-reboot [ArtifactReboot_Leave] -\u003e update-commit [ArtifactCommit_Enter]","timestamp":"2021-07-12T11:49:17Z"}
{"level":"info","message":"State transition: update-commit [ArtifactCommit_Enter] -\u003e update-after-first-commit [none]","timestamp":"2021-07-12T11:51:34Z"}
{"level":"info","message":"State transition: update-after-first-commit [none] -\u003e update-after-commit [ArtifactCommit_Leave]","timestamp":"2021-07-12T11:51:35Z"}
{"level":"info","message":"State transition: update-after-commit [ArtifactCommit_Leave] -\u003e cleanup [none]","timestamp":"2021-07-12T11:51:35Z"}
{"level":"info","message":"State transition: cleanup [none] -\u003e update-status-report [none]","timestamp":"2021-07-12T11:51:35Z"}

I have just completed downloading manually the mender artifact and will proceed to manually install it…

5

Alright, interesting indeed.

How much space is left on your data partition?

6

There were about 200MB free.
Manual installation seemed to “fix” the problem, unfortunately without understanding the root cause.
Any extra troubleshooting you may need, I’ll be happy to help for the rest of the day as my holidays start tomorrow :slight_smile:

1 Like
7

I don’t see anything in the logs, which tells me anything other than that it did not have any deployment logs to upload, which is odd.

If you can get me a full log from an old deployment, the log from the passing one, and all the log files present in your data partition that would be a nice start :slight_smile:

8

That puzzled me too… there aren’t any other logs:

root@hostname:~ # date
Tue Dec 28 13:23:41 UTC 2021
root@hostname:~ # ls -l /var/lib/mender/*.log
-rw------- 1 root root  107 Dec 28 06:24 /var/lib/mender/deployments.0001.7a3a5a3d-a94b-4a46-ae9a-8d8d83488dbb.log
-rw------- 1 root root 2244 Jul 12 11:51 /var/lib/mender/deployments.0002.47333005-770d-4522-bcde-3f562418a2ea.log
root@hostname:~ # cat /var/lib/mender/deployments.0001.7a3a5a3d-a94b-4a46-ae9a-8d8d83488dbb.log
{"level":"info","message":"Running Mender client version: 2.3.0-dirty","timestamp":"2021-12-28T06:24:42Z"}
root@hostname:~ # cat /var/lib/mender/deployments.0002.47333005-770d-4522-bcde-3f562418a2ea.log
{"level":"info","message":"Running Mender client version: 2.3.0-dirty","timestamp":"2021-07-12T11:26:38Z"}
{"level":"info","message":"State transition: update-fetch [Download_Enter] -\u003e update-store [Download_Enter]","timestamp":"2021-07-12T11:26:43Z"}
{"level":"info","message":"Installer: authenticated digital signature of artifact","timestamp":"2021-07-12T11:26:44Z"}
{"level":"error","message":"Cannot check update or update inventory while in update-after-store state","timestamp":"2021-07-12T11:48:13Z"}
{"level":"info","message":"State transition: update-store [Download_Enter] -\u003e update-after-store [Download_Leave]","timestamp":"2021-07-12T11:48:13Z"}
{"level":"info","message":"State transition: update-after-store [Download_Leave] -\u003e update-install [ArtifactInstall]","timestamp":"2021-07-12T11:48:13Z"}
{"level":"info","message":"State transition: update-install [ArtifactInstall] -\u003e reboot [ArtifactReboot_Enter]","timestamp":"2021-07-12T11:48:14Z"}
{"level":"info","message":"Rebooting device(s)","timestamp":"2021-07-12T11:48:15Z"}
{"level":"info","message":"Running Mender client version: 2.3.0-dirty","timestamp":"2021-07-12T11:49:16Z"}
{"level":"info","message":"State transition: init [none] -\u003e after-reboot [ArtifactReboot_Leave]","timestamp":"2021-07-12T11:49:16Z"}
{"level":"info","message":"State transition: after-reboot [ArtifactReboot_Leave] -\u003e after-reboot [ArtifactReboot_Leave]","timestamp":"2021-07-12T11:49:17Z"}
{"level":"info","message":"State transition: after-reboot [ArtifactReboot_Leave] -\u003e update-commit [ArtifactCommit_Enter]","timestamp":"2021-07-12T11:49:17Z"}
{"level":"info","message":"State transition: update-commit [ArtifactCommit_Enter] -\u003e update-after-first-commit [none]","timestamp":"2021-07-12T11:51:34Z"}
{"level":"info","message":"State transition: update-after-first-commit [none] -\u003e update-after-commit [ArtifactCommit_Leave]","timestamp":"2021-07-12T11:51:35Z"}
{"level":"info","message":"State transition: update-after-commit [ArtifactCommit_Leave] -\u003e cleanup [none]","timestamp":"2021-07-12T11:51:35Z"}
{"level":"info","message":"State transition: cleanup [none] -\u003e update-status-report [none]","timestamp":"2021-07-12T11:51:35Z"}
root@hostname:~ #

Additionally there was no option for the log on the deployment page (also something I haven’t seen before):

image
image1495Ă—945 66.7 KB

9

The reason there is no log in the UI is because the client does not upload any logs to the UI, and the deployments service returns the error No Messages.

But this is odd. And I’m not sure what to make of it right now, I will take a closer look at the client in the meantime.