Hey guys,
First, some background:
- EU hosted Mender is used
- Client devices run Raspberry Pi OS (32bit) Bullseye Lite 2023-05-03
- Client devices are Raspberry Pi 3B+
I have recently started playing around with Mender client 4.0.4 (current fleet is on 3.5.2) and realised that the client does not communicate/fails to communicate with the hosted server on boot - logs available below.
If I issue mender-update send-inventory, authorisation request appears on the hosted dashboard - I approve that one. Then I can send another command of mender-update send-inventory to actually get an inventory data from a device. So, i had to send mender-update send-inventory twice: once to generate an auth request, second time to actually send the inventory data through.
With 3.5.2, it was automatically creating an auth request on boot. Then I was going onto the dashboard to accept auth request. After couple of minutes of accepting request, it was automatically sending the inventory data. So, I only had to accept the auth request - rest was done by the system auto-magically. However, this is no longer the case with Mender client v4.0.4
These are the logs I am getting from authd and updated services. Not sure if the errors have to do something with the issue at hand.
mender-updated logs
-- Journal begins at Wed 2023-05-03 01:25:51 BST, ends at Thu 2024-09-05 13:46:26 BST. --
Sep 05 13:00:39 <REDACTED> systemd[1]: Started Mender OTA update service.
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=1 severity=info time="2024-Sep-05 13:00:42.125611" name="Global" msg="Running Mender client 4.0.4"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=2 severity=info time="2024-Sep-05 13:00:42.126215" name="Global" msg="The update client daemon is now ready to handle incoming deployments"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=3 severity=error time="2024-Sep-05 13:00:42.962299" name="Global" msg="Failed to request new token fetching: DBus reply error: Got error reply: The name io.mender.AuthenticationManager was not provided by any .service files"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=4 severity=error time="2024-Sep-05 13:00:42.962520" name="Global" msg="Failed to obtain authentication credentials"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=5 severity=error time="2024-Sep-05 13:00:42.962628" name="Global" msg="Request to push inventory data failed: Got error reply: The name io.mender.AuthenticationManager was not provided by any .service files"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=6 severity=error time="2024-Sep-05 13:00:42.962724" name="Global" msg="Failed to submit inventory: DBus reply error: Got error reply: The name io.mender.AuthenticationManager was not provided by any .service files"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=7 severity=error time="2024-Sep-05 13:00:42.974307" name="Global" msg="Failed to request new token fetching: DBus reply error: Got error reply: The name io.mender.AuthenticationManager was not provided by any .service files"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=8 severity=error time="2024-Sep-05 13:00:42.974513" name="Global" msg="Failed to obtain authentication credentials"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=9 severity=error time="2024-Sep-05 13:00:42.974669" name="Global" msg="Request to check new deployments failed: Got error reply: The name io.mender.AuthenticationManager was not provided by any .service files"
Sep 05 13:00:42 <REDACTED> mender-update[572]: record_id=10 severity=error time="2024-Sep-05 13:00:42.974753" name="Global" msg="Error while polling for deployment: DBus reply error: Got error reply: The name io.mender.AuthenticationManager was not provided by any .service files"
Sep 05 13:36:27 <REDACTED> mender-update[572]: record_id=11 severity=warning time="2024-Sep-05 13:36:27.764693" name="Global" msg="Timed-out waiting for a new token"
Sep 05 13:45:56 <REDACTED> mender-update[572]: record_id=12 severity=info time="2024-Sep-05 13:45:56.022438" name="Global" msg="SIGUSR2 received, triggering inventory update"
Sep 05 13:45:56 <REDACTED> mender-update[572]: record_id=13 severity=error time="2024-Sep-05 13:45:56.768241" name="Global" msg="Failed to set new authentication data on HTTP request"
Sep 05 13:45:56 <REDACTED> mender-update[572]: record_id=14 severity=error time="2024-Sep-05 13:45:56.768492" name="Global" msg="Request to push inventory data failed: Cannot submit API request"
Sep 05 13:45:56 <REDACTED> mender-update[572]: record_id=15 severity=error time="2024-Sep-05 13:45:56.768598" name="Global" msg="Failed to submit inventory: Unauthorized error: Cannot submit API request"
Sep 05 13:47:26 <REDACTED> mender-update[572]: record_id=16 severity=info time="2024-Sep-05 13:47:26.177473" name="Global" msg="SIGUSR2 received, triggering inventory update"
Sep 05 13:52:42 <REDACTED> systemd[1]: Stopping Mender OTA update service...
Sep 05 13:52:42 <REDACTED> mender-update[572]: record_id=17 severity=info time="2024-Sep-05 13:52:42.684723" name="Global" msg="Termination signal received, shutting down gracefully"
Sep 05 13:52:42 <REDACTED> systemd[1]: mender-updated.service: Succeeded.
Sep 05 13:52:42 <REDACTED> systemd[1]: Stopped Mender OTA update service.
mender-authd logs
-- Journal begins at Wed 2023-05-03 01:25:51 BST, ends at Thu 2024-09-05 13:46:26 BST. --
Sep 05 13:00:39 <REDACTED> systemd[1]: Started Mender authentication service.
Sep 05 13:00:42 <REDACTED> mender-auth[570]: record_id=1 severity=warning time="2024-Sep-05 13:00:42.425984" name="Global" msg="Failed to load OpenSSL configuration file: error:25066067:DSO support routines:dlfcn_load:could not load the shared library
Sep 05 13:00:42 <REDACTED> mender-auth[570]: error:25070067:DSO support routines:DSO_load:could not load the shared library
Sep 05 13:00:42 <REDACTED> mender-auth[570]: error:0E07506E:configuration file routines:module_load_dso:error loading dso
Sep 05 13:00:42 <REDACTED> mender-auth[570]: error:0E076071:configuration file routines:module_run:unknown module name"
Sep 05 13:00:42 <REDACTED> mender-auth[570]: record_id=2 severity=error time="2024-Sep-05 13:00:42.434929" name="Global" msg="Got error loading the private key from the keystore: No key in memory: Error loading private key from /var/lib/mender/mender-agent.pem: Failed to load the private key file /var/lib/mender/mender-agent.pem: error:02001002:system library:fopen:No such file or directory
Sep 05 13:00:42 <REDACTED> mender-auth[570]: error:2006D080:BIO routines:BIO_new_file:no such file
Sep 05 13:00:42 <REDACTED> mender-auth[570]: System error, code=2, No such file or directory"
Sep 05 13:00:42 <REDACTED> mender-auth[570]: record_id=3 severity=info time="2024-Sep-05 13:00:42.435355" name="Global" msg="Generating new RSA key"
Sep 05 13:00:50 <REDACTED> mender-auth[570]: record_id=4 severity=info time="2024-Sep-05 13:00:50.474696" name="Global" msg="The authentication daemon is now ready to accept incoming authentication request"
Sep 05 13:45:56 <REDACTED> mender-auth[929]: using interface /sys/class/net/eth0
Sep 05 13:45:56 <REDACTED> mender-auth[570]: record_id=5 severity=info time="2024-Sep-05 13:45:56.522664" name="Global" msg="Signing with: /var/lib/mender/mender-agent.pem"
Sep 05 13:45:56 <REDACTED> mender-auth[570]: record_id=6 severity=info time="2024-Sep-05 13:45:56.766477" name="Global" msg="Authentication error trying server 'https://eu.hosted.mender.io/': Unauthorized error: Authentication error(Unauthorized): Failed to authorize with the server.({"error":"dev auth: unauthorized","request_id":"849720c8-2bac-4800-bb6b-f82efe419d0c"})"
Sep 05 13:45:56 <REDACTED> mender-auth[570]: record_id=7 severity=error time="2024-Sep-05 13:45:56.766698" name="Global" msg="Failed to fetch new token: Authentication error: No more servers to try for authentication"
Sep 05 13:47:26 <REDACTED> mender-auth[1043]: using interface /sys/class/net/eth0
Sep 05 13:47:26 <REDACTED> mender-auth[570]: record_id=8 severity=info time="2024-Sep-05 13:47:26.720646" name="Global" msg="Signing with: /var/lib/mender/mender-agent.pem"
Sep 05 13:47:26 <REDACTED> mender-auth[570]: record_id=9 severity=info time="2024-Sep-05 13:47:26.891975" name="Global" msg="Successfully received new authorization data"
Sep 05 13:52:43 <REDACTED> mender-auth[570]: record_id=10 severity=error time="2024-Sep-05 13:52:43.665523" name="Global" msg="Error during network socket forwarding: End of file: Could not read from socket"
Sep 05 13:52:43 <REDACTED> mender-auth[570]: record_id=11 severity=warning time="2024-Sep-05 13:52:43.666235" name="http_client" url="https://eu.hosted.mender.io/api/devices/v1/deviceconnect/connect" msg="Client destroyed while request is still active!"
Sep 05 13:52:43 <REDACTED> mender-auth[570]: record_id=12 severity=error time="2024-Sep-05 13:52:43.666702" name="Global" msg="Error during network socket forwarding: Operation canceled: Could not read from socket"
Sep 05 13:52:43 <REDACTED> mender-auth[570]: record_id=13 severity=info time="2024-Sep-05 13:52:43.674937" name="Global" msg="Termination signal received, shutting down gracefully"
Sep 05 13:52:43 <REDACTED> systemd[1]: Stopping Mender authentication service...
Sep 05 13:52:43 <REDACTED> systemd[1]: mender-authd.service: Succeeded.
Sep 05 13:52:43 <REDACTED> systemd[1]: Stopped Mender authentication service.
Sep 05 13:52:43 <REDACTED> systemd[1]: mender-authd.service: Consumed 8.194s CPU time.
Do errors logged have anything to do with the request generation? Am I missing something during transition to 4.0.4?
Looking forward to the suggestions.
Kind regards,
Dmitrij