Mender-connect sometimes fails

Sometimes, mender-connect fails to reach the server. After a while, it suddenly works, and sometimes a reboot works. Restarting the mender-connect.service also seems to work.

The error message in the log is *connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 212/0); len(token)=873

  • Raspberry CM3+, Raspbian Buster
  • mender-convert installed by running script wget -q -O- https://get.mender.io/ | sudo bash -s
  • mender software (by apt list):
mender-client/unknown,now 2.5.0-1 armhf [installed]
mender-connect/unknown,now 1.0.0-1 armhf [installed]

Contents of the /etc/mender/mender-connect.conf configruation (default conf.)

{
  "ServerCertificate": "/usr/share/doc/mender-client/examples/demo.crt",
  "User": "someuser",
  "ShellCommand": "/bin/bash"
}

sudo journalctl -u mender-connect -f gives the following output:

Mar 19 16:31:42 somename mender-connect[733]: time="2021-03-19T16:31:42+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 19 16:31:43 somename mender-connect[733]: time="2021-03-19T16:31:43+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 211/0); len(token)=873"
Mar 19 16:31:48 somename mender-connect[733]: time="2021-03-19T16:31:48+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 19 16:31:48 somename mender-connect[733]: time="2021-03-19T16:31:48+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...AXBgNVBAMM=\n-----END CERTIFICATE-----\n"
Mar 19 16:31:48 somename mender-connect[733]: time="2021-03-19T16:31:48+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 19 16:31:49 somename mender-connect[733]: time="2021-03-19T16:31:49+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 212/0); len(token)=873"
Mar 19 16:31:54 somename mender-connect[733]: time="2021-03-19T16:31:54+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 19 16:31:54 somename mender-connect[733]: time="2021-03-19T16:31:54+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...AXBgNVBAMM=\n-----END CERTIFICATE-----\n"

Question: Is there anything I can do, or is it just a software bug?

Update (2021.03.20)
I suspected the time to be an issue (checken and egg with ntpd and resolved) when booting with a time/date off by several hours. I tried to recreate the situation by stopping resolved, timesynced and flushing dns), but I cannot re-recreate the situation:

sudo systemctl stop systemd-timesyncd.service
sudo systemctl stop mender-connect.service
sudo systemctl stop systemd-resolved
sudo systemd-resolve --flush-caches
sudo date +%Y%m%d  -s"20210319"
sudo systemd-resolve --flush-caches
ping vg.no
sudo reboot

The situation usually occurs after a fresh image installation (or artifact update).

@tranchitella @lluiscampos any ideas?

@johan I confirm the websocket connection cannot be established if the date/time on the device is out of sync.

@tranchitella Yes, I know that the time must be in sync, but I would expect that mender-connect re-connects as soon as the time is back in sync. My last update in the post was just a test to see if I was able to re-create the situation by forcing the time to wrong at boot, but as soon as the time is syncronized, the mender-connect works as expected.

Summary: Do not put too much into my last comment as the problem occured even when the time was correct the first time. I have not been able to re-create the issue without flashing the whole device

@johan can you provide the logs of the mender-client service, as well?

@tranchitella Yes, and thanks for helping!

I re-created the issue by flashing a new device. The device boots and “phones home” to mender.io. The device shows up at hosted.mender.io, but mender-connet fails


mender-client log (repeating):
sudo journalctl -u mender-client -f

