Fcos 39 fails booting due journalctl --list-boots never return

Hi,

I updated my raspi fcos and could not login any longer. Raspi sits here indefinately:

I managed to go back to fcos38, add root ssh key and got into fcos39 via ssh as root while it’s in middle of boot process. Turns out the blocking task is in file:
/usr/libexec/coreos-ignition-write-issues the line nreboots=$(($(journalctl --list-boots | wc -l) - 1)). The journalctl never returns, thus this systemd service hangs, and never proceeds to login level.

So there is probably some corrupted journal or smth, which triggers problem here. This task should probably be changed somehow to non-blocking.

UPDATE: Got rid of the problem by vacuuming journals to hold only the last couple of days journalctl --vacuum-time=2d

1 Like

I am not sure if the list of boots is indexed; if it’s not, and finding all boots involves traversing the whole journal, then we should probably drop this by default.

You probably have a combination of slow storage with a large journal. How large is your root disk?

I’m not at the box now to verify, but I recall doing ls|wc -l gve around 70 journal files. And doing the vacuum removed 4GB of storage.

Each entry in the journal has a boot ID attached. Listing of the boot IDs is implemented by opening the journal at the beginning, reading the boot ID of the first entry and writing it down, then seeking to the last entry with this boot ID, advancing to the next entry, writing down the boot ID, and so on until no more entries remain. Boot IDs in a given journal file are indexed. So the operation of seeking to the last entry with a given boot ID in a journal file is generally very quick. But the index is per file: i.e., each journal file needs to be opened and its header read. If case of journal files with multiple boots, there will be some additional reads. So altogether, the operation is O(n + m), where n is the number of journal files and m is the number of boots. Generally, this is all fast enough to not be a problem, but the slowdown could be noticeable with a rotating disk or some other slow medium, and/or very many boots in the log or lots of journal files.

I wouldn’t recommend doing this during each boot…

There should probably be some other mechanism, like some true/false flag if ignition is done. I had this running for long, at least 24h, and it never finished. I still doubt there is some incompatibility between journal formats or smth, which just got it silently stuck.

Anyhow, sounds like overkill to check if ignition is done or not. End result was broken system. Device is raspi4 with usb ssd. So not the fastest, but not slowest either.

Thank you for isolating where boot gets stuck!

My workaroud

In case it helps others, as a workaround, I added TimeoutStartSec=120 to the coreos-ignition-write-issues service.

Steps:

  1. Boot to old (working) deployment.
  2. Edit the coreos-ignition-write-issues.service and add TimeoutStartSec.
    sudo systemctl edit --full coreos-ignition-write-issues.service
    # This service writes issue files describing status
    # information about the Ignition run, which includes
    # Ignition warnings and information if no Ignition
    # config is provided.
    [Unit]
    Description=Create Ignition Status Issue Files
    Before=systemd-user-sessions.service
    ConditionPathExists=/etc/.ignition-result.json
    
    [Service]
    Type=oneshot
    ExecStart=/usr/libexec/coreos-ignition-write-issues
    RemainAfterExit=yes
    TimeoutStartSec=120
    
    [Install]
    WantedBy=multi-user.target
    
  3. Create new deployment with upgrade.
    sudo rpm-ostree upgrade --bypass-driver

Additional debug info

I am booting from USB on Raspberry Pi4

systemd package diff between my working (fc38) and non-working (fc39) deployments

rpm-ostree db diff ... ...| grep systemd
  clevis-systemd 19-2.fc38 -> 19-4.fc39
  systemd 253.12-1.fc38 -> 254.5-2.fc39
  systemd-container 253.12-1.fc38 -> 254.5-2.fc39
  systemd-libs 253.12-1.fc38 -> 254.5-2.fc39
  systemd-pam 253.12-1.fc38 -> 254.5-2.fc39
  systemd-resolved 253.12-1.fc38 -> 254.5-2.fc39
  systemd-udev 253.12-1.fc38 -> 254.5-2.fc39

Command on fc38

time journalctl --list-boots | wc -l
18

real	0m0.066s
user	0m0.012s
sys		0m0.057s

My log is not huge?

du -hs /var/log/journal
456M	/var/log/journal

strace snippet on fc39 (seems to get stuck in a loop?)

