Wait for network connection before uploading status report

Hi there,

I’m looking for a way for the mender client on a device to wait for a network connection (or timeout) before trying to update the status report. The situation that prompted this came from forcing a shut down of the device while it was downloading an update. This generated the following logs:

2020-09-25 16:33:50 +0000 UTC info: Running Mender client version: 2.3.0
2020-09-25 16:33:51 +0000 UTC info: State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]
2020-09-25 16:33:51 +0000 UTC info: No public key was provided for authenticating the artifact
2020-09-25 16:33:51 +0000 UTC info: Update Module path "/usr/share/mender/modules/v3" could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available
2020-09-25 16:33:51 +0000 UTC info: Opening device "/dev/mmcblk0p2" for writing
2020-09-25 16:33:51 +0000 UTC info: Native sector size of block device /dev/mmcblk0p2 is 512 bytes. Mender will write in chunks of 1048576 bytes
2020-09-25 16:35:46 +0000 UTC info: Running Mender client version: 2.3.0
2020-09-25 16:35:46 +0000 UTC error: Mender shut down in state: update-store
2020-09-25 16:35:46 +0000 UTC info: Update Module path "/usr/share/mender/modules/v3" could not be opened (open /usr/share/mender/modules/v3: no such file or directory). Update modules will not be available
2020-09-25 16:35:46 +0000 UTC info: State transition: init [none] -> cleanup [Error]
2020-09-25 16:35:46 +0000 UTC info: State transition: cleanup [Error] -> update-status-report [none]
2020-09-25 16:35:46 +0000 UTC error: Failed to report status: Put "https://hosted.mender.io/api/devices/v1/deployments/device/deployments/: dial tcp: lookup hosted.mender.io on [::1]:53: server misbehaving
2020-09-25 16:35:46 +0000 UTC error: error reporting update status: reporting status failed: Put "https://hosted.mender.io/api/devices/v1/deployments/device/deployments/": dial tcp: lookup hosted.mender.io on [::1]:53: server misbehaving
2020-09-25 16:35:46 +0000 UTC error: Failed to send status to server: transient error: reporting status failed: Put "https://hosted.mender.io/api/devices/v1/deployments/device/deployments/": dial tcp: lookup hosted.mender.io on [::1]:53: server misbehaving
2020-09-25 16:35:46 +0000 UTC info: State transition: update-status-report [none] -> update-retry-report [none]
2020-09-25 16:39:02 +0000 UTC info: State transition: update-retry-report [none] -> update-status-report [none]

I’ve looked for a state script option, but did not find one that runs in this situation. Any help or information is appreciated.
Thanks!

There is a Yocto example here: https://github.com/mendersoftware/meta-mender/tree/master/meta-mender-core/recipes-mender/mender-wait-for-timesync

Drew

Sorry, I should clarify, that script waits for time sync to complete but you could simply check if you can ping a specific IP address or something instead.

Drew

Hi Drew,

Thanks for the reply! I have a script to check network connectivity, but I’m more looking for a type of state script that runs in this situation. For example, I’ve tried using it as the Download_Error state script to no avail. To my understanding, the example you linked would not run in this situation since the script was set as an ArtifactCommit_Enter script. I think what I would ideally be looking for is a state script that runs during one of these transitions from the above logs:

2020-09-25 16:35:46 +0000 UTC info: State transition: init [none] -> cleanup [Error]
2020-09-25 16:35:46 +0000 UTC info: State transition: cleanup [Error] -> update-status-report [none]

Does something like that exist? Sorry for any confusion. Thanks!

Hi @amorgan you probably want a Sync_Enter state script as that runs prior to any communication with the server.

I see that Sync_Enter is a common place for network checks here, but I don’t see anything there that suggests it will run when a download has already started. Also wouldn’t the deployment log say something about being in a Sync state if it were happening?

No we don’t explicitly log that.

I don’t understand what you are trying to accomplish. It seems to me that you had a deployment in progress but then rebooted the device before it completed. On the next boot, the Mender client will detect this and using the standard Sync state connect with the server and upload the report. The only way to delay that is to use the Sync_Enter state script.

Drew

I think you get what I’m trying to accomplish based on what you say. I want to delay the attempt to upload the report because it seems like mender is trying to upload the report before our devices networking is on and working.

For what you suggest, I’ve tried recreating the same situation with a Sync_Enter state script logging to an external file when it is run to check when is running. The script works as expected for normal check-ins, but it does not seem to be run after the reboot. Is there a better way to tell if it’s being run? Or do you have any other ideas to try? Thanks!