-- Logs begin at Fri 2021-03-19 20:27:04 CET, end at Mon 2021-03-22 15:52:59 CET. --
Mar 19 20:27:18 somename systemd[1]: Started Mender OTA update service.
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="Mender running on partition: /dev/mmcblk0p2"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: init [none] -> init [none]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: init [none] -> idle [Idle]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: update-check [Sync] -> error [Error]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="Handling error state, current error: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: error [Error] -> idle [Idle]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Mar 19 20:27:23 somename mender[732]: time="2021-03-19T20:27:23+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="State transition: update-check [Sync] -> error [Error]"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="Handling error state, current error: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="State transition: error [Error] -> idle [Idle]"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Mar 19 20:27:28 somename mender[732]: time="2021-03-19T20:27:28+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="State transition: update-check [Sync] -> error [Error]"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="Handling error state, current error: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="State transition: error [Error] -> idle [Idle]"
Mar 19 20:27:33 somename mender[732]: time="2021-03-19T20:27:33+01:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="Failed to submit inventory data: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=warning msg="Failed to refresh inventory: failed to submit inventory data: inventory submit failed: Put \"https://hosted.mender.io/api/devices/v1/inventory/device/attributes\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="State transition: update-check [Sync] -> error [Error]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="Error receiving scheduled update data: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="Handling error state, current error: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="State transition: error [Error] -> idle [Idle]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Mar 19 20:27:38 somename mender[732]: time="2021-03-19T20:27:38+01:00" level=error msg="Update check failed: transient error: POST update check request failed: Post \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments/next\": dial tcp: lookup hosted.mender.io: no such host"
Mar 22 15:22:25 somename mender[732]: time="2021-03-22T15:22:25+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 22 15:22:25 somename mender[732]: time="2021-03-22T15:22:25+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:22:25 somename mender[732]: time="2021-03-22T15:22:25+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:22:27 somename mender[732]: time="2021-03-22T15:22:27+01:00" level=info msg="Device unauthorized; attempting reauthorization"
Mar 22 15:22:28 somename mender[732]: time="2021-03-22T15:22:28+01:00" level=info msg="successfully received new authorization data"
Mar 22 15:22:29 somename mender[732]: time="2021-03-22T15:22:29+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 22 15:22:29 somename mender[732]: time="2021-03-22T15:22:29+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 22 15:22:29 somename mender[732]: time="2021-03-22T15:22:29+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Mar 22 15:22:30 somename mender[732]: time="2021-03-22T15:22:30+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 22 15:22:30 somename mender[732]: time="2021-03-22T15:22:30+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:22:30 somename mender[732]: time="2021-03-22T15:22:30+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:22:30 somename mender[732]: time="2021-03-22T15:22:30+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 22 15:22:34 somename mender[732]: time="2021-03-22T15:22:34+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 22 15:22:34 somename mender[732]: time="2021-03-22T15:22:34+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Mar 22 15:22:35 somename mender[732]: time="2021-03-22T15:22:35+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 22 15:22:35 somename mender[732]: time="2021-03-22T15:22:35+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:22:35 somename mender[732]: time="2021-03-22T15:22:35+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:22:36 somename mender[732]: time="2021-03-22T15:22:36+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 22 15:22:39 somename mender[732]: time="2021-03-22T15:22:39+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 22 15:22:39 somename mender[732]: time="2021-03-22T15:22:39+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Mar 22 15:22:40 somename mender[732]: time="2021-03-22T15:22:40+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
...
Mar 22 15:23:20 somename mender[732]: time="2021-03-22T15:23:20+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 22 15:23:24 somename mender[732]: time="2021-03-22T15:23:24+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 22 15:23:24 somename mender[732]: time="2021-03-22T15:23:24+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Mar 22 15:23:25 somename mender[732]: time="2021-03-22T15:23:25+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 22 15:23:25 somename mender[732]: time="2021-03-22T15:23:25+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:23:25 somename mender[732]: time="2021-03-22T15:23:25+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:23:25 somename mender[732]: time="2021-03-22T15:23:25+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Mar 22 15:23:29 somename mender[732]: time="2021-03-22T15:23:29+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Mar 22 15:23:29 somename mender[732]: time="2021-03-22T15:23:29+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Mar 22 15:23:30 somename mender[732]: time="2021-03-22T15:23:30+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Mar 22 15:23:30 somename mender[732]: time="2021-03-22T15:23:30+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"
Mar 22 15:23:30 somename mender[732]: time="2021-03-22T15:23:30+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 3"

