Mender-connect JWT Token timeout error in Yocto Kirkstone build

Guilhermerossi · October 20, 2022, 5:07pm

Hello everyone,

I successfully implemented Mender on IMX8QXP-MEK with Yocto Zeus using Meta-mender layers and a manual board adaptation based on meta-mender-imx for imx8m nano.
Everything went fine and i could even deploy a image update through Mender.

The problem started when i switched to Kirkstone, using the same board.
I made similar adaptations to the board, changed the meta-mender layers to the kirkstone version. The board boots up fine, loads the kernel with no errors, the partitions are all ok.
The problem i think is with the API.
This board with the Kirkstone branch never shows up on the hosted mender server https://hosted.mender.io/. I have the Organization token correctly configured on my local.conf, and i even tried using the new Personal Token generator but both of them failed.

The mender-connect API always timeouts with the error

Oct 20 14:04:13 imx8qxpc0mek mender-connect[366]: time="2022-10-20T14:04:13Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"

And at board init, mender-connect also shows:

Oct 20 14:00:01 imx8qxpc0mek mender-connect[366]: time="2022-10-20T14:00:01Z" 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"

There are no major manual changes under the mender layers, the only thing i changed was some minor adaptations on the mender-imx layer, to make it Kirkstone compatible

Mender-client seems fine, no unusual errors. Ethernet is also ok. Building on top of core-image-minimal. I already dismissed all the old devices i had connected to the mender hosted server (when i used Zeus branches) and i even made a new Mender user, generating a new token, but with still the same errors.

Mender versions:

root@imx8qxpc0mek:~# mender --version
3.4.0	runtime: go1.17.8
root@imx8qxpc0mek:~# mender-connect --version
mender-connect version 2.1.0	runtime: go1.17.8

Mender server configs on local.conf (worked on Zeus)
MENDER_SERVER_URL = “https://hosted.mender.io”
MENDER_TENANT_TOKEN = “token hash copied from hosted.mender.io”

Some other debug logs i have:

mender-connect --dd daemon

root@imx8qxpc0mek:~# mender-connect --dd daemon
INFO[2022-10-20T14:35:36Z] Loaded configuration file: /etc/mender/mender-connect.conf 
WARN[2022-10-20T14:35:36Z] ShellArguments is empty, defaulting to [--login] 
TRAC[2022-10-20T14:35:36Z] daemon Run starting                          
TRAC[2022-10-20T14:35:36Z] mender-connect connecting to dbus            
TRAC[2022-10-20T14:35:36Z] mender-connect entering main loop.           
TRAC[2022-10-20T14:35:36Z] messageLoop: starting                        
TRAC[2022-10-20T14:35:36Z] messageLoop: posting event: reconnect-req; waiting for response 
TRAC[2022-10-20T14:35:36Z] needsReconnect: got event: reconnect-req     
TRAC[2022-10-20T14:35:36Z] dbusEventLoop: daemon needs to reconnect     
TRAC[2022-10-20T14:35:46Z] dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange 
TRAC[2022-10-20T14:35:57Z] dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange 
TRAC[2022-10-20T14:36:08Z] dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange

journalctl -u mender-connect

root@imx8qxpc0mek:~# journalctl -u mender-connect
Oct 20 15:00:59 imx8qxpc0mek systemd[1]: Started Mender Connect service.
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=info msg="Loaded configuration file: /etc/mender/mender-connect.conf"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=warning msg="ShellArguments is empty, defaulting to [--login]"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="daemon Run starting"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="mender-connect connecting to dbus"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" 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"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="mender-connect entering main loop."
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="messageLoop: starting"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="messageLoop: posting event: reconnect-req; waiting for response"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="needsReconnect: got event: reconnect-req"
Oct 20 15:00:59 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:00:59Z" level=trace msg="dbusEventLoop: daemon needs to reconnect"
Oct 20 15:01:09 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:01:09Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"
Oct 20 15:01:20 imx8qxpc0mek mender-connect[380]: time="2022-10-20T15:01:20Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"
Oct 20 16:46:21 imx8qxpc0mek mender-connect[380]: time="2022-10-20T16:46:21Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"
Oct 20 16:46:32 imx8qxpc0mek mender-connect[380]: time="2022-10-20T16:46:32Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"
Oct 20 16:46:43 imx8qxpc0mek mender-connect[380]: time="2022-10-20T16:46:43Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"
Oct 20 16:46:54 imx8qxpc0mek mender-connect[380]: time="2022-10-20T16:46:54Z" level=trace msg="dbusEventLoop: WaitForJwtTokenStateChange [], err timeout waiting for signal JwtTokenStateChange"

DBus List

