Re: expand-on-first-boot and surprising umounts

[Raphael Lisicki <raphael.lisicki@siemens.com>]

On 21.10.22 11:41, Bezdeka, Florian (T CED SES-DE) wrote:
> On Fri, 2022-10-21 at 11:36 +0200, Raphael Lisicki wrote:
>>
>> On 21.10.22 10:45, Bezdeka, Florian (T CED SES-DE) wrote:
>>> On Fri, 2022-10-21 at 09:48 +0200, Raphael Lisicki wrote:
>>>> Hi everybody,
>>>>
>>>> I am using a debian bullseye based system and use expand-on-first-boot
>>>> to expand the last partition. It is not the root file system but an
>>>> extra ext4 partition to be mounted under /data. The mounting happens
>>>> after expand-on-first boot has succeeded.
>>>>
>>>> Sometimes, on some builds more often than others, /data gets (attempted
>>>> to be) umounted immediately after being mounted and subsequent units
>>>> will fail.
>>>
>>> Hm... Nothing happens on build time. Everything takes place on the
>>> "first" boot (until expand-on-first-boot disables itself). "more often"
>>> is also confusing me because expand-on-first-boot should run exactly
>>> once.
>>
>> Yes, it runs on first boot, but I can use the very same original image
>> multiple times (after restoring it). And I can also try the same with
>> other builds (doing a first boot) and some builds seem to be more often
>> affected than others. My guess from this is that the exact
>> alignment/size/padding/moon phase of some things in the image also plays
>> a role.
>>
>>
>>>
>>>>
>>>> Removing expand-on-first-boot resolves the issue, so does adding
>>>> "ExecStartPost=/usr/bin/udevadm settle" to expand-on-first-boot but I am
>>>> not sure if this is only a sophisticated way of solving a race condition
>>>> with "sleep".
>>>>
>>>> My gut feeling is that after expand-on-first boot finishes, the kernel
>>>> still processes block device events, which systemd gets after /data has
>>>> already been mounted and then cause it to be umounted, as systemd was
>>>> already picky with umounting stuff in the past [1]. Unfortunately I have
>>>> no idea how to test this hypothesis.
>>>
>>> Nothing should be mounted (except the rootfs) until expand-on-first
>>> completed. See below.
>>>
>>>>
>>>> Did anyone already experience something like this? The racy-ness of the
>>>> issue makes creating a minimal reproduction hard.
>>>
>>> Nope, have never seen that, but that doesn't mean that there is no
>>> race.
>>>
>>> We have
>>>
>>> After=systemd-remount-fs.service
>>> Before=local-fs-pre.target shutdown.target
>>> ConditionPathIsReadWrite=/etc
>>>
>>> inside the expand-on-first-boot.service file.
>>>
>>> So we should be done before systemd tries to mount your /data
>>> (according to Before=) and start after systemd did remounting in case
>>> mount options (ro, rw, ...) have to be adjusted.
>>>
>>> I guess you should check your startup order (systemd-analyze might
>>> help) and report back if we missed something.
>>
>> systemd-analyze shows exactly what you described: after
>> expand-on-first-boot has finished, /data gets mounted (and immedeately
>> umounted again).
> 
> OK, so you have to figure out why this happens. Hopefully there are
> some logs available...
Yes, trying to do so, but nothing really helpful to see, if only there 
was a way to check why a unit got disabled.
The most suspicious things I can find - taken from a boot without the 
problem:
Oct 20 11:18:33 localhost systemctl[329]: Removed 
/etc/systemd/system/sysinit.target.wants/expand-on-first-boot.service.
Oct 20 11:18:33 localhost systemd[1]: Reloading.
[...]
Oct 20 11:18:33 localhost systemd[1]: Found device QEMU_HARDDISK data.
Oct 20 11:18:34 localhost systemd[1]: Mounted /data.


Maybe that systemd reloading might have something to do with it. I will 
need to re-check with a log when the error occurred, I only have a log 
at hand where the unloading failed (even weirder behaviour, but I would 
forget about that one for now).

I will repeat it and re-check in the environment where the problem 
happens, when I have access again. Running the same image on another 
system with qemu does not allow the reproduction of the issue (already 
played a little bit with number of cores).



> 
> What file system is on your /data partition? What is the initial size
> and the full-blown size?

I am running in a virtual machine and did not bother to actually 
increase the image. It is an ext4 filesystem blown from 5324812 to a 
whopping 5324813 sectors, and resize2fs does not even do anything about 
it: "The filesystem is already 665601 (4k) blocks long.  Nothing to do!"


best regards
raphael