mender-connect log (repeating): `sudo journalctl -u mender-connect -f`
-- Logs begin at Fri 2021-03-19 20:27:04 CET, end at Mon 2021-03-22 15:54:07 CET. --
Mar 19 20:27:18 somename systemd[1]: Started Mender Connect service.
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=info msg="Loaded configuration file: /etc/mender/mender-connect.conf"
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=warning msg="No server URL(s) specified in mender configuration."
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=warning msg="Server entry 1 has no associated server URL."
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=warning msg="call to GetJWTToken on the Mender D-Bus API failed: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name io.mender.AuthenticationManager was not provided by any .service files"
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=info msg="waiting for JWT token (waitForJWTToken)"
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 19 20:27:23 somename mender-connect[737]: time="2021-03-19T20:27:23+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: dial tcp: lookup hosted.mender.io: no such host; reconnecting in 5s (try 1/0); len(token)=873"
Mar 19 20:27:28 somename mender-connect[737]: time="2021-03-19T20:27:28+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 19 20:27:28 somename mender-connect[737]: time="2021-03-19T20:27:28+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...
Mar 19 20:27:28 somename mender-connect[737]: time="2021-03-19T20:27:28+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 19 20:27:29 somename mender-connect[737]: time="2021-03-19T20:27:29+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: dial tcp: lookup hosted.mender.io: no such host; reconnecting in 5s (try 2/0); len(token)=873"
Mar 19 20:27:34 somename mender-connect[737]: time="2021-03-19T20:27:34+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 19 20:27:34 somename mender-connect[737]: time="2021-03-19T20:27:34+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...
Mar 19 20:27:34 somename mender-connect[737]: time="2021-03-19T20:27:34+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 19 20:27:34 somename mender-connect[737]: time="2021-03-19T20:27:34+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: dial tcp: lookup hosted.mender.io: no such host; reconnecting in 5s (try 3/0); len(token)=873"
Mar 19 20:27:39 somename mender-connect[737]: time="2021-03-19T20:27:39+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 19 20:27:39 somename mender-connect[737]: time="2021-03-19T20:27:39+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...
Mar 19 20:27:39 somename mender-connect[737]: time="2021-03-19T20:27:39+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 19 20:27:39 somename mender-connect[737]: time="2021-03-19T20:27:39+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: dial tcp: lookup hosted.mender.io: no such host; reconnecting in 5s (try 4/0); len(token)=873"
Mar 22 15:22:26 somename mender-connect[737]: time="2021-03-22T15:22:26+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 22 15:22:26 somename mender-connect[737]: time="2021-03-22T15:22:26+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...
Mar 22 15:22:26 somename mender-connect[737]: time="2021-03-22T15:22:26+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 22 15:22:27 somename mender-connect[737]: time="2021-03-22T15:22:27+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 5/0); len(token)=873"
Mar 22 15:22:32 somename mender-connect[737]: time="2021-03-22T15:22:32+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 22 15:22:32 somename mender-connect[737]: time="2021-03-22T15:22:32+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBf...
Mar 22 15:22:32 somename mender-connect[737]: time="2021-03-22T15:22:32+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 22 15:22:32 somename mender-connect[737]: time="2021-03-22T15:22:32+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 6/0); len(token)=873"
...
Mar 22 15:25:57 somename mender-connect[737]: time="2021-03-22T15:25:57+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 22 15:25:58 somename mender-connect[737]: time="2021-03-22T15:25:58+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 41/0); len(token)=873"
Mar 22 15:26:03 somename mender-connect[737]: time="2021-03-22T15:26:03+01:00" level=info msg="loadServerTrust loading certificate from /usr/share/doc/mender-client/examples/demo.crt"
Mar 22 15:26:03 somename mender-connect[737]: time="2021-03-22T15:26:03+01:00" level=info msg="API Gateway certificate (in PEM format): \n-----BEGIN CERTIFICATE-----\nMIIBfT<xxx>0fy7niBbIQ=\n-----END CERTIFICATE-----\n"
Mar 22 15:26:03 somename mender-connect[737]: time="2021-03-22T15:26:03+01:00" level=info msg="Issuer: [], Valid from: 2016-12-14 19:52:46 +0000 UTC, Valid to: 2026-12-12 19:52:46 +0000 UTC"
Mar 22 15:26:03 somename mender-connect[737]: time="2021-03-22T15:26:03+01:00" level=error msg="connection manager failed to connect to https://hosted.mender.io/api/devices/v1/deviceconnect/connect: websocket: bad handshake; reconnecting in 5s (try 42/0); len(token)=873"

Updated with logs from start

@johan would you be able to share the full logs, not only the last rows?

I added more from the logs (from beginning) in the original post

Looked up the warning on geo and tried the commands inside the script. Could it be that the geo-location is failing:
wget --timeout=10 https://ipvigilante.com/csv/84.48.241.146

--2021-03-22 15:40:11--  https://ipvigilante.com/csv/84.48.241.146
Resolving ipvigilante.com (ipvigilante.com)... 1.1.1.1
Connecting to ipvigilante.com (ipvigilante.com)|1.1.1.1|:443... connected.
The certificate's owner does not match hostname ‘ipvigilante.com’

You can ignore the geo-location script (which you can either disable, or replace with the current version from master). This is unrelated to your original issue.

I still have no idea what causes this issue. It is not a big problem as it seems to be related to the initial connection to Mender. A reboot seems to fix the issue.

We hope that the problem with initial connections will be fixed by this bug fix, which is scheduled for Mender Client 2.7, and will probably be cherry-picked to older releases as well.

1 Like