Adaptive update evaluation (via QEMUx86-64)

[jungte]

I encountered an issue when I install qemu-demo-bundle-qemux86-64.raucb
(w/RAUC_SLOT_rootfs[adaptive] = "block-hash-index")

Any suggestion? Thanks!

root@qemux86-64:/data# rauc install qemu-demo-bundle-qemux86-64.raucb
installing
0% Installing
0% Determining slot states
20% Determining slot states done.
20% Checking bundle
20% Verifying signature
40% Verifying signature done.
40% Checking bundle done.
40% Checking manifest contents
60% Checking manifest contents done.
60% Determining target install group
80% Determining target install group done.
80% Updating slots
80% Checking slot efi.0
85% Checking slot efi.0 done.
85% Copying image to efi.0
90% Copying image to efi.0 done.
90% Checking slot rootfs.1
95% Checking slot rootfs.1 done.
95% Copying image to rootfs.1
[ 183.464339] traps: installer[279] trap int3 ip:7f8cc750e73a sp:7f8cc616d8e0 error:0 in libglib-2.0.so.0.7200.3[7f8cc74d0000+8c000] RAUC service disappeared
D-Bus error while installing '/data/qemu-demo-bundle-qemux86-64.raucb\'

root@qemux86-64:/data# rauc info qemu-demo-bundle-qemux86-64.raucb
rauc-Message: 07:42:52.557: Using central status file /data/central.raucs
rauc-Message: 07:42:52.569: valid /etc/rauc/system.conf found, using it
rauc-Message: 07:42:52.580: Reading bundle: /data/qemu-demo-bundle-qemux86-64.raucb
rauc-Message: 07:42:52.665: Verifying bundle signature...
rauc-Message: 07:42:52.722: Verified inline signature by 'O = Test Org, CN = Test Org Development-1'
Compatible: 'qemu86-64 demo platform'
Version: '1.0'
Description: 'qemu-demo-bundle version 1.0-r0'
Build: '20221025045346'
Hooks: ''
Bundle Format: verity
Verity Salt: 'fdb4b0259a2d0e51051dfbfd2b16ae2d1d54fb757b0835c8e3aa7ab37305213e'
Verity Hash: '08fe228e55dc76c7545b79a31039d897896512bf76742faea166b0ff5dba8fea'
Verity Size: 389120

2 Images:
[efi]
Filename: efi-boot.vfat
Checksum: c2e30acd778e466139243389b6f5497b5d5a946504fcbd2d89a1f4229d054c43
Size: 33572864
Hooks:
[rootfs]
Filename: core-image-minimal-qemux86-64.ext4
Checksum: 2aee25f486b58e6976aeb3d8fb15ef62c30e084492405722a6deff43402e729b
Size: 186052608
Hooks:
Adaptive: block-hash-index

Certificate Chain:
.
.
.

[jluebbe]

Could you run the rauc service with -d and post the resulting logs?

[jungte]

Sure, here you go.

