Update not working

General Discussions
1

Hi,

I’ve integrated mender into our board and went through the integration checklist ok but for some reason an image update isn’t working. It does the update and reboots but as soon after booting it reboots again. I checked the update and it’s using the right device for the update

Oct 22 13:14:36 octave-imx8mnevk mender[375]: time="2020-10-22T13:14:36Z" level=info msg="Opening device \"/dev/mmcblk2p2\" for writing"
Oct 22 13:14:36 octave-imx8mnevk mender[375]: time="2020-10-22T13:14:36Z" level=info msg="Native sector size of block device /dev/mmcblk2p2 is 512 bytes. Mender will write in chunks of 1048576 bytes"
Oct 22 13:15:56 octave-imx8mnevk mender[375]: time="2020-10-22T13:15:56Z" level=info msg="All bytes were successfully written to the new partition"
Oct 22 13:15:56 octave-imx8mnevk mender[375]: time="2020-10-22T13:15:56Z" level=info msg="The optimized block-device writer wrote a total of 5449 frames, where 0 frames did need to be rewritten (i.e., skipped)"
Oct 22 13:15:57 octave-imx8mnevk mender[375]: time="2020-10-22T13:15:57Z" level=info msg="Wrote 5712642048/5712642048 bytes to the inactive partition"
Oct 22 13:15:57 octave-imx8mnevk mender[375]: time="2020-10-22T13:15:57Z" level=info msg="State transition: update-store [Download_Enter] -> update-after-store [Download_Leave]"

Which looks good as it’s updated the image to /dev/mmcblk2p2. But when it reboots the kernel command line is wrong

[ 0.000000][ T0] Kernel command line: root=/dev/mmcblk2p1 console=ttymxc1,115200 earlycon=ec_imx6q,0x30890000,115200 maxcpus=0

NOTE: I’m using an eMMC where the bootloader is in mmcblk2boot0 so Mender is setup to use

MENDER_ROOTFS_PART_A="/dev/mmcblk2p1"
MENDER_ROOTFS_PART_A_DEFAULT="/dev/mmcblk2p1"
MENDER_ROOTFS_PART_A_NAME="/dev/mmcblk2p1"
MENDER_ROOTFS_PART_A_NAME_DEFAULT="/dev/mmcblk2p1"
MENDER_ROOTFS_PART_A_NAME_DEFAULT_mender-ubi="/dev/mmcblk2:rootfsa"
MENDER_ROOTFS_PART_A_NUMBER="1"
MENDER_ROOTFS_PART_A_NUMBER_DEFAULT="1"
MENDER_ROOTFS_PART_A_NUMBER_DEFAULT_mender-ubi="0"
MENDER_ROOTFS_PART_B="/dev/mmcblk2p2"
MENDER_ROOTFS_PART_B_DEFAULT="/dev/mmcblk2p2"
MENDER_ROOTFS_PART_B_NAME="/dev/mmcblk2p2"
MENDER_ROOTFS_PART_B_NAME_DEFAULT="/dev/mmcblk2p2"
MENDER_ROOTFS_PART_B_NAME_DEFAULT_mender-ubi="/dev/mmcblk2:rootfsb"
MENDER_ROOTFS_PART_B_NUMBER="2"
MENDER_ROOTFS_PART_B_NUMBER_DEFAULT="2"
MENDER_ROOTFS_PART_B_NUMBER_DEFAULT_mender-ubi="1"

When the new image boots I managed to log in and get the journal output before it reboots and I get the following

Oct 22 13:16:17 octave-imx8mnevk login[309]: ROOT LOGIN  on '/dev/ttymxc1'
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Started Wait for Network to be Configured.
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Reached target Network is Online.
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Started Mender OTA update service.
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Reached target Multi-User System.
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Starting Update UTMP about System Runlevel Changes...
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Started Update UTMP about System Runlevel Changes.
Oct 22 13:16:24 octave-imx8mnevk systemd[1]: Startup finished in 1.869s (kernel) + 18.834s (userspace) = 20.704s.
Oct 22 13:16:24 octave-imx8mnevk mender[318]: time="2020-10-22T13:16:24Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Oct 22 13:16:24 octave-imx8mnevk mender[318]: time="2020-10-22T13:16:24Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Oct 22 13:16:24 octave-imx8mnevk mender[318]: time="2020-10-22T13:16:24Z" level=info msg="Mender running on partition: /dev/mmcblk2p1"
Oct 22 13:16:25 octave-imx8mnevk mender[318]: time="2020-10-22T13:16:25Z" level=info msg="State transition: init [none] -> init [none]"

It probably reboots because it maybe detects that it has rebooted to the same partition?

To prove it can boot the other image I ran

root@octave-imx8mnevk:~# fw_setenv mender_boot_part 2
root@octave-imx8mnevk:~# fw_setenv mender_boot_part_hex 2

and rebooted and it was fine

$ mount
/dev/mmcblk2p2 on / type ext4 (ro,relatime)

Any ideas to what I have done wrong? I can’t recall making any changes to U-Boot I think the automatic integration was fine.

2

Forgot to include the mender configuration:

MENDER_ARTIFACT_NAME = "release-2020-10-21"
MENDER_STORAGE_DEVICE = "/dev/mmcblk2"
MENDER_STORAGE_TOTAL_SIZE_MB ?= "15028"
MENDER_UBOOT_STORAGE_INTERFACE = "mmc"
MENDER_UBOOT_STORAGE_DEVICE = "2"


#    Mender Partitions - we are going to keep the defaults:
#       MENDER_ROOTFS_PART_A = "${MENDER_STORAGE_DEVICE_BASE}1"
#       MENDER_ROOTFS_PART_B = "${MENDER_STORAGE_DEVICE_BASE}2"
#       MENDER_DATA_PART = "${MENDER_STORAGE_DEVICE_BASE}3"

MENDER_BOOT_PART_SIZE_MB ?= "0"
MENDER_DATA_PART_SIZE_MB ?= "4096"

PREFERRED_VERSION_pn-mender-client = "2.4.0"
PREFERRED_VERSION_pn-mender-artifact = "3.4.0"
PREFERRED_VERSION_pn-mender-artifact-native = "3.4.0"


MENDER_FEATURES_ENABLE = " \
    mender-uboot \
    mender-image-sd \
    mender-image \
    mender-client-install \
    mender-systemd \
"
MENDER_FEATURES_DISABLE_append = " mender-grub mender-image-uefi"

# Required for Mender
PREFERRED_PROVIDER_u-boot-fw-utils = "u-boot-imx-fw-utils"
PREFERRED_RPROVIDER_u-boot-fw-utils = "u-boot-imx-fw-utils"
3

Can you post the output of the following from the LInux runtime:

# lsblk
# fdisk -l
# cat /etc/fw_env.config

and from the U-Boot prompt:

u-boot> mmc list
u-boot> mmc dev 2
u-boot> mmc part
4

There’s no lsblk on the rootfs so I’ve dumped out /proc/partitions in case this helps

root@octave-imx8mnevk:~# lsblk
-sh: lsblk: not found
root@octave-imx8mnevk:~# cat /proc/partitions 
major minor  #blocks  name

  31        0      32768 mtdblock0
 179        0   15388672 mmcblk2
 179        1    5578752 mmcblk2p1
 179        2    5578752 mmcblk2p2
 179        3    4194304 mmcblk2p3
 179       96   31166976 mmcblk1
 179       97      85196 mmcblk1p1
 179       98     179308 mmcblk1p2
root@octave-imx8mnevk:~# fdisk -l
Disk /dev/mmcblk2: 15 GB, 15758000128 bytes, 30777344 sectors
240448 cylinders, 4 heads, 32 sectors/track
Units: sectors of 1 * 512 = 512 bytes

Device       Boot StartCHS    EndCHS        StartLBA     EndLBA    Sectors  Size Id Type
/dev/mmcblk2p1    384,0,1     1023,3,32        49152   11206655   11157504 5448M 83 Linux
/dev/mmcblk2p2    1023,3,32   1023,3,32     11206656   22364159   11157504 5448M 83 Linux
/dev/mmcblk2p3    1023,3,32   1023,3,32     22364160   30752767    8388608 4096M 83 Linux
Disk /dev/mmcblk1: 30 GB, 31914983424 bytes, 62333952 sectors
486984 cylinders, 4 heads, 32 sectors/track
Units: sectors of 1 * 512 = 512 bytes

Device       Boot StartCHS    EndCHS        StartLBA     EndLBA    Sectors  Size Id Type
/dev/mmcblk1p1 *  128,0,1     1023,3,32        16384     186775     170392 83.1M  c Win95 FAT32 (LBA)
/dev/mmcblk1p2    1023,3,32   1023,3,32       196608     555223     358616  175M 83 Linux
root@octave-imx8mnevk:~# cat /etc/fw_env.config 
/dev/mmcblk2 0x800000 0x1000
/dev/mmcblk2 0x1000000 0x1000

U-Boot output

u-boot=> mmc list
FSL_SDHC: 1
FSL_SDHC: 2 (eMMC)
u-boot=> mmc dev 2
switch to partitions #0, OK
mmc2(part 0) is current device
u-boot=> mmc part

Partition Map for MMC device 2  --   Partition Type: DOS

Part	Start Sector	Num Sectors	UUID		Type
  1	49152     	11157504  	beeafdb6-01	83
  2	11206656  	11157504  	beeafdb6-02	83
  3	22364160  	8388608   	beeafdb6-03	83
5

Is this a consistent failure? Can you interrupt the UBoot before booting with the wrong command line and print the entire U-Boot environment?

One possibility is that the fw_env.config contents don’t match what is built into U-Boot. It’s possible that one of the environment blocks matches but the other does not. That would make it seem like you could sometimes properly write to the environment from Linux and sometimes not. You would have to scrutinize the U-Boot sources for your particular port to determine.

6

Thanks for the reply Drew. It is a consistent failure. I can interrupt U-Boot and here is the environment

altbootcmd=run mender_altbootcmd; run bootcmd
autoload=no
baudrate=115200
bootcmd=run mender_setup; setenv bootargs root=${mender_kernel_root} ${bootargs}; if test "${fdt_addr_r}" != ""; then load ${mender_uboot_root} ${fdt_addr_r} /boot/${mender_dtb_name}; fi; load ${mender_uboot_root} ${kernel_addr_r} /boot/${mender_kernel_name}; ${mender_boot_kernel_type} ${kernel_addr_r} - ${fdt_addr_r}; run mender_try_to_recover
bootcmd_mfg=run mfgtool_args;if iminfo ${initrd_addr}; then if test ${tee} = yes; then bootm ${tee_addr} ${initrd_addr} ${fdt_addr}; else booti ${loadaddr} ${initrd_addr} ${fdt_addr}; fi; else echo "Run fastboot ..."; fastboot 0; fi;
bootcount=1
bootdelay=2
bootlimit=1
console=ttymxc1,115200 earlycon=ec_imx6q,0x30890000,115200
emmc_dev=2
ethaddr=00:04:9f:06:61:31
ethprime=FEC
fastboot_dev=mmc2
fdtcontroladdr=bc92a8e0
kboot=booti 
kernel_addr_r=0x48000000
kernel_image=fitImage-octave-imx8mnevk.bin
kernel_image_rootfs=fitImage-octave-imx8mnevk.bin
loadaddr=0x48000000
loglevel=5
mender_altbootcmd=if test ${mender_boot_part} = 1; then setenv mender_boot_part 2; setenv mender_boot_part_hex 2; else setenv mender_boot_part 1; setenv mender_boot_part_hex 1; fi; setenv upgrade_available 0; saveenv; run mender_setup
mender_boot_kernel_type=bootm
mender_boot_part=1
mender_boot_part_hex=1
mender_check_saveenv_canary=1
mender_dtb_name=octopus,octave-imx8mnevk.dtb
mender_kernel_name=fitImage
mender_post_setup_commands=setenv bootargs console=${console} maxcpus=0
mender_saveenv_canary=1
mender_setup=if test "${mender_saveenv_canary}" != "1"; then setenv mender_saveenv_canary 1; saveenv; fi; if test "${mender_pre_setup_commands}" != ""; then run mender_pre_setup_commands; fi; if test "${mender_systemd_machine_id}" != ""; then setenv bootargs systemd.machine_id=${mender_systemd_machine_id} ${bootargs}; fi; setenv mender_kernel_root /dev/mmcblk2p${mender_boot_part}; if test ${mender_boot_part} = 1; then setenv mender_boot_part_name /dev/mmcblk2p1; else setenv mender_boot_part_name /dev/mmcblk2p2; fi; setenv mender_kernel_root_name ${mender_boot_part_name}; setenv mender_uboot_root mmc 2:${mender_boot_part_hex}; setenv mender_uboot_root_name ${mender_boot_part_name}; setenv expand_bootargs "setenv bootargs \\"${bootargs}\\""; run expand_bootargs; setenv expand_bootargs; if test "${mender_post_setup_commands}" != ""; then run mender_post_setup_commands; fi
mender_try_to_recover=if test ${upgrade_available} = 1; then reset; fi
mender_uboot_boot=mmc 2:1
mender_uboot_dev=2
mender_uboot_if=mmc
mfgtool_args=setenv bootargs console=${console},${baudrate} rdinit=/linuxrc clk_ignore_unused 
mmcautodetect=yes
sd_dev=1
serial#=2244220a5c85f0d6
soc_type=imx8mn
stderr=serial
stdin=serial
stdout=serial
upgrade_available=0

I also used the mmc command to copy out the environments from MMC to address 0x40000000 and then checked each environment:

40800500: 746f6f623d657079 7265646e656d006d    ype=bootm.mender
40800510: 61705f746f6f625f 6e656d00313d7472    _boot_part=1.men
40800520: 746f6f625f726564 65685f747261705f    der_boot_part_he
40800530: 646e656d00313d78 6b636568635f7265    x=1.mender_check

and

41000500: 746f6f623d657079 7265646e656d006d    ype=bootm.mender
41000510: 61705f746f6f625f 6e656d00313d7472    _boot_part=1.men
41000520: 746f6f625f726564 65685f747261705f    der_boot_part_he
41000530: 646e656d00313d78 6b636568635f7265    x=1.mender_check

And hopefully you can see they both have the same mender_boot_part and mender_boot_part_hex set to 1. It looks like neither has been updated by the client during the update. My rootfs is really cut down, is there a certain utility that the client is expecting other that the uboot-fwutils? I will also check my U-Boot sources to see if the offsets match.

7

Just grepping the mender-client code and I see a few references to bash which is not installed on the target, we currently use ash from busybox and the hope is to remove any sort of shell, would this cause the mender-client any problems?

8

None that I am aware of but @kacf may have more insight.

Interestingly though your environment variable mender_boot_part is set to 1 rather than 2. That’s consistent with your report but inconsistent with having run an update.

How did you do the deployment? Was it a full end-to-end test with the Mender server or did you use standalone mode?

Do you have any state scripts installed?

Is it a standard full image update or are you using a custom update module?

Can you provide the full journalctl logs from mender-client on the system when it is applying the update?

Drew

9

Full end-to-end test with a Mender Server running locally on my laptop. It’s pretty much a vanilla installation with no custom update modules or state scripts installed and it’s a full image update.

Here is the log of the update

Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="State transition: init [none] -> idle [Idle]"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="authorization data present and valid"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Oct 24 09:58:42 octave-imx8mnevk mender[318]: time="2020-10-24T09:58:42Z" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Oct 24 09:58:58 octave-imx8mnevk systemd[1]: systemd-hostnamed.service: Succeeded.
Oct 24 09:59:39 octave-imx8mnevk systemd[1]: Condition check resulted in Mender persistent data dir being skipped.
Oct 24 09:59:39 octave-imx8mnevk systemd[1]: Stopping Mender OTA update service...
Oct 24 09:59:39 octave-imx8mnevk systemd[1]: mender-client.service: Succeeded.
Oct 24 09:59:39 octave-imx8mnevk systemd[1]: Stopped Mender OTA update service.
Oct 24 09:59:39 octave-imx8mnevk systemd[1]: Started Mender OTA update service.
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Mender running on partition: /dev/mmcblk2p1"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: init [none] -> init [none]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: init [none] -> idle [Idle]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="authorization data present and valid"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: idle [Idle] -> check-wait [Idle]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=warning msg="Inventory tool /usr/share/mender/inventory/mender-inventory-geo wait failed: exit status 2"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Correct request for getting image from: https://rufilla.octopus.mender.com:9000/mender-artifact-storage/7363f185-979d-4915-94a8-92cd68c1760d?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=mender-deployments%2F20201024%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20201024T095940Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=c713444619b422ec5a468e4aa7a98e6be139a20209cd58788e85a79f499a40e4 [name: release-2020-10-21; devices: [octave-imx8mnevk]]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Running Mender client version: 2.4.0"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="No public key was provided for authenticating the artifact"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="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"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Opening device \"/dev/mmcblk2p2\" for writing"
Oct 24 09:59:40 octave-imx8mnevk mender[368]: time="2020-10-24T09:59:40Z" level=info msg="Native sector size of block device /dev/mmcblk2p2 is 512 bytes. Mender will write in chunks of 1048576 bytes"
Oct 24 10:01:00 octave-imx8mnevk mender[368]: time="2020-10-24T10:01:00Z" level=info msg="All bytes were successfully written to the new partition"
Oct 24 10:01:00 octave-imx8mnevk mender[368]: time="2020-10-24T10:01:00Z" level=info msg="The optimized block-device writer wrote a total of 5449 frames, where 0 frames did need to be rewritten (i.e., skipped)"
Oct 24 10:01:01 octave-imx8mnevk mender[368]: time="2020-10-24T10:01:01Z" level=info msg="Wrote 5712642048/5712642048 bytes to the inactive partition"
Oct 24 10:01:01 octave-imx8mnevk mender[368]: time="2020-10-24T10:01:01Z" level=info msg="State transition: update-store [Download_Enter] -> update-after-store [Download_Leave]"
Oct 24 10:01:01 octave-imx8mnevk mender[368]: t         Stopping Serial Getty on ttymxc1...
         Stopping Login Service...
         Stopping Load/Save Random Seed...
        [snip]

If there is a way to get more debugging information let me know and I’ll enable it.

10

I can’t immediately see what the problem is, but the log appears truncated to me. It should go through more steps before rebooting.

Can you add -debug to the arguments inside /lib/systemd/system/mender-client.service, and post the log again?

11

It’s a 1.4GHz quad core processor so maybe it has stopped the journal before it has had time to send the output to the console. Is there a way to delay the reboot after an update?

Here the log with -debug (Had to truncate as there is a character limit on the post, let me know if there is a better way of uploading logs)

debug msg="Inventory refresh complete" func="github.com/mendersoftware/mender/app.(*inventoryUpdateState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1198"
info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
debug msg="Handle check wait state" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1120"
debug msg="Check wait state; next checks: (update: 0001-01-01 00:30:00 +0000 UTC) (inventory: 2020-10-26 18:59:02.186646415 +0000 UTC m=+28800.415726458)" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1131"
debug msg="Next check: 0001-01-01 00:30:00 +0000 UTC:update-check, (2020-10-26 10:59:02.292615046 +0000 UTC m=+0.521695089)" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1149"
debug msg="Check wait returned: update-check" func="github.com/mendersoftware/mender/app.(*checkWaitState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1181"
info msg="State transition: check-wait [Idle] -> update-check [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: check-wait [Idle] -> update-check [Sync]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
debug msg="Handle update check state" func="github.com/mendersoftware/mender/app.(*updateCheckState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:662"
debug msg="Returning artifact name from /etc/mender/artifact_info file." func="github.com/mendersoftware/mender/device.(*DeviceManager).GetCurrentArtifactName" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:134"
debug msg="Reading data from the device manifest file: /etc/mender/artifact_info" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:80"
debug msg="artifact_name=release-2020-09-22" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:91"
debug msg="Current manifest data: release-2020-09-22" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:98"
debug msg="Reading data from the device manifest file: /var/lib/mender/device_type" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:80"
debug msg="device_type=octave-imx8mnevk" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:91"
debug msg="Current manifest data: octave-imx8mnevk" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:98"
debug msg="device provides not accepted by the server. Response code: 405" func="github.com/mendersoftware/mender/client.(*UpdateClient).getUpdateInfo" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_update.go:103"
debug msg="Received response:200 OK" func=github.com/mendersoftware/mender/client.processUpdateResponse file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_update.go:183"
debug msg="Have update available" func=github.com/mendersoftware/mender/client.processUpdateResponse file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_update.go:192"
info msg="Correct request for getting image from: https://rufilla.octopus.mender.com:9000/mender-artifact-storage/7363f185-979d-4915-94a8-92cd68c1760d?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=mender-deployments%2F20201026%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20201026T105902Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=4964c0fe6fb9a8a43d4b81b2f45d4228088a7d2c7528b32e1117eb3579ca4269 [name: release-2020-10-21; devices: [octave-imx8mnevk]]" func=github.com/mendersoftware/mender/client.validateGetUpdate file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_update.go:175"
info msg="Correct request for getting image from: https://rufilla.octopus.mender.com:9000/mender-artifact-storage/7363f185-979d-4915-94a8-92cd68c1760d?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=mender-deployments%2F20201026%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20201026T105902Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=4964c0fe6fb9a8a43d4b81b2f45d4228088a7d2c7528b32e1117eb3579ca4269 [name: release-2020-10-21; devices: [octave-imx8mnevk]]" func=github.com/mendersoftware/mender/client.validateGetUpdate file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_update.go:175"
debug msg="Received update response: {{{https://rufilla.octopus.mender.com:9000/mender-artifact-storage/7363f185-979d-4915-94a8-92cd68c1760d?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=mender-deployments%2F20201026%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20201026T105902Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&response-content-type=application%2Fvnd.mender-artifact&X-Amz-Signature=4964c0fe6fb9a8a43d4b81b2f45d4228088a7d2c7528b32e1117eb3579ca4269 2020-10-26T10:59:02.337574221Z} [octave-imx8mnevk] [] release-2020-10-21  map[]} 0c7f0081-6d9f-4d34-891e-86f4791d4951 []  0 false}" func="github.com/mendersoftware/mender/app.(*Mender).CheckUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:391"
info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: update-check [Sync] -> update-fetch [Download_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
info msg="Running Mender client version: 2.4.0" func="github.com/mendersoftware/mender/app.(*DeploymentLogManager).Enable" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/deployment_logger.go:143"
info msg="Running Mender client version: 2.4.0" func="github.com/mendersoftware/mender/app.(*DeploymentLogManager).Enable" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/deployment_logger.go:143"
debug msg="Handling update fetch state" func="github.com/mendersoftware/mender/app.(*updateFetchState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:704"
debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_status.go:90"
debug msg="Received fetch update response &{200 OK 200 HTTP/1.1 1 1 map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[40432640] Content-Security-Policy:[block-all-mixed-content] Content-Type:[application/vnd.mender-artifact] Date:[Mon, 26 Oct 2020 10:59:02 GMT] Etag:[\"398b270cff57f927bd2df8e152155d30-4\"] Expires:[Thu, 22 Oct 2020 12:58:36 GMT] Last-Modified:[Thu, 22 Oct 2020 12:49:16 GMT] Server:[openresty/1.13.6.2] Strict-Transport-Security:[max-age=63072000; includeSubdomains; preload] Vary:[Origin] X-Amz-Request-Id:[164185B21EF62B37] X-Content-Type-Options:[nosniff] X-Frame-Options:[DENY] X-Xss-Protection:[1; mode=block]] 0x40002e8fc0 40432640 [] false false map[] 0x4000292a00 <nil>}+" func="github.com/mendersoftware/mender/client.(*UpdateClient).FetchUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_update.go:146"
info msg="State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: update-fetch [Download_Enter] -> update-store [Download_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
debug msg="Handling update install state" func="github.com/mendersoftware/mender/app.(*updateStoreState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:777"
debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_status.go:90"
debug msg="Reading data from the device manifest file: /var/lib/mender/device_type" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:80"
debug msg="device_type=octave-imx8mnevk" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:91"
debug msg="Current manifest data: octave-imx8mnevk" func=github.com/mendersoftware/mender/device.GetManifestData file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/device/device.go:98"
info msg="No public key was provided for authenticating the artifact" func=github.com/mendersoftware/mender/installer.ReadHeaders file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/installer.go:109"
info msg="No public key was provided for authenticating the artifact" func=github.com/mendersoftware/mender/installer.ReadHeaders file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/installer.go:109"
info msg="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" func="github.com/mendersoftware/mender/installer.(*ModuleInstallerFactory).GetModuleTypes" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/modules.go:914"
info msg="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" func="github.com/mendersoftware/mender/installer.(*ModuleInstallerFactory).GetModuleTypes" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/modules.go:914"
debug msg="Checking if device [octave-imx8mnevk] is on compatible device list: [octave-imx8mnevk]\n" func=github.com/mendersoftware/mender/installer.ReadHeaders.func1 file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/installer.go:120"
debug msg="Installer: Successfully read artifact [name: release-2020-10-21; version: 3; compatible devices: [octave-imx8mnevk]]" func=github.com/mendersoftware/mender/installer.ReadHeaders file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/installer.go:196"
debug msg="Active partition: /dev/mmcblk2p1" func="github.com/mendersoftware/mender/installer.(*partitions).GetActive" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/partitions.go:55"
debug msg="Detected inactive partition /dev/mmcblk2p2, based on active partition /dev/mmcblk2p1" func="github.com/mendersoftware/mender/installer.(*partitions).getAndCacheInactivePartition" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/partitions.go:82"
info msg="Opening device \"/dev/mmcblk2p2\" for writing" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:66"
info msg="Opening device \"/dev/mmcblk2p2\" for writing" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:66"
debug msg="Installing update of size: 5712642048" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:71"
debug msg="Device: /dev/mmcblk2p2 is a ubi device: false" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:94"
info msg="Native sector size of block device /dev/mmcblk2p2 is 512 bytes. Mender will write in chunks of 1048576 bytes" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:146"
info msg="Native sector size of block device /dev/mmcblk2p2 is 512 bytes. Mender will write in chunks of 1048576 bytes" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:146"
debug msg="Opening device: /dev/mmcblk2p2 for writing with flag: 2" func=github.com/mendersoftware/mender/installer.bdevice.Open file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:152"
info msg="All bytes were successfully written to the new partition" func="github.com/mendersoftware/mender/utils.(*LimitedWriteCloser).Close" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/utils/limited_writer.go:57"
info msg="All bytes were successfully written to the new partition" func="github.com/mendersoftware/mender/utils.(*LimitedWriteCloser).Close" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/utils/limited_writer.go:57"
info msg="The optimized block-device writer wrote a total of 5449 frames, where 0 frames did need to be rewritten (i.e., skipped)" func="github.com/mendersoftware/mender/installer.(*OptimizedBlockDeviceWriter).Close" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:395"
info msg="The optimized block-device writer wrote a total of 5449 frames, where 0 frames did need to be rewritten (i.e., skipped)" func="github.com/mendersoftware/mender/installer.(*OptimizedBlockDeviceWriter).Close" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/block_device.go:395"
info msg="Wrote 5712642048/5712642048 bytes to the inactive partition" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).StoreUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:181"
info msg="Wrote 5712642048/5712642048 bytes to the inactive partition" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).StoreUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:181"
debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_status.go:90"
info msg="State transition: update-store [Download_Enter] -> update-after-store [Download_Leave]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: update-store [Download_Enter] -> update-after-store [Download_Leave]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: update-after-store [Download_Leave] -> update-install [ArtifactInstall]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
info msg="State transition: update-after-store [Download_Leave] -> update-install [ArtifactInstall]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_status.go:90"
debug msg="Inactive partition: /dev/mmcblk2p2" func="github.com/mendersoftware/mender/installer.(*partitions).GetInactive" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/partitions.go:47"
debug msg="Marking inactive partition (/dev/mmcblk2p2) as the new boot candidate." func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).getInactivePartition" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:196"
info msg="Enabling partition with new image installed to be a boot candidate: 2" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).InstallUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:216"
info msg="Enabling partition with new image installed to be a boot candidate: 2" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).InstallUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:216"
debug msg="Have U-Boot variable: mender_check_saveenv_canary=1" func=github.com/mendersoftware/mender/installer.getEnvironmentVariable file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/bootenv.go:153"
debug msg="List of U-Boot variables:map[mender_check_saveenv_canary:1]" func=github.com/mendersoftware/mender/installer.getEnvironmentVariable file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/bootenv.go:176"
debug msg="Have U-Boot variable: mender_saveenv_canary=1" func=github.com/mendersoftware/mender/installer.getEnvironmentVariable file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/bootenv.go:153"
debug msg="List of U-Boot variables:map[mender_saveenv_canary:1]" func=github.com/mendersoftware/mender/installer.getEnvironmentVariable file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/bootenv.go:176"
debug msg="Marking inactive partition as a boot candidate successful." func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).InstallUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:223"
info msg="State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
[info msg="State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
debug msg="Handling reboot state" func="github.com/mendersoftware/mender/app.(*updateRebootState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1544"
debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_status.go:90"
info msg="Rebooting device(s)" func="github.com/mendersoftware/mender/app.(*updateRebootState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1551"
info msg="Rebooting device(s)" func="github.com/mendersoftware/mender/app.(*updateRebootState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1551"
info msg="Mender rebooting from active partition: /dev/mmcblk2p1" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Reboot" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:111"
info msg="Mender rebooting from active partition: /dev/mmcblk2p1" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Reboot" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:111"
Oct 26 11:00:23 octave-imx8mnevk systemd[1]: Stopped target Multi-User System.
  OK  ] Stopped target Multi-User System.
12

Here is an excerpt from the full log with timestamp information

Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=debug msg="Marking inactive partition as a boot candidate successful." func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).InstallUpdate" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:223"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=info msg="State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
[Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=info msg="State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter]" func=github.com/mendersoftware/mender/app.transitionState file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/mender.go:591"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" 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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" 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="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/statescript/executor.go:82"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=debug msg="Handling reboot state" func="github.com/mendersoftware/mender/app.(*updateRebootState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1544"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=debug msg="Status reported, response 204 No Content" func="github.com/mendersoftware/mender/client.(*StatusClient).Report" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/client/client_status.go:90"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=info msg="Rebooting device(s)" func="github.com/mendersoftware/mender/app.(*updateRebootState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1551"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=info msg="Rebooting device(s)" func="github.com/mendersoftware/mender/app.(*updateRebootState).Handle" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/app/state.go:1551"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=info msg="Mender rebooting from active partition: /dev/mmcblk2p1" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Reboot" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:111"
Oct 26 11:00:23 octave-imx8mnevk mender[369]: time="2020-10-26T11:00:23Z" level=info msg="Mender rebooting from active partition: /dev/mmcblk2p1" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).Reboot" file="/ws/rufilla/octopus/yocto/build-release/tmp/work/aarch64-poky-linux/mender-client/2.4.0-r0/build/src/github.com/mendersoftware/mender/installer/dual_rootfs_device.go:111"
Oct 26 11:00:23 octave-imx8mnevk systemd[1]: Stopped target Multi-User System.
  OK  ] Stopped target Multi-User System.

Notice that the opening square bracket for the systemd shutdown message "Stopped target Multi-User System. appears earlier ("State transition: update-install [ArtifactInstall] -> reboot [ArtifactReboot_Enter) so it looks like the system is rebooting while the mender-client is still running. As this is a quad core processor running at 1.4GHz could I be hitting some sort of race condition when an update is finished and a reboot it kicked off but the reboot occurs too quickly and the u-boot environment hasn’t been updated?

13

What does your ArtifactReboot_Enter state script look like?
Drew

14

I don’t have any state scripts, do I need too add them? I see there is a page on adding state scripts to an image:

15

No you don’t need them. I just wanted to make sure they were not doing the reboot.

Is there anything else in your system that may be triggering this reboot? Mender will automatically reboot at the right time and if something else reboots, then you will have this kind of issue.

16

This is a very basic root filesystem image with no application code as of yet so nothing else should be rebooting the system.

I’ve been reading through the mender-client code and it looks like it goes through the InstallUpdate() -> WriteEnvs() code path by the message

Enabling partition with new image installed to be a boot candidate: 2" func="github.com/mendersoftware/mender/installer.(*dualRootfsDeviceImpl).InstallUpdate"

I see WriteEnv using

fw_setenv -s -

and then uses pipes to set the U-Boot variables. I wonder if this works with the busybox shell? Is there a command line I could run to check this, I tried

root@octave-imx8mnevk:~# fw_setenv -s - <(echo "test=test")
-sh: syntax error: unexpected "("
root@octave-imx8mnevk:~# fw_setenv -s - <<< $(echo "test=test")
-sh: syntax error: unexpected redirection
17

Do the following command work?

echo “test=test” | fw_setenv -s

18

I tried adding bash to the root filesystem but the problem still persists. I tried that command but no joy:

root@octave-imx8mnevk:~# echo | fw_setenv -s
fw_setenv: option requires an argument -- 's'
root@octave-imx8mnevk:~# echo | fw_setenv -s -
root@octave-imx8mnevk:~# fw_printenv | grep ^test
19

BTW it looks like I’m using libubootenv for fw_setenv in case this makes a difference

20

I couldn’t get fw_setenv to work using stdin

echo test1=test1 > /var/run/test
root@octave-imx8mnevk:~# fw_setenv -s - < /var/run/test 
root@octave-imx8mnevk:~# fw_printenv | grep test1
root@octave-imx8mnevk:~# 
root@octave-imx8mnevk:~# fw_setenv -s /var/run/test
root@octave-imx8mnevk:~# fw_printenv | grep test1
test1=test1

I looked through the libubootenv code and can’t see how it processes - for stdin, in the u-boot version you can see

	if (strcmp(fname, "-") == 0)
		fp = stdin;

But I don’t see anything for libubootenv, if you run

fw_setenv -s -

it just returns, in fact if you specify a non existent file it returns

root@octave-imx8mnevk:~# fw_setenv -s /doesnt/exist
root@octave-imx8mnevk:~# echo $?
0

I’m using v0.2 of libubootenv, do I need a different version?