strace journalctl --list-boots
...
newfstatat(5, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(6, "", {st_mode=S_IFREG|0640, st_size=3737864, ...}, AT_EMPTY_PATH) = 0
newfstatat(9, "", {st_mode=S_IFREG|0640, st_size=3798336, ...}, AT_EMPTY_PATH) = 0
newfstatat(13, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(7, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(7, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(9, "", {st_mode=S_IFREG|0640, st_size=3798336, ...}, AT_EMPTY_PATH) = 0
newfstatat(8, "", {st_mode=S_IFREG|0640, st_size=3793576, ...}, AT_EMPTY_PATH) = 0
newfstatat(8, "", {st_mode=S_IFREG|0640, st_size=3793576, ...}, AT_EMPTY_PATH) = 0
newfstatat(9, "", {st_mode=S_IFREG|0640, st_size=3798336, ...}, AT_EMPTY_PATH) = 0
newfstatat(9, "", {st_mode=S_IFREG|0640, st_size=3798336, ...}, AT_EMPTY_PATH) = 0
newfstatat(9, "", {st_mode=S_IFREG|0640, st_size=3798336, ...}, AT_EMPTY_PATH) = 0
newfstatat(8, "", {st_mode=S_IFREG|0640, st_size=3793576, ...}, AT_EMPTY_PATH) = 0
newfstatat(10, "", {st_mode=S_IFREG|0640, st_size=3774840, ...}, AT_EMPTY_PATH) = 0
newfstatat(10, "", {st_mode=S_IFREG|0640, st_size=3774840, ...}, AT_EMPTY_PATH) = 0
newfstatat(8, "", {st_mode=S_IFREG|0640, st_size=3793576, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(10, "", {st_mode=S_IFREG|0640, st_size=3774840, ...}, AT_EMPTY_PATH) = 0
newfstatat(12, "", {st_mode=S_IFREG|0640, st_size=4577504, ...}, AT_EMPTY_PATH) = 0
newfstatat(13, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(13, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(13, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(14, "", {st_mode=S_IFREG|0640, st_size=4556448, ...}, AT_EMPTY_PATH) = 0
newfstatat(32, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(15, "", {st_mode=S_IFREG|0640, st_size=3774824, ...}, AT_EMPTY_PATH) = 0
newfstatat(15, "", {st_mode=S_IFREG|0640, st_size=3774824, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(16, "", {st_mode=S_IFREG|0640, st_size=3773224, ...}, AT_EMPTY_PATH) = 0
newfstatat(16, "", {st_mode=S_IFREG|0640, st_size=3773224, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(17, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(7, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(18, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(18, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(19, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(19, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(20, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(20, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(21, "", {st_mode=S_IFREG|0640, st_size=3789744, ...}, AT_EMPTY_PATH) = 0
newfstatat(21, "", {st_mode=S_IFREG|0640, st_size=3789744, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(22, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(22, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(23, "", {st_mode=S_IFREG|0640, st_size=3737856, ...}, AT_EMPTY_PATH) = 0
newfstatat(37, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(24, "", {st_mode=S_IFREG|0640, st_size=3769344, ...}, AT_EMPTY_PATH) = 0
newfstatat(24, "", {st_mode=S_IFREG|0640, st_size=3769344, ...}, AT_EMPTY_PATH) = 0
newfstatat(11, "", {st_mode=S_IFREG|0640, st_size=3769336, ...}, AT_EMPTY_PATH) = 0
newfstatat(25, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(25, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(24, "", {st_mode=S_IFREG|0640, st_size=3769344, ...}, AT_EMPTY_PATH) = 0
newfstatat(26, "", {st_mode=S_IFREG|0640, st_size=3737832, ...}, AT_EMPTY_PATH) = 0
newfstatat(7, "", {st_mode=S_IFREG|0640, st_size=8388608, ...}, AT_EMPTY_PATH) = 0
newfstatat(24, "", {st_mode=S_IFREG|0640, st_size=3769344, ...}, AT_EMPTY_PATH) = 0
newfstatat(27, "", {st_mode=S_IFREG|0640, st_size=4571808, ...}, AT_EMPTY_PATH) = 0
...

Possible related issue?

1 Like

Thanks all for posting this and doing some investigation. It seems to be a bug somewhere so I opened an issue for it over in hanging `journalctl --list-boots` stops boot · Issue #1641 · coreos/fedora-coreos-tracker · GitHub

1 Like