I would have it log to a file in /tmp so you can see whether it is doing anything or not.

Ok I tried this a couple times. After starting the update, I emptied the file before forcing the reboot. The file remained empty the entire time while mender was trying to update the status. I feel pretty confident the Sync_Enter script is not running in this situation. Any other ideas? Thanks!

Can you provide the output from the following?

$ sudo ls -l /etc/mender/scripts/
$ sudo journalctl -u mender-client

Sure.
scripts:

~# ls -l /etc/mender/scripts/
-rwxr-xr-x    1 root     root          2000 Mar  9  2018 Download_Enter_10
-rwxr-xr-x    1 root     root           321 Mar  9  2018 Idle_Enter_10
-rwxr-xr-x    1 root     root           650 Sep 29 18:53 Sync_Enter_09_connection_check
-rwxr-xr-x    1 root     root           667 Mar  9  2018 Sync_Enter_10
-rw-r--r--    1 root     root             1 Mar  9  2018 version

journal:

Oct 01 15:59:05 luci-som-imx8 systemd[1]: Started Mender OTA update service.
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="Mender running on partition: /dev/mmcblk0p2"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="State transition: init [none] -> init [none]"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="State transition: init [none] -> idle [Idle]"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="authorization data present and valid"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="Collected output (stderr) while running script /etc/mender/scripts/Sync_Enter_09_connection_check\nwge>
Oct 01 15:59:06 luci-som-imx8 mender[634]: time="2020-10-01T15:59:06Z" level=info msg="statescript: Sync_Enter_09_connection_check requested a retry"
Oct 01 15:59:40 luci-som-imx8 mender[634]: time="2020-10-01T15:59:40Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Oct 01 15:59:40 luci-som-imx8 mender[634]: time="2020-10-01T15:59:40Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Oct 01 16:01:43 luci-som-imx8 mender[634]: time="2020-10-01T16:01:43Z" level=info msg="Correct request for getting image from: https://s3.amazonaws.com/hosted-mender-artifacts/5b5219ba3bc50>
Oct 01 16:01:43 luci-som-imx8 mender[634]: time="2020-10-01T16:01:43Z" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]"
Oct 01 16:01:47 luci-som-imx8 mender[634]: time="2020-10-01T16:01:47Z" level=info msg="Running Mender client version: 2.3.0"
Oct 01 16:01:49 luci-som-imx8 mender[634]: time="2020-10-01T16:01:49Z" level=info msg="State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]"
Oct 01 16:01:50 luci-som-imx8 mender[634]: time="2020-10-01T16:01:50Z" level=info msg="No public key was provided for authenticating the artifact"
Oct 01 16:01:50 luci-som-imx8 mender[634]: time="2020-10-01T16:01:50Z" level=info msg="Update Module path \"/usr/share/mender/modules/v3\" could not be opened (open /usr/share/mender/module>
Oct 01 16:01:50 luci-som-imx8 mender[634]: time="2020-10-01T16:01:50Z" level=info msg="Opening device \"/dev/mmcblk0p3\" for writing"
Oct 01 16:01:50 luci-som-imx8 mender[634]: time="2020-10-01T16:01:50Z" level=info msg="Native sector size of block device /dev/mmcblk0p3 is 512 bytes. Mender will write in chunks of 1048576>
-- Reboot --
Oct 01 16:02:15 luci-som-imx8 systemd[1]: Started Mender OTA update service.
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="Mender running on partition: /dev/mmcblk0p2"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="State transition: init [none] -> init [none]"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="Handling loaded state: update-store"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="Running Mender client version: 2.3.0"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=error msg="Mender shut down in state: update-store"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="Update Module path \"/usr/share/mender/modules/v3\" could not be opened (open /usr/share/mender/module>
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="State transition: init [none] -> cleanup [Error]"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="State transition: cleanup [Error] -> update-status-report [none]"
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=error msg="Failed to report status: Put \"https://hosted.mender.io/api/devices/v1/deployments/device/deployments>
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=error msg="error reporting update status: reporting status failed: Put \"https://hosted.mender.io/api/devices/v1>
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=error msg="Failed to send status to server: transient error: reporting status failed: Put \"https://hosted.mende>
Oct 01 16:02:16 luci-som-imx8 mender[656]: time="2020-10-01T16:02:16Z" level=info msg="State transition: update-status-report [none] -> update-retry-report [none]"

Hmm. I’m not sure what to suggest next. @kacf do you have any suggestions?
Drew