Update-Loop - overwrite partition b, then a, again

General Discussions
1

Hi.
Sorry for my bad english.
I have a problem with mender-update-process.
My System is a debian on a x86_64 system, converted with mender-convert in version 2.4.0
Now I use a golden Image and try to create a artifact (file.mender) with mender-artifact (testet in version 3.4.2 and 3.6).
Everything looks fine. The client connects to the self hosted mender-server and starts the update-process. Also the reboot is fine. After that, I had a problem, getting the connection from client to server (credentials are okay). “Network unreachable”. After a while of waiting, the download from the update starts again and the installation on the first partition (overwrite my rollback-partition) is starting. The status on mender-server tells me the correct order. Pending, download, install, reboot. → then it starts again with download.
I fixed this with a delay in mender-client.service startup. Okay… now the client is not started by the service, I start it directly after reboot, by hand (mender-client.service: Start-pre operation timed out. Terminating). Now the error message with non reachable network is gone. But the result is the same. After a while, the download will start again and installation on my old partition is starting.
I checked the server-logs.

Do you have any idea, how to solve this problem? Thanks a lot.

Log:

Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="Validating the Update Info: https://iv-tecwatch-manage-0:9000/mender-artifact-storage/a3aff170-427b-4af6-a7a4-a4eba0819feb?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Content-Sha256=UNSIGNED-PAYLOAD&X-Amz-Credential=minio%2F20211221%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20211221T070759Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=00e2effdc6520ef448bb5f9067954517613ffaf07db25426e24ed1f1975b08e6 [name: release-1; devices: [x86_64]]"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="Running Mender client version: 3.0.0"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="No public key was provided for authenticating the artifact"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="Opening device \"/dev/sda3\" for writing"
Dec 21 08:07:46 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:07:46+01:00" level=info msg="Native sector size of block device /dev/sda3 is 512 bytes. Mender will write in chunks of 1048576 bytes"
Dec 21 08:42:10 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:10+01:00" level=info msg="All bytes were successfully written to the new partition"
Dec 21 08:42:10 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:10+01:00" level=info msg="The optimized block-device writer wrote a total of 39961 frames, where 410 frames did need to be rewritten (i.e., skipped)"
Dec 21 08:42:12 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:12+01:00" level=info msg="Wrote 41901096960/41901096960 bytes to the inactive partition"
Dec 21 08:42:12 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:12+01:00" level=info msg="State transition: update-store [Download_Enter] -> update-after-store [Download_Leave]"
Dec 21 08:42:12 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:12+01:00" level=info msg="State transition: update-after-store [Download_Leave] -> mender-update-control [none]"
Dec 21 08:42:12 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:12+01:00" level=info msg="Executing script: Download_Leave_00"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: target directorys exists: Start copy configurationfiles
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: Copied Configuration
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="Collected output (stderr) while running script /etc/mender/scripts/Download_Leave_00\nartifact_name=release-7: Running Download_Leave_00\n\n---------- end of script output"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="State transition: mender-update-control [none] -> update-install [ArtifactInstall]"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="Enabling partition with new image installed to be a boot candidate: 3"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="State transition: update-install [ArtifactInstall] -> mender-update-control [none]"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="State transition: mender-update-control [none] -> reboot [ArtifactReboot_Enter]"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="Rebooting device(s)"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="Mender rebooting from active partition: /dev/sda2"
Dec 21 08:42:14 MDM-DELL-SERVER-1 mender[754]: time="2021-12-21T08:42:14+01:00" level=info msg="Daemon terminated with SIGTERM"
Dec 21 08:47:17 MDM-DELL-SERVER-1 systemd[1]: mender-client.service: Start-pre operation timed out. Terminating.
Dec 21 08:47:17 MDM-DELL-SERVER-1 systemd[1]: mender-client.service: Control process exited, code=killed, status=15/TERM
Dec 21 08:47:17 MDM-DELL-SERVER-1 systemd[1]: mender-client.service: Failed with result 'timeout'.
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="'UpdateControlMapExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 2*UpdatePollIntervalSeconds"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="'UpdateControlMapBootExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 600 seconds"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="Mender running on partition: /dev/sda3"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="State transition: init [none] -> init [none]"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="State transition: init [none] -> idle [Idle]"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Dec 21 08:56:09 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T08:56:09+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"




Dec 21 09:01:54 MDM-DELL-SERVER-1 mender[5932]: /usr/share/mender/inventory/mender-inventory-geo: Unable to get IP info from ipinfo.io
Dec 21 09:01:54 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:54+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Dec 21 09:01:54 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:54+01:00" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="Device unauthorized; attempting reauthorization"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: using interface /sys/class/net/eth0
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="successfully received new authorization data"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="Validating the Update Info: https://iv-tecwatch-manage-0:9000/mender-artifact-storage/a3aff170-427b-4af6-a7a4-a4eba0819feb?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Content-Sha256=UNSIGNED-PAYLOAD&X-Amz-Credential=minio%2F20211221%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20211221T080207Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=7d29b4deba49ec0960ac12b48580d3e2ea043081be03e11b19f1f74ca3278028 [name: release-1; devices: [x86_64]]"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="Running Mender client version: 3.0.0"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="No public key was provided for authenticating the artifact"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="Opening device \"/dev/sda2\" for writing"
Dec 21 09:01:55 MDM-DELL-SERVER-1 mender[5932]: time="2021-12-21T09:01:55+01:00" level=info msg="Native sector size of block device /dev/sda2 is 512 bytes. Mender will write in chunks of 1048576 bytes"
2

Hi @daniel1

Can I have a look at both the script you are running, and the modifications done to the mender-client systemd service file?

3

Hi.
Thank you for your reply!

The Script is only for copy some config-files.

#!/bin/sh
#
#

echo "$(cat /etc/mender/artifact_info): Running $(basename "$0")" >&2

if [ ! -x /usr/bin/fw_printenv ]; then
    exit 1
fi

current=$(/usr/bin/fw_printenv mender_boot_part | awk -F = '{ print $2 }')

if [ $current = "2" ]; then
    newroot=/dev/sda3
elif [ $current = "3" ]; then
    newroot=/dev/sda2
else
    echo "Unexpected current root: $current" >&2
    exit 1
fi

mount $newroot /mnt

if [ $? -ne 0 ]; then
    echo "Failed to mount $newroot" >&2
    exit 1
fi

sleep 2

if [ -d /mnt/etc/network ]; then
    echo "target directorys exists: Start copy configurationfiles"
    cp /etc/network/interfaces /mnt/etc/network/interfaces
    cp /etc/ntp.conf /mnt/etc/ntp.conf
    cp /etc/hostname /mnt/etc/hostname
    cp /etc/hosts /mnt/etc/hosts
    cp /etc/iptables.up.rules /mnt/etc/iptables.up.rules

    cp /etc/mender/scripts/Download_Leave_00 /mnt/etc/mender/scripts/Download_Leave_00

    echo "Copied Configuration" >&1

else
    echo "Failed to find one of the target directorys on newroot partition" >&2
    exit 1
fi
umount $newroot

The mender-client.service: (customized line is bold)

[Unit]
Description=Mender OTA update service
Wants=network-online.target
After=systemd-resolved.service network-online.target mender.service
Conflicts=mender.service

[Service]
**ExecStartPre=/bin/sleep 180**
Type=idle
User=root
Group=root
ExecStart=/usr/bin/mender daemon
Restart=on-abort

[Install]
WantedBy=multi-user.target
4

Interesting!

Is there any chance you can reproduce this once more, and run the client in debug mode?

That would mean:

ExecStart=/usr/bin/mender --log-level debug daemon
```