AUM rollback tests fail on UP Squared 6000 board

added priority:needs triage release:v2021 release:v2022 status:unconfirmed + 1 deleted label

@adalessandro when you have time please have a look at this.

changed the description

added priority:high label and removed priority:needs triage label

Running ostree image from eMMC https://images.apertis.org/daily/v2023pre/20220926.0018/amd64/fixedfunction/apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018.img.gz:

$ cat /etc/os-release 
PRETTY_NAME="Apertis v2023pre"
NAME="Apertis"
VERSION_ID="v2023pre"
VERSION="v2023pre"
VERSION_CODENAME="v2023pre"
ID=apertis
ID_LIKE=debian
HOME_URL="https://apertis.org/"
VARIANT_ID=fixedfunction
BUILD_ID=20220926.0018

I'm getting the following error (logged as user user):

$ common/run-test-in-systemd --timeout=1200 --name=rollback-blacklist env DEBUG=
2 RELEASE=v2023pre ARCH=amd64 BASEURL=https://images.apertis.org IMGPATH=daily/v
2023pre IMGDATE=20220926.0018 IMGTYPE=fixedfunction IMGNAME=apertis_ostree_v2023
pre-fixedfunction-amd64-uefi_20220926.0018 BOARD=uefi ./run-test-rollback-blackl
ist.sh
+ . ./update-manager-common.sh
+ STATUS_UNKNOWN=0
+ STATUS_CHECKING=1
+ STATUS_DOWNLOADING=2
+ STATUS_DEPLOYING=3
+ STATUS_PENDING=100
+ STATUS_UPTODATE=200
+ GETPROP=gdbus call -y -d org.apertis.ApertisUpdateManager -o / -m org.freedesktop.DBus.Properties.Get org.apertis.ApertisUpdateManager
+ ED25519PUBLIC=
+ ED25519SEED=
+ ED25519SECRET=
+ EFIBOOTDIR=/boot/efi/loader/entries
+ update_manager_phases phase_boot phase_check_update phase_check_rollback phase_check_update_is_blacklisted phase_check_rollback
+ set -eux
+ RUNPHASE=/var/run-phase
+ cat /var/run-phase
+ head -1
+ PHASE=1
+ trap error_occured EXIT
+ cd /var
+ shift 1
+ ostree admin status
  apertis ea57f47a660d2e7d0ea62fed6b552384fa4352bbca19b39aa0ec843338939507.0 (pending)
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
* apertis 543f4947186305222a88340c6acb3fd4600f19874414d78ea1319fb880cac07c.0
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
+ echo -=< Current phase: phase_check_update >=-
-=< Current phase: phase_check_update >=-
+ set -x
+ eval phase_check_update
+ phase_check_update
+ ostree admin status
  apertis ea57f47a660d2e7d0ea62fed6b552384fa4352bbca19b39aa0ec843338939507.0 (pending)
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
* apertis 543f4947186305222a88340c6acb3fd4600f19874414d78ea1319fb880cac07c.0
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
+ enable_aum_debug
+ AUMDIR=/etc/systemd/system/apertis-update-manager.service.d
+ mkdir -p /etc/systemd/system/apertis-update-manager.service.d
mkdir: cannot create directory '/etc/systemd/system/apertis-update-manager.service.d': Permission denied
+ error_occured
+ set +x
./run-test-rollback-blacklist.sh: 185: cannot create /var/run-phase: Permission denied
Job for generated-test-case-rollback-blacklist.service failed because the control process exited with error code.
See "systemctl --user status generated-test-case-rollback-blacklist.service" and "journalctl --user -xe" for details.
Command exited with non-zero status 1
real	0m 0.04s
user	0m 0.00s
sys	0m 0.00s
NOTE: Run command with the --debug or --full-debug option to enable journal logs
$

So it seems a permissions issue, as the folder are root owned:

$ ls -alF /etc/systemd/system/
total 40
drwxr-xr-x 9 root root 4096 Sep 26 01:43 ./
drwxr-xr-x 5 root root 4096 Sep 26 01:43 ../
lrwxrwxrwx 1 root root   42 Sep 26 01:43 dbus-fi.w1.wpa_supplicant1.service@ -> /lib/systemd/system/wpa_supplicant.service
drwxr-xr-x 2 root root 4096 Sep 26 01:43 default.target.wants/
drwxr-xr-x 2 root root 4096 Sep 26 01:43 getty.target.wants/
drwxr-xr-x 2 root root 4096 Sep 26 01:43 graphical.target.wants/
drwxr-xr-x 2 root root 4096 Sep 26 01:43 local-fs.target.wants/
drwxr-xr-x 2 root root 4096 Sep 26 01:43 multi-user.target.wants/
drwxr-xr-x 2 root root 4096 Sep 26 01:43 network-online.target.wants/
lrwxrwxrwx 1 root root   31 Sep 26 01:43 sshd.service@ -> /lib/systemd/system/ssh.service
drwxr-xr-x 2 root root 4096 Sep 26 01:43 sysinit.target.wants/
lrwxrwxrwx 1 root root    9 Sep 26 01:43 systemd-backlight@leds:asus::kbd_backlight.service@ -> /dev/null
-rw-r--r-- 1 root root  837 Sep 26 01:43 tmp.mount

@wlozano Do you if this has been recently modified? Otherwise, it looks like it should have been broken for a long time, or we were running tests as root?

And running the same issue as root succeeds:

/home/user/aum-offline-upgrade # common/run-test-in-systemd --timeout=1200 --nam
e=rollback-blacklist env DEBUG=2 RELEASE=v2023pre ARCH=amd64 BASEURL=https://ima
ges.apertis.org IMGPATH=daily/v2023pre IMGDATE=20220926.0018 IMGTYPE=fixedfuncti
on IMGNAME=apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018 BOARD=
uefi ./run-test-rollback-blacklist.sh
+ . ./update-manager-common.sh
+ STATUS_UNKNOWN=0
+ STATUS_CHECKING=1
+ STATUS_DOWNLOADING=2
+ STATUS_DEPLOYING=3
+ STATUS_PENDING=100
+ STATUS_UPTODATE=200
+ GETPROP=gdbus call -y -d org.apertis.ApertisUpdateManager -o / -m org.freedesktop.DBus.Properties.Get org.apertis.ApertisUpdateManager
+ ED25519PUBLIC=
+ ED25519SEED=
+ ED25519SECRET=
+ EFIBOOTDIR=/boot/efi/loader/entries
+ update_manager_phases phase_boot phase_check_update phase_check_rollback phase_check_update_is_blacklisted phase_check_rollback
+ set -eux
+ RUNPHASE=/var/run-phase
+ cat /var/run-phase
+ head -1
cat: /var/run-phase: No such file or directory (os error 2)
+ PHASE=
+ PHASE=0
+ trap error_occured EXIT
+ cd /var
+ shift 0
+ ostree admin status
* apertis 543f4947186305222a88340c6acb3fd4600f19874414d78ea1319fb880cac07c.0
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
+ echo -=< Current phase: phase_boot >=-
-=< Current phase: phase_boot >=-
+ set -x
+ eval phase_boot
+ phase_boot
+ get_static_delta _rollback tests
+ local DELTAURL=
+ local DELTAFILE=
+ local SUFFIX=_rollback
+ local SUBDIR=
+ local ENCRYPTED=
+ [ 2 -gt 1 ]
+ SUBDIR=tests/
+ [ 2 -gt 2 ]
+ DELTAURL=https://images.apertis.org/daily/v2023pre/20220926.0018
+ DELTAFILE=apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ DELTAURL=https://images.apertis.org/daily/v2023pre/20220926.0018/amd64/fixedfunction/tests/apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ [ ! -f apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta ]
+ busybox wget -q https://images.apertis.org/daily/v2023pre/20220926.0018/amd64/fixedfunction/tests/apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ echo apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ local DELTAFILE=apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ branch_name
+ [ uefi = rpi64 ]
+ echo apertis/v2023pre/amd64-uefi/fixedfunction
+ local BRANCHNAME=apertis/v2023pre/amd64-uefi/fixedfunction
+ ostree rev-parse origin:apertis/v2023pre/amd64-uefi/fixedfunction
+ local CURREV=543f4947186305222a88340c6acb3fd4600f19874414d78ea1319fb880cac07c
+ apply_update_sync -d apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ local RESULT=1
+ local DELTAFILE=
+ local OTA=
+ local CHECK=
+ journalctl --show-cursor -n 0 -o cat
+ local CURSOR=-- cursor: s=42338a01b1b14de48711f3c8de0906b1;i=59a;b=52446242472340539482a071360826f4;m=9fb91b9;t=5e9ae13226b37;x=da0a78deaadf739
+ CURSOR=s=42338a01b1b14de48711f3c8de0906b1;i=59a;b=52446242472340539482a071360826f4;m=9fb91b9;t=5e9ae13226b37;x=da0a78deaadf739
+ getopt -o cod: -l check,ota,delta: -- -d apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ local OPTS= -d 'apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta' --
+ [ 2 -eq 0 ]
+ [ 2 -gt 0 ]
+ DELTAFILE=apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ shift 2
+ break
+ JOURNALPID=772
+ systemctl restart apertis-update-manager
+ journalctl --after-cursor s=42338a01b1b14de48711f3c8de0906b1;i=59a;b=52446242472340539482a071360826f4;m=9fb91b9;t=5e9ae13226b37;x=da0a78deaadf739 --unit apertis-update-manager -ef
-- Journal begins at Tue 2022-09-27 19:56:13 UTC. --
+ UPGRADEHANDLERPID=778
+ journalctl --show-cursor -n 0 -o cat
+ nohup updatectl --register-upgrade-handler
+ CURSOR=-- cursor: s=42338a01b1b14de48711f3c8de0906b1;i=5bd;b=52446242472340539482a071360826f4;m=9fc9f83;t=5e9ae13237900;x=47ede2b7280c9c3b
+ CURSOR=s=42338a01b1b14de48711f3c8de0906b1;i=5bd;b=52446242472340539482a071360826f4;m=9fc9f83;t=5e9ae13237900;x=47ede2b7280c9c3b
+ [ -n  ]
+ [ -n apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta ]
+ apply_update_async apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ [ 1 -eq 0 ]
+ echo Applying static delta: apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
Applying static delta: apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
+ updatectl --apply-static-delta apertis_ostree_v2023pre-fixedfunction-amd64-uefi_20220926.0018_rollback.delta
AUM-Message: 19:58:58.231: Network connected: Yes
AUM-Message: 19:58:58.235: Network connected: Yes
AUM-Message: 19:58:58.236: Upgrade status: Checking
+ seq 0 99
+ sleep 5
AUM-Message: 19:58:58.252: Upgrade status: Deploying
Sep 27 19:58:58 apertis systemd[1]: Stopping Apertis update manager...
Sep 27 19:58:58 apertis systemd[1]: apertis-update-manager.service: Succeeded.
Sep 27 19:58:58 apertis systemd[1]: Stopped Apertis update manager.
Sep 27 19:58:58 apertis systemd[1]: Starting Apertis update manager...
Sep 27 19:58:58 apertis apertis-update-[774]: Auto update status: disabled
Sep 27 19:58:58 apertis systemd[1]: Started Apertis update manager.
Sep 27 19:58:58 apertis apertis-update-[774]: aum_boot_state_uboot_ext_read: Failed to open file “/boot/uboot.cnt”: No such file or directory
Sep 27 19:58:58 apertis apertis-update-[774]: Cannot initialize boot-state from U-Boot ext environment
Sep 27 19:58:58 apertis apertis-update-[774]: Wrong checksum: 0x0
Sep 27 19:58:58 apertis apertis-update-[774]: aum_boot_state_uboot_env_read: unknown error
Sep 27 19:58:58 apertis apertis-update-[774]: Cannot initialize boot-state from U-Boot environment
Sep 27 19:58:58 apertis apertis-update-[774]: Cannot initialize boot-state from file: No such file or directory
Sep 27 19:58:58 apertis apertis-update-[774]: Loaded boot count from conf file: count 0
Sep 27 19:58:58 apertis apertis-update-[774]: Using EFI based boot backend
Sep 27 19:58:58 apertis apertis-update-[774]: Network status: online
Sep 27 19:58:58 apertis apertis-update-[774]: Ostree static delta starting
Sep 27 19:58:58 apertis apertis-update-[774]: Metadata read from commit 'ea57f47a660d2e7d0ea62fed6b552384fa4352bbca19b39aa0ec843338939507': {'ostree.collection-binding': <'org.apertis.os'>, 'ostree.ref-binding': <['apertis/v2023pre/amd64-uefi/fixedfunction', 'apertis/v2023pre/amd64-uefi/fixedfunction-rollback']>}
Sep 27 19:58:58 apertis apertis-update-[774]: Cannot check the ID in black list: No such file or directory
Sep 27 19:58:58 apertis apertis-update-[774]: Static delta is applicable for the system
Sep 27 19:59:00 apertis apertis-update-managerd[774]: Copying /etc changes: 11 modified, 1 removed, 1 added
Sep 27 19:59:00 apertis apertis-update-managerd[774]: Transaction complete; bootconfig swap: yes; deployment count change: 1
AUM-Message: 19:59:01.373: An upgrade is pending
Sep 27 19:59:01 apertis apertis-update-[774]: Ostree upgrade ready, system should be rebooted
Sep 27 19:59:01 apertis apertis-update-[774]: Upgrade handlers registered or the system is being reset, not rebooting
+ journalctl --after-cursor s=42338a01b1b14de48711f3c8de0906b1;i=5bd;b=52446242472340539482a071360826f4;m=9fc9f83;t=5e9ae13237900;x=47ede2b7280c9c3b --unit apertis-update-manager
+ grep -qE Ostree already up to date
+ journalctl --after-cursor s=42338a01b1b14de48711f3c8de0906b1;i=5bd;b=52446242472340539482a071360826f4;m=9fc9f83;t=5e9ae13237900;x=47ede2b7280c9c3b --unit apertis-update-manager
+ grep -qE Ostree upgrade failed
+ journalctl --after-cursor s=42338a01b1b14de48711f3c8de0906b1;i=5bd;b=52446242472340539482a071360826f4;m=9fc9f83;t=5e9ae13237900;x=47ede2b7280c9c3b --unit apertis-update-manager
+ grep -qE Starting Apertis update manager
+ journalctl --after-cursor s=42338a01b1b14de48711f3c8de0906b1;i=5bd;b=52446242472340539482a071360826f4;m=9fc9f83;t=5e9ae13237900;x=47ede2b7280c9c3b --unit apertis-update-manager
+ grep -qE Ostree upgrade ready, system should be rebooted
+ echo ok
ok
+ RESULT=0
+ break
+ kill 778
+ kill 772
+ return 0
+ get_phase_data_path
+ echo /var/run-phase-data
+ echo 543f4947186305222a88340c6acb3fd4600f19874414d78ea1319fb880cac07c
+ ostree admin status
  apertis ea57f47a660d2e7d0ea62fed6b552384fa4352bbca19b39aa0ec843338939507.0 (pending)
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
* apertis 543f4947186305222a88340c6acb3fd4600f19874414d78ea1319fb880cac07c.0
    origin refspec: origin:apertis/v2023pre/amd64-uefi/fixedfunction
+ check_bootcounter   00 01
+ [ -f /boot/uboot.cnt ]
+ [ -f /boot/efi/loader/entries/ostree-0-2+3.conf ]
+ m=
+ ver=00
+ ls /boot/efi/loader/entries/ostree-0-2+3.conf
+ cut -d + -f 2 -s
+ cut -d . -f 1 -s
+ local suffix=3
+ [ -z 3 ]
+ uflag=01
+ echo 3
+ cut -d - -f 2 -s
+ cnt=
+ [ -z  ]
+ cnt=00
+ local ret=0
+ local magic=
+ local version=00
+ local bootcount=00
+ local upgrade=01
+ test  = 
+ test 00 -eq 00
+ test 00 -eq 00
+ test 01 -eq 01
+ echo Expected bootcounter: , 00, 00, 01
Expected bootcounter: , 00, 00, 01
+ echo     Read bootcounter: , 00, 00, 01
    Read bootcounter: , 00, 00, 01
+ return 0
+ set +x
finished
real	0m 7.02s
user	0m 0.00s
sys	0m 0.00s

@wlozano Do you if this has been recently modified? Otherwise, it looks like it should have been broken for a long time, or we were running tests as root?

These tests were disabled for long time since there were no enough hardware resources. Also the integration of tests between UEFI and U-Boot boards is not so long in the past.

mentioned in merge request tests/aum-offline-upgrade!42

The following MR has been pushed fixing the test on this amd64 platform, which uses a grub efi system: tests/aum-offline-upgrade!42

Summarizing status/findings:

+cc @wlozano @sjoerd

This MR fixes the rollback test on grub-efi systems.
- There's no issue on the ostree rollback test sequence, but fixes were required on how the bootcount file was processed.
- The above means that no manual reboot nor other steps needed to be added. The LAVA test job definition remains the same
Commit tests/aum-offline-upgrade!42 (c76fd4ec)
- After the rollback, there's no bootcount conf (i.e. no ostree-0-2*.conf). Because of this, test was failing reporting: "No boot counter found".
- This is fixed by detecting the EFI directory first, then considering the above case as default values, i.e. no update is in progress and no bootcount/limit values are set.
Commit tests/aum-offline-upgrade!42 (ae5baaca)
- This is to be discussed, as there's a difference with the u-boot case. The rollback-blacklist test is expecting the update flag to be enabled after a successful update.
- This is currently working fine on u-boot based systems, but not in the grub EFI (blessing) case. After a successful boot, blessing is resetting the alternative boot conf file: ostree-0-2*.conf (i.e. suffix is removed). As the no-suffix filename is considered as a disabled update flag, the checking fails.

The last item should be discussed, to understand first if this is the correct expected behavior on grub/efi systems. If both u-boot and grub AUM behaviors are correct, we need to adapt the test to process each case separately in that phase.

added priority:normal label and removed priority:high label

changed title from OSTree rollback test fails on UP Squared 6000 board to AUM rollback test fails on UP Squared 6000 board

changed title from AUM rollback test fails on UP Squared 6000 board to AUM rollback tests fail on UP Squared 6000 board

This is to be discussed with @sudarshan, changing its state to need info.

added status:needinfo label and removed status:unconfirmed label

assigned to @detlev and unassigned @adalessandro

The following issue has also been observed:

+ grep -qE Starting Apertis update manager
+ echo AUM crashed
AUM crashed
+ RESULT=99
+ break
+ kill 637
+ kill 630
+ return 99
+ ret=99
+ echo Internal bug detected.
Internal bug detected.

As well as this one:

/var/lib/lava-7786113/3/../bin/lava-test-case: 72: cannot create /var/lib/lava-7786113/3/results/5_aum-ota-out-of-space-phase-2-1667189683/results/out-of-space/result: Directory nonexistent
<LAVA_SIGNAL_TESTCASE TEST_CASE_ID=out-of-space RESULT=fail>
NOTE: Run command with the --debug or --full-debug option to enable journal logs
+ set +x
<LAVA_SIGNAL_ENDRUN 5_aum-ota-out-of-space-phase-2 7786113_3.1.3.21>
/var/lib/lava-7786113/3/../bin/lava-test-shell: 12: echo: echo: I/O error
<LAVA_TEST_RUNNER EXIT>

The first one could be related to an issue with the restart of apertis-update-manager in ??? where it would restart too slowly and the journalctl CURSOR value that is retrieved right after could point to the line before the restart actually happens. That would make the script see "Starting Apertis update manager" in the log, making it believe that aum has been restarted automatically after a crash. The log doesn't seem to mention an actual crash.

I did not investigate the second case much, may just be a temporary glitch.

unassigned @detlev

mentioned in merge request tests/apertis-test-cases!509 (merged)

Disable rollback tests in the mean time

tests/apertis-test-cases!509 (diffs)

assigned to @wlozano

changed the description

mentioned in merge request tests/apertis-test-cases!510 (merged)

mentioned in merge request tests/apertis-test-cases!511 (merged)

changed the description

Backports for disabling tests

added priority:low label and removed priority:normal label

Since there is no real pressure to fix this let's lower its priority.

unassigned @wlozano

added area:aum label

mentioned in issue #419

mentioned in issue #477 (closed)

added release:v2023 label and removed 1 deleted label

Type	Arch	v2023pre
minimal/fixedfunction	amd64	*
minimal/fixedfunction	armhf
minimal/fixedfunction	arm64
target/hmi	amd64
target/hmi	armhf
target/hmi	arm64
basesdk	amd64
sdk	amd64
nfs	amd64
nfs	armhf
nfs	arm64
lxc	amd64
lxc	armhf
lxc	arm64
image-builder
package-source-builder

AUM rollback tests fail on UP Squared 6000 board

Affected images versions

Unaffected images versions

Testcase

Steps to reproduce

Expected result

Actual result

Reproducibility

Impact of bug

Attachments

Root cause

Outcomes

Management data

Designs

Child items ...

Activity