root@imx8qxpc0mek:~# dbus-send --system --dest=org.freedesktop.DBus --type=method_call --print-reply /org/freedesktop/DBus org.freedesktop.DBus.ListNames
method return time=1666275414.623496 sender=org.freedesktop.DBus -> destination=:1.12 serial=3 reply_serial=2
   array [
      string "org.freedesktop.DBus"
      string "org.freedesktop.login1"
      string "org.freedesktop.timesync1"
      string ":1.9"
      string "org.freedesktop.systemd1"
      string ":1.10"
      string ":1.11"
      string ":1.12"
      string "io.mender.UpdateManager"
      string ":1.0"
      string "io.mender.AuthenticationManager"
      string ":1.1"
      string ":1.2"
      string "org.freedesktop.network1"
      string "org.freedesktop.resolve1"
      string ":1.4"
      string ":1.5"
   ]

Systemctl Mender Services List

root@imx8qxpc0mek:~# systemctl list-units --type=service | grep -i mender
  boot-script.service                                  loaded active running Boot script to demo Mender OTA updates
  mender-client.service                                loaded active running Mender OTA update service
  mender-connect.service                               loaded active running Mender Connect service
  mender-grow-data.service                             loaded active exited  Mender service to grow data partition size
  mender-systemd-growfs-data.service                   loaded active exited  Grow File System on /data

Systemctl Mender Files List

root@imx8qxpc0mek:~# systemctl list-unit-files | grep -i mender
mender-client-data-dir.service               disabled        disabled
mender-client.service                        enabled         enabled
mender-configure-apply-device-config.service enabled         enabled
mender-connect.service                       enabled         enabled
mender-grow-data.service                     disabled        disabled
mender-systemd-growfs-data.service           static          -

io.mender.AuthenticationManager.conf location

root@imx8qxpc0mek:~# find / -name io.mender.AuthenticationManager.conf
/usr/share/dbus-1/system.d/io.mender.AuthenticationManager.conf

Did anyone encounter this problem on Kirkstone? Any tips on how to debug this error more minutely? I couldn’t find much material on that.
Thanks for all the help!

kacf · October 21, 2022, 6:46am

I can’t see anything out of the ordinary there. Even though you say the client is fine, could we see the log from it?

Guilhermerossi · October 21, 2022, 1:00pm

Sure, no problem
The only error is that the artifact wasn’t found, because i never did an update on this board, so this is expected.

The messages after initialization keep looping:

journalctl -u mender-client

root@imx8qxpc0mek:~# journalctl -u mender-client
Oct 20 21:03:24 imx8qxpc0mek systemd[1]: Started Mender OTA update service.
Oct 20 21:03:24 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:24Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Oct 20 21:03:24 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:24Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Oct 20 21:03:29 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:29Z" level=info msg="Mender running on partition: /dev/mmcblk0p2"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: init [none] -> init [none]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: init [none] -> idle [Idle]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=warning msg="Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before."
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=warning msg="Failed to refresh inventory: could not read the artifact name. This is a necessary condition in order for a Mender update to finish safely. Please give the current Artifact a name (This can be done by adding a name to the file /etc/mender/artifact_info) err: open /etc/mender/artifact_info: no such file or directory: cannot determine current artifact name"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: inventory-update [Sync] -> error [Error]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="Handling error state, current error: transient error: could not read the artifact name. This is a necessary condition in order for a Mender update to finish safely. Please give the current Artifact a name (This can be done by adding a name to the file /etc/mender/artifact_info) err: open /etc/mender/artifact_info: no such file or directory: cannot determine current artifact name"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: error [Error] -> idle [Idle]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=warning msg="Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before."
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=error msg="could not get the current Artifact name"
Oct 20 21:03:34 imx8qxpc0mek mender[383]: time="2022-10-20T21:03:34Z" level=error msg="Update check failed: transient error: could not read the Artifact name. This is a necessary condition in order for a Mender update to finish safely. Please give the current Artifact a name (This can be done by adding a name to the file /etc/mender/artifact_info) err: open /etc/mender/artifact_info: no such file or directory"

kacf · October 21, 2022, 1:25pm

Oh, this is a completely different issue. It is because of what is described in this thread. Use the tags as suggested there. We are working on fixing it, but it’s not quite there yet.

Guilhermerossi · October 21, 2022, 2:21pm

That was it, I changed to the kirkstone tag v2022-09 and it worked
Thanks a lot for the quick response and attention

Topic		Replies	Views
Mender-connect issue Yocto Project	2	115	February 6, 2024
Mender-connect not working on kirkstone General Discussions	2	184	August 9, 2023
Mender-connect dbus errors that "AuthenticationManager was not provided" General Discussions yocto , orangepi , dunfell	7	1768	March 26, 2021
Mender Authentication Error General Discussions yocto , hosted-mender , zeus , imx8mq	8	1885	January 12, 2021
Remote terminal not working General Discussions mender-client , mender-connect , dbus	4	448	January 19, 2023

Mender-connect JWT Token timeout error in Yocto Kirkstone build

Related Topics