Azure IoT Hub Integration - Configuration Update Fails

General Discussions
1

Hello,

A while ago we enabled the Azure IoT Hub integration to our Mender account. The integration partially works: when we accept a device into Mender, the corresponding device is created in IoT Hub. After this, we see a configuration OTA update containing the connection string, but this is always stuck in “queued to start”.

On looking at the device logs, we get this error:

level=error msg="Update fetch failed: (request_id: ): error receiving scheduled update information server error message: {\"error\": {\"status_code\": 404,\"message\": \"Not Found\"}}. I couldn’t see anything more helpful when increasing the log verbosity.

Please can someone suggest how to resolve this issue? I can confirm that other types of OTA update (file, deb and image) do work successfully with this device.

Best,

Tom

2

Hello Tom,

This error message indicates that the URL returned by the update instructions points to a non-existing resource. Are you hosting your own Mender server on-premises, or are you using Hosted Mender?
If you are hosting your own Mender server, could you describe the type of deployment you are using (i.e. k8s Helm or docker-compose)? It might be a symptom of some missing configuration in one of the micro-services.
I just tested the Azure integration on Hosted Mender, and the provisioning works as expected.

BR,
Alf-Rune

3

We’re using Hosted Mender, seems to be running the latest version (3.3.0).

Thanks,

Tom

4

Could you check the device logs for an entry showing the download URL for the deployment? There should be an entry on the following format (the URL parameters in the example below are replaced with random values for security purposes):

Jul 05 07:16:30 raspberrypi4 mender[267]: time="2022-07-05T09:16:30Z" level=info msg="Validating the Update Info: https://hosted.mender.io/api/devices/v1/deployments/download/configuration/ab8b18c4-c635-4753-9fb9-ac0228fb8d06/raspberrypi4/96c6cc30-3b70-43ad-89d2-d0bc56baea0f?tenant_id=123456789012345678901234&x-men-expire=2022-07-05T07%3A31%3A30Z&x-men-signature=jOcq2XP6ryCnJwouaV7Cid7QjZCvgVkmGi8WJ0wpyw4 [name: configuration-ab8b18c4-c635-4753-9fb9-ac0228fb8d06; devices: [raspberrypi4]]"

Could you verify that the URL path and hostname matches the URL in the sample log above?

5

I don’t have that exact log line, but I do have a message Correct request for getting image from: <url>, where the URL does match what you posted above. That log line is immediately after a message State transition: update-check [Sync] -> update-fetch [Download Enter].

This is with Client version 2.6.1 (built with Yocto).

6

Hmm… Could you share the entire client logs from when it starts until it finishes (fails) the update?
(Please make sure you mask the download URLs query parameters or wait 15 minutes until it expires before posting it here).

I’m not 100% sure which API endpoint is returning the 404 above.

7

It’s also not clear to me since there seems to be some concurrency:

Started Mender OTA update service.
time="2022-07-05T10:34:34Z" level=debug msg="Reading Mender configuration from file /var/lib/mender/mender.conf" func=github.com/mendersoftware/mender/conf.readConfigFile file="/path/to/mender/conf/config.go:209"
time="2022-07-05T10:34:34Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf" func=github.com/mendersoftware/mender/conf.loadConfigFile file="/path/to/mender/conf/config.go:202"
time="2022-07-05T10:34:34Z" level=debug msg="Reading Mender configuration from file /etc/mender/mender.conf" func=github.com/mendersoftware/mender/conf.readConfigFile file="/path/to/mender/conf/config.go:209"
time="2022-07-05T10:34:34Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf" func=github.com/mendersoftware/mender/conf.loadConfigFile file="/path/to/mender/conf/config.go:202"
time="2022-07-05T10:34:34Z" level=debug msg="Loaded 2 configuration file(s)" func=github.com/mendersoftware/mender/conf.LoadConfig file="/path/to/mender/conf/config.go:135"
time="2022-07-05T10:34:34Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf" func=github.com/mendersoftware/mender/conf.loadConfigFile file="/path/to/mender/conf/config.go:202"
time="2022-07-05T10:34:34Z" level=debug msg="Loaded configuration = &conf.MenderConfig{MenderConfigFromFile:conf.MenderConfigFromFile{ArtifactVerifyKey:\"/etc/mender/artifact-verify-key.pem\", HttpsClient:client.HttpsClient{Certificate:\"\", Key:\"\", SSLEngine:\"\"}, Security:client.Security{AuthPrivateKey:\"\", SSLEngine:\"\"}, RootfsPartA:\"/dev/mmcblk0p1\", RootfsPartB:\"/dev/mmcblk0p11\", DeviceTypeFile:\"\", DBus:conf.DBusConfig{Enabled:true}, UpdatePollIntervalSeconds:1800, InventoryPollIntervalSeconds:300, SkipVerify:false, RetryPollIntervalSeconds:300, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ModuleTimeoutSeconds:0, ServerCertificate:\"\", ServerURL:\"https://hosted.mender.io\", UpdateLogPath:\"\", TenantToken:\"<tenant-token>\", Servers:[]client.MenderServer(nil)}, ModulesPath:\"/usr/share/mender/modules/v3\", ModulesWorkPath:\"/var/lib/mender/modules/v3\", ArtifactInfoFile:\"/etc/mender/artifact_info\", ArtifactScriptsPath:\"/var/lib/mender/scripts\", RootfsScriptsPath:\"/etc/mender/scripts\"}" func=github.com/mendersoftware/mender/conf.LoadConfig file="/path/to/mender/conf/config.go:142"
time="2022-07-05T10:34:34Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf" func=github.com/mendersoftware/mender/conf.loadConfigFile file="/path/to/mender/conf/config.go:202"
time="2022-07-05T10:34:34Z" level=debug msg="Verified configuration = &conf.MenderConfig{MenderConfigFromFile:conf.MenderConfigFromFile{ArtifactVerifyKey:\"/etc/mender/artifact-verify-key.pem\", HttpsClient:client.HttpsClient{Certificate:\"\", Key:\"\", SSLEngine:\"\"}, Security:client.Security{AuthPrivateKey:\"\", SSLEngine:\"\"}, RootfsPartA:\"/dev/mmcblk0p1\", RootfsPartB:\"/dev/mmcblk0p11\", DeviceTypeFile:\"/var/lib/mender/device_type\", DBus:conf.DBusConfig{Enabled:true}, UpdatePollIntervalSeconds:1800, InventoryPollIntervalSeconds:300, SkipVerify:false, RetryPollIntervalSeconds:300, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ModuleTimeoutSeconds:0, ServerCertificate:\"\", ServerURL:\"https://hosted.mender.io\", UpdateLogPath:\"\", TenantToken:\"<tenant-token>\", Servers:[]client.MenderServer{client.MenderServer{ServerURL:\"https://hosted.mender.io\"}}}, ModulesPath:\"/usr/share/mender/modules/v3\", ModulesWorkPath:\"/var/lib/mender/modules/v3\", ArtifactInfoFile:\"/etc/mender/artifact_info\", ArtifactScriptsPath:\"/var/lib/mender/scripts\", RootfsScriptsPath:\"/etc/mender/scripts\"}" func="github.com/mendersoftware/mender/conf.(*MenderConfig).Validate" file="/path/to/mender/conf/config.go:183"
time="2022-07-05T10:34:34Z" level=debug msg="Have U-Boot variable: mender_boot_part=1" func=github.com/mendersoftware/mender/installer.getEnvironmentVariable file="/path/to/mender/installer/bootenv.go:208"
time="2022-07-05T10:34:34Z" level=debug msg="List of U-Boot variables:map[mender_boot_part:1]" func=github.com/mendersoftware/mender/installer.getEnvironmentVariable file="/path/to/mender/installer/bootenv.go:231"
time="2022-07-05T10:34:34Z" level=debug msg="Setting active partition from mount candidate: /dev/mmcblk0p1" func="github.com/mendersoftware/mender/installer.(*partitions).getAndCacheActivePartition" file="/path/to/mender/installer/partitions.go:175"
time="2022-07-05T10:34:34Z" level=info msg="Mender running on partition: /dev/mmcblk0p1" func="github.com/mendersoftware/mender/cli.(*runOptionsType).commonCLIHandler" file="/path/to/mender/cli/cli.go:464"
time="2022-07-05T10:34:34Z" level=debug msg="Could not open local Mender trust store directory: open /usr/local/share/ca-certificates/mender: no such file or directory" func=github.com/mendersoftware/mender/cli.checkDemoCert file="/path/to/mender/cli/commands.go:269"
time="2022-07-05T10:34:34Z" level=debug msg="ModuleTimeoutSeconds not set. Defaulting to 14400 seconds" func=github.com/mendersoftware/mender/installer.NewModuleInstallerFactory file="/path/to/mender/installer/modules.go:881"
time="2022-07-05T10:34:34Z" level=info msg="Mender running on partition: /dev/mmcblk0p1" func="github.com/mendersoftware/mender/cli.(*runOptionsType).commonCLIHandler" file="/path/to/mender/cli/cli.go:464"
time="2022-07-05T10:34:34Z" level=info msg="State transition: init [none] -> init [none]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=debug msg="No state data stored" func="github.com/mendersoftware/mender/app.(*initState).Handle" file="/path/to/mender/app/state.go:268"
time="2022-07-05T10:34:34Z" level=info msg="State transition: init [none] -> idle [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=info msg="State transition: init [none] -> init [none]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:34Z" level=info msg="State transition: init [none] -> idle [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:34Z" level=info msg="State transition: idle [Idle] -> authorize-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=info msg="State transition: idle [Idle] -> authorize-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=debug msg="Handle authorize wait state" func="github.com/mendersoftware/mender/app.(*authorizeWaitState).Handle" file="/path/to/mender/app/state.go:418"
time="2022-07-05T10:34:34Z" level=debug msg="Wait 0s before next authorization attempt" func="github.com/mendersoftware/mender/app.(*authorizeWaitState).Handle" file="/path/to/mender/app/state.go:428"
time="2022-07-05T10:34:34Z" level=info msg="State transition: authorize-wait [Idle] -> authorize [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=info msg="State transition: authorize-wait [Idle] -> authorize [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:34Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:34Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:34Z" level=debug msg="Handle authorize state" func="github.com/mendersoftware/mender/app.(*authorizeState).Handle" file="/path/to/mender/app/state.go:447"
time="2022-07-05T10:34:34Z" level=debug msg="received the FETCH_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:362"
time="2022-07-05T10:34:34Z" level=debug msg="Tenant token: <tenant-token>" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).MakeAuthRequest" file="/path/to/mender/app/auth.go:608"
time="2022-07-05T10:34:34Z" level=debug msg="Authorization data: {{\"emmc_serial\":\"<emmc-serial>\",\"eth0_mac\":\"<mac-addr>\",\"mac\":\"<mac-addr>\"} <tenant-token> <public-key>}" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).MakeAuthRequest" file="/path/to/mender/app/auth.go:613"
time="2022-07-05T10:34:34Z" level=debug msg="Making an authorization request () to server https://hosted.mender.io" func="github.com/mendersoftware/mender/client.(*AuthClient).Request" file="/path/to/mender/client/client_auth.go:52"
time="2022-07-05T10:34:35Z" level=debug msg="Got response: &{200 OK 200 HTTP/1.1 1 1 map[Connection:[keep-alive] Content-Length:[1072] Content-Type:[application/json; charset=utf-8] Date:[Tue, 05 Jul 2022 10:34:35 GMT] Referrer-Policy:[no-referrer] Strict-Transport-Security:[max-age=31536000; includeSubDomains; preload] X-Content-Type-Options:[nosniff] X-Men-Requestid:[aef23222-05c2-4986-8eb6-d2f19a8f529f] X-Xss-Protection:[1; mode=block]] 0x400000e0a0 1072 [] false false map[] 0x40002ce100 0x400014a2c0}" func="github.com/mendersoftware/mender/client.(*AuthClient).Request" file="/path/to/mender/client/client_auth.go:94"
time="2022-07-05T10:34:35Z" level=debug msg="Receive response data" func="github.com/mendersoftware/mender/client.(*AuthClient).Request" file="/path/to/mender/client/client_auth.go:100"
time="2022-07-05T10:34:35Z" level=debug msg="Received response data:  <byte array of JWT>" func="github.com/mendersoftware/mender/client.(*AuthClient).Request" file="/path/to/mender/client/client_auth.go:106"
time="2022-07-05T10:34:35Z" level=info msg="successfully received new authorization data" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).fetchAuthToken" file="/path/to/mender/app/auth.go:538"
time="2022-07-05T10:34:35Z" level=info msg="successfully received new authorization data" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).fetchAuthToken" file="/path/to/mender/app/auth.go:538"
time="2022-07-05T10:34:35Z" level=info msg="Server authorization successful" func="github.com/mendersoftware/mender/app.(*authorizeState).Handle" file="/path/to/mender/app/state.go:457"
time="2022-07-05T10:34:35Z" level=info msg="Server authorization successful" func="github.com/mendersoftware/mender/app.(*authorizeState).Handle" file="/path/to/mender/app/state.go:457"
time="2022-07-05T10:34:35Z" level=info msg="State transition: authorize [Sync] -> check-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:35Z" level=info msg="State transition: authorize [Sync] -> check-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:35Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:35Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:35Z" level=debug msg="Handle check wait state" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1120"
time="2022-07-05T10:34:35Z" level=debug msg="Check wait state; next checks: (update: 0001-01-01 00:30:00 +0000 UTC) (inventory: 0001-01-01 00:00:00 +0000 UTC)" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1131"
time="2022-07-05T10:34:35Z" level=debug msg="Next check: 0001-01-01 00:00:00 +0000 UTC:inventory-update, (2022-07-05 10:34:35.315180111 +0000 UTC m=+0.623313838)" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1149"
time="2022-07-05T10:34:35Z" level=debug msg="Check wait returned: inventory-update" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1181"
time="2022-07-05T10:34:35Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:35Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:35Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:35Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:35Z" level=debug msg="Returning artifact name full-frame-video-capture from database." func="github.com/mendersoftware/mender/device.(*DeviceManager).GetCurrentArtifactName" file="/path/to/mender/device/device.go:128"
time="2022-07-05T10:34:35Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:36Z" level=debug msg="Reading data from the device manifest file: /var/lib/mender/device_type" func=github.com/mendersoftware/mender/device.GetManifestData file="/path/to/mender/device/device.go:80"
time="2022-07-05T10:34:36Z" level=debug msg="device_type=mydevice" func=github.com/mendersoftware/mender/device.GetManifestData file="/path/to/mender/device/device.go:91"
time="2022-07-05T10:34:36Z" level=debug msg="Current manifest data: mydevice" func=github.com/mendersoftware/mender/device.GetManifestData file="/path/to/mender/device/device.go:98"
time="2022-07-05T10:34:36Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:36Z" level=debug msg="Connecting to server hosted.mender.io" func="github.com/mendersoftware/mender/client.(*ApiRequest).Do" file="/path/to/mender/client/client.go:219"
time="2022-07-05T10:34:36Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:36Z" level=debug msg="Inventory update sent, response &{200 OK 200 HTTP/1.1 1 1 map[Connection:[keep-alive] Content-Length:[0] Content-Type:[application/json; charset=utf-8] Date:[Tue, 05 Jul 2022 10:34:36 GMT] Referrer-Policy:[no-referrer] Strict-Transport-Security:[max-age=31536000; includeSubDomains; preload] X-Content-Type-Options:[nosniff] X-Men-Requestid:[e24d8b26-cd6c-4b78-879e-f12ac9466df0] X-Xss-Protection:[1; mode=block]] 0x400056cca0 0 [] false false map[] 0x40002ce800 0x400014a370}" func="github.com/mendersoftware/mender/client.(*InventoryClient).Submit" file="/path/to/mender/client/client_inventory.go:45"
time="2022-07-05T10:34:36Z" level=debug msg="Inventory refresh complete" func="github.com/mendersoftware/mender/app.(*inventoryUpdateState).Handle" file="/path/to/mender/app/state.go:1198"
time="2022-07-05T10:34:36Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:36Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:36Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:36Z" level=debug msg="Handle check wait state" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1120"
time="2022-07-05T10:34:36Z" level=debug msg="Check wait state; next checks: (update: 0001-01-01 00:30:00 +0000 UTC) (inventory: 2022-07-05 10:39:35.315180111 +0000 UTC m=+300.623313838)" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1131"
time="2022-07-05T10:34:36Z" level=debug msg="Next check: 0001-01-01 00:30:00 +0000 UTC:update-check, (2022-07-05 10:34:36.62859006 +0000 UTC m=+1.936723915)" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1149"
time="2022-07-05T10:34:36Z" level=debug msg="Check wait returned: update-check" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/path/to/mender/app/state.go:1181"
time="2022-07-05T10:34:36Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:36Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:36Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:36Z" level=debug msg="Handle update check state" func="github.com/mendersoftware/mender/app.(*updateCheckState).Handle" file="/path/to/mender/app/state.go:659"
time="2022-07-05T10:34:36Z" level=debug msg="Returning artifact name full-frame-video-capture from database." func="github.com/mendersoftware/mender/device.(*DeviceManager).GetCurrentArtifactName" file="/path/to/mender/device/device.go:128"
time="2022-07-05T10:34:36Z" level=debug msg="Reading data from the device manifest file: /var/lib/mender/device_type" func=github.com/mendersoftware/mender/device.GetManifestData file="/path/to/mender/device/device.go:80"
time="2022-07-05T10:34:36Z" level=debug msg="device_type=mydevice" func=github.com/mendersoftware/mender/device.GetManifestData file="/path/to/mender/device/device.go:91"
time="2022-07-05T10:34:36Z" level=debug msg="Current manifest data: mydevice" func=github.com/mendersoftware/mender/device.GetManifestData file="/path/to/mender/device/device.go:98"
time="2022-07-05T10:34:36Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:36Z" level=debug msg="Connecting to server hosted.mender.io" func="github.com/mendersoftware/mender/client.(*ApiRequest).Do" file="/path/to/mender/client/client.go:219"
time="2022-07-05T10:34:36Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:36Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:36Z" level=debug msg="Received response:200 OK" func=github.com/mendersoftware/mender/client.processUpdateResponse file="/path/to/mender/client/client_update.go:184"
time="2022-07-05T10:34:36Z" level=debug msg="Have update available" func=github.com/mendersoftware/mender/client.processUpdateResponse file="/path/to/mender/client/client_update.go:193"
time="2022-07-05T10:34:36Z" level=info msg="Correct request for getting image from: https://hosted.mender.io/api/devices/v1/deployments/download/configuration/<configuration_id>/mydevice/<device-id>?tenant_id=<tenant_id>&x-men-expire=2022-07-05T10%3A49%3A36Z&x-men-signature=<x-men-signature> [name: configuration-<configuration_id>; devices: [mydevice]]" func=github.com/mendersoftware/mender/client.validateGetUpdate file="/path/to/mender/client/client_update.go:176"
time="2022-07-05T10:34:36Z" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:36Z" level=info msg="Correct request for getting image from: https://hosted.mender.io/api/devices/v1/deployments/download/configuration/<configuration_id>/mydevice/<device-id>?tenant_id=<tenant_id>&x-men-expire=2022-07-05T10%3A49%3A36Z&x-men-signature=<x-men-signature> [name: configuration-<configuration_id>; devices: [mydevice]]" func=github.com/mendersoftware/mender/client.validateGetUpdate file="/path/to/mender/client/client_update.go:176"
time="2022-07-05T10:34:36Z" level=debug msg="Received update response: {{{https://hosted.mender.io/api/devices/v1/deployments/download/configuration/<configuration_id>/mydevice/<device-id>?tenant_id=<tenant_id>&x-men-expire=2022-07-05T10%3A49%3A36Z&x-men-signature=<x-men-signature> 2022-07-05T10:49:36.694529305Z} [mydevice] [] configuration-<configuration_id>  map[] []} <configuration_id> []  0 false}" func="github.com/mendersoftware/mender/app.(*Mender).CheckUpdate" file="/path/to/mender/app/mender.go:322"
time="2022-07-05T10:34:36Z" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/path/to/mender/app/mender.go:461"
time="2022-07-05T10:34:36Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:36Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:36Z" level=debug msg="statescript: The timeout for executing scripts is not defined; using default of 1h0m0s seconds" func=github.com/mendersoftware/mender/statescript.Launcher.getTimeout file="/path/to/mender/statescript/executor.go:82"
time="2022-07-05T10:34:36Z" level=info msg="Running Mender client version: 2.6.1" func="github.com/mendersoftware/mender/app.(*DeploymentLogManager).Enable" file="/path/to/mender/app/deployment_logger.go:143"
time="2022-07-05T10:34:36Z" level=info msg="Running Mender client version: 2.6.1" func="github.com/mendersoftware/mender/app.(*DeploymentLogManager).Enable" file="/path/to/mender/app/deployment_logger.go:143"
time="2022-07-05T10:34:36Z" level=debug msg="Handling update fetch state" func="github.com/mendersoftware/mender/app.(*updateFetchState).Handle" file="/path/to/mender/app/state.go:701"
time="2022-07-05T10:34:36Z" level=debug msg="received the GET_AUTH_TOKEN action" func="github.com/mendersoftware/mender/app.(*menderAuthManagerService).run" file="/path/to/mender/app/auth.go:359"
time="2022-07-05T10:34:36Z" level=debug msg="Connecting to server hosted.mender.io" func="github.com/mendersoftware/mender/client.(*ApiRequest).Do" file="/path/to/mender/client/client.go:219"
time="2022-07-05T10:34:36Z" level=debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/path/to/mender/client/client_status.go:90"
time="2022-07-05T10:34:36Z" level=debug msg="Received fetch update response &{404 Not Found 404 HTTP/1.1 1 1 map[Connection:[keep-alive] Content-Length:[54] Content-Type:[application/json] Date:[Tue, 05 Jul 2022 10:34:36 GMT] Referrer-Policy:[no-referrer] Server:[nginx] Strict-Transport-Security:[max-age=31536000; includeSubDomains; preload] X-Content-Type-Options:[nosniff] X-Xss-Protection:[1; mode=block]] 0x400033c840 54 [] false false map[] 0x40002cf000 0x400014a370}+" func="github.com/mendersoftware/mender/client.(*UpdateClient).FetchUpdate" file="/path/to/mender/client/client_update.go:146"
time="2022-07-05T10:34:36Z" level=error msg="Error fetching scheduled update info: code (404)" func="github.com/mendersoftware/mender/client.(*UpdateClient).FetchUpdate" file="/path/to/mender/client/client_update.go:151"
time="2022-07-05T10:34:36Z" level=error msg="Update fetch failed: (request_id: ): error receiving scheduled update information server error message: {\"error\": {\"status_code\": 404,\"message\": \"Not Found\"}}" func="github.com/mendersoftware/mender/app.(*updateFetchState).Handle" file="/path/to/mender/app/state.go:710"
time="2022-07-05T10:34:36Z" level=error msg="Error fetching scheduled update info: code (404)" func="github.com/mendersoftware/mender/client.(*UpdateClient).FetchUpdate" file="/path/to/mender/client/client_update.go:151"
time="2022-07-05T10:34:36Z" level=error msg="Update fetch failed: (request_id: ): error receiving scheduled update information server error message: {\"error\": {\"status_code\": 404,\"message\": \"Not Found\"}}" func="github.com/mendersoftware/mender/app.(*updateFetchState).Handle" file="/path/to/mender/app/state.go:710"
8

Thanks for sharing, and for masking all the device sensitive data :slight_smile:

I have two follow-up questions.
First off, it looks like there are two client processes running in parallel since log entries are duplicated, do you have two systemd units starting the mender client?
Second, does the actual name of your device type contain a slash character or any other special URL characters (e.g. ‘/’, ‘?’ or ‘&’)? I just discovered a bug that this will generate an un-resolvable URL, I reported the issue here. In the meantime, as a workaround, you can change the device type name (if that is the case, that is).

9

I’d be surprised if we were running multiple daemons, and all the journal logs have the same PID. I might have used the CLI to run check-update but that should just use the DBus to the running service right?

As for the device name, it does have a ., since we have a semver suffix for our device names. Would that cause the URL problem?

10

Ok, maybe it’s the check-update CLI call that’s causing the duplicate log messages.

It shouldn’t be a problem that the device type contains a period . as it does not have any special interpretation as a path component. However, when I tried it myself it turns out it is a problem. I will include this observation in the bug tracker once I’ve investigated a little bit more.

11

Thanks for all of your investigative work - I can see that a fix has been merged. I’d like to give it a try - are there binaries available from CI or will I have to build manually? On a related note, is there anything special (state scripts) that has to be done when updating the Mender client via Mender, or can it be treated like any other update?