root@qemux86-64:/data# journalctl -u rauc
Oct 25 08:10:58 qemux86-64 systemd[1]: Starting RAUC Update Service...
Oct 25 08:10:59 qemux86-64 rauc[253]: Debug log domains: 'rauc'
Oct 25 08:10:59 qemux86-64 rauc[253]: No value for key "max-bundle-download-size" in [system] defined - using default value of 8388608 bytes.
Oct 25 08:10:59 qemux86-64 rauc[253]: No mount prefix provided, using /mnt/rauc/ as default
Oct 25 08:10:59 qemux86-64 rauc[253]: Using central status file /data/central.raucs
Oct 25 08:10:59 qemux86-64 rauc[253]: service start
Oct 25 08:10:59 qemux86-64 rauc[253]: No value for key "max-bundle-download-size" in [system] defined - using default value of 8388608 bytes.
Oct 25 08:10:59 qemux86-64 rauc[253]: No mount prefix provided, using /mnt/rauc/ as default
Oct 25 08:10:59 qemux86-64 rauc[253]: Using central status file /data/central.raucs
Oct 25 08:10:59 qemux86-64 systemd[1]: Started RAUC Update Service.
Oct 25 08:10:59 qemux86-64 rauc[253]: name 'de.pengutronix.rauc' acquired
Oct 25 08:11:00 qemux86-64 rauc[253]: Failed getting primary slot: grub backend: No bootable slot found in ORDER 'A B'
Oct 25 08:11:00 qemux86-64 rauc[253]: Found external mountpoint for slot rootfs.0 at /
Oct 25 08:11:00 qemux86-64 rauc[253]: Found external mountpoint for slot rescue.0 at /rescue
Oct 25 08:11:00 qemux86-64 rauc[253]: Found booted slot: rootfs.0 on /dev/sda4
Oct 25 08:11:01 qemux86-64 rauc[253]: Load status for slot efi.0.
Oct 25 08:11:01 qemux86-64 rauc[253]: Set default status for slot rootfs.1.
Oct 25 08:11:01 qemux86-64 rauc[253]: Set default status for slot rescue.0.
Oct 25 08:11:01 qemux86-64 rauc[253]: Set default status for slot rootfs.0.
Oct 25 08:11:01 qemux86-64 rauc[253]: removing obsolete slot data dir '/data/slot.rootfs.1/hash-unknown'
Oct 25 08:11:01 qemux86-64 rauc[253]: removing obsolete slot data dir '/data/slot.rootfs.0/hash-unknown'
Oct 25 08:11:01 qemux86-64 rauc[253]: Found external mountpoint for slot rootfs.0 at /
Oct 25 08:11:01 qemux86-64 rauc[253]: Found external mountpoint for slot rescue.0 at /rescue
Oct 25 08:11:01 qemux86-64 rauc[253]: Found booted slot: rootfs.0 on /dev/sda4
Oct 25 08:11:01 qemux86-64 rauc[253]: rauc mark: marked slot rootfs.0 as good
Oct 25 08:11:24 qemux86-64 rauc[253]: input bundle: /data/qemu-demo-bundle-qemux86-64.raucb
Oct 25 08:11:24 qemux86-64 rauc[253]: Active slot bootname: A
Oct 25 08:11:24 qemux86-64 rauc[253]: thread started for /data/qemu-demo-bundle-qemux86-64.raucb
Oct 25 08:11:24 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: started
Oct 25 08:11:24 qemux86-64 rauc[253]: Found external mountpoint for slot rootfs.0 at /
Oct 25 08:11:24 qemux86-64 rauc[253]: Found external mountpoint for slot rescue.0 at /rescue
Oct 25 08:11:24 qemux86-64 rauc[253]: Found booted slot: rootfs.0 on /dev/sda4
Oct 25 08:11:24 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Checking and mounting bundle...
Oct 25 08:11:24 qemux86-64 rauc[253]: Reading bundle: /data/qemu-demo-bundle-qemux86-64.raucb
Oct 25 08:11:24 qemux86-64 rauc[253]: Found valid CMS data
Oct 25 08:11:24 qemux86-64 rauc[253]: Verifying bundle signature...
Oct 25 08:11:24 qemux86-64 rauc[253]: Verified inline signature by 'O = Test Org, CN = Test Org Development-1'
Oct 25 08:11:24 qemux86-64 rauc[253]: Got 2 elements for trust chain
Oct 25 08:11:24 qemux86-64 rauc[253]: Mounting bundle '/data/qemu-demo-bundle-qemux86-64.raucb' to '/run/rauc/bundle'
Oct 25 08:11:24 qemux86-64 rauc[253]: Configured loop device '/dev/loop0' for 49561600 bytes
Oct 25 08:11:24 qemux86-64 rauc[253]: Configured dm-verity device '/dev/dm-0'
Oct 25 08:11:24 qemux86-64 rauc[253]: Checking slot: rootfs.1
Oct 25 08:11:24 qemux86-64 rauc[253]:         Adding mapping: rootfs -> rootfs.1
Oct 25 08:11:24 qemux86-64 rauc[253]: Checking slot: efi.0
Oct 25 08:11:24 qemux86-64 rauc[253]:         Adding mapping: efi -> efi.0
Oct 25 08:11:24 qemux86-64 rauc[253]: Checking slot: rescue.0
Oct 25 08:11:24 qemux86-64 rauc[253]:         Adding mapping: rescue -> rescue.0
Oct 25 08:11:24 qemux86-64 rauc[253]: Checking slot: rootfs.0
Oct 25 08:11:24 qemux86-64 rauc[253]:         No mapping found
Oct 25 08:11:24 qemux86-64 rauc[253]: Using default installation handler
Oct 25 08:11:24 qemux86-64 rauc[253]: Found image mapping: efi-boot.vfat -> efi
Oct 25 08:11:24 qemux86-64 rauc[253]: Found image mapping: core-image-minimal-qemux86-64.ext4 -> rootfs
Oct 25 08:11:24 qemux86-64 rauc[253]: Marking target slot rootfs.1 as non-bootable...
Oct 25 08:11:24 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Updating slots...
Oct 25 08:11:24 qemux86-64 rauc[253]: Checking image type for slot type: boot-gpt-switch
Oct 25 08:11:24 qemux86-64 rauc[253]: Image detected as type: *.vfat
Oct 25 08:11:24 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Checking slot efi.0
Oct 25 08:11:24 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Updating slot efi.0
Oct 25 08:11:24 qemux86-64 rauc[253]: Updating /dev/sda with /run/rauc/bundle/efi-boot.vfat
Oct 25 08:11:24 qemux86-64 rauc[253]: Found inactive (second) half of boot partition region (pos. 56623104B, size 52428800B)
Oct 25 08:11:24 qemux86-64 rauc[253]: Clearing inactive (second) half of boot partition region on /dev/sda
Oct 25 08:12:03 qemux86-64 rauc[253]: Write image to inactive (second) half of boot partition region on /dev/sda
Oct 25 08:12:06 qemux86-64 rauc[253]: Setting second half of boot partition region active in GPT
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: No errors detected.
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: Header version: 1.0
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: Using 6 out of 128 partitions.
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: A total of 125637 free sectors is available in 6 segments (the largest is 52 MiB).
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: No errors detected.
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: Header version: 1.0
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: Using 6 out of 128 partitions.
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: A total of 125637 free sectors is available in 6 segments (the largest is 54 MiB).
Oct 25 08:12:07 qemux86-64 rauc[253]: libfdisk: Syncing disks.
Oct 25 08:12:07 qemux86-64 rauc[253]: Saving global slot status
Oct 25 08:12:07 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Updating slot efi.0 status
Oct 25 08:12:07 qemux86-64 rauc[253]: Checking image type for slot type: ext4
Oct 25 08:12:07 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Updating slot efi.0 done
Oct 25 08:12:07 qemux86-64 rauc[253]: Image detected as type: *.ext4
Oct 25 08:12:07 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Checking slot rootfs.1
Oct 25 08:12:07 qemux86-64 rauc[253]: Updating /dev/sda5 with /run/rauc/bundle/core-image-minimal-qemux86-64.ext4
Oct 25 08:12:07 qemux86-64 rauc[253]: installing /data/qemu-demo-bundle-qemux86-64.raucb: Updating slot rootfs.1
Oct 25 08:12:07 qemux86-64 rauc[253]: building new hash index for target_slot with 38400 chunks
Oct 25 08:12:36 qemux86-64 rauc[253]: opened hash index for slot rootfs.1 as target_slot
Oct 25 08:12:36 qemux86-64 rauc[253]: building new hash index for active_slot with 38400 chunks
Oct 25 08:13:04 qemux86-64 rauc[253]: opened hash index for slot rootfs.0 as active_slot
Oct 25 08:13:04 qemux86-64 rauc[253]: using existing hash index for source_image from /run/rauc/bundle/core-image-minimal-qemux86-64.ext4.block-hash-index
Oct 25 08:13:05 qemux86-64 rauc[253]: opened hash index for image /run/rauc/bundle/core-image-minimal-qemux86-64.ext4 with index /run/rauc/bundle/core-image-minimal-qemux86-64.ext4.block-hash-index
Oct 25 08:13:34 qemux86-64 rauc[253]: g_propagate_error: assertion 'src != NULL' failed
Oct 25 08:13:34 qemux86-64 systemd[1]: rauc.service: Main process exited, code=killed, status=5/TRAP
Oct 25 08:13:34 qemux86-64 systemd[1]: rauc.service: Failed with result 'signal'.
root@qemux86-64:/data#

[ejoerns]

Looks like there is an error that is hidden by a bug in error propagation.

Had a short look at the code but could not figure out directly where this happens.

Thus if you have the ability to attach a debugger and dump a trace of where this happens in code, that would be really helpful!

[jungte]

I'm not familiar with gdb, hope this will help:
gdb screenshot

BTW, I can complete install adaptive bundle when I enlarged root_a and root_b partition.
The original partition doesn't have enough space to store gdb and rauc debug symbols, so I add additional 100MB to each of partition A and B and this issue was gone.

For reproduce this issue with gdb hooked I have to reduce available size of partition under around 31MB, FYR.

[ejoerns]

@jungte many thanks for providing the additional information!

You run into error not being set here when returning FALSE:

https://github.com/rauc/rauc/blob/ab94e691745159bf1f3de2c241e04c59f8ba8f0d/src/utils.c#L428

This should be fixed. Would you like to make a PR for this or should I?

[ejoerns]

The detection and handling of too small block device sizes could also be done much earlier I guess since at least in the raw copy cases we could know the size difference between our image and our target device in advance.

[jungte]

@ejoerns I would like to make a PR for this issue and will do it later today. :)