Bug 2251394

Summary: systemd-vconsole-setup sometimes fails on boot due to "Start request repeated too quickly"
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: systemdAssignee: systemd-maint
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: rawhideCC: fedoraproject, filbranden, fsumsal, lnykryn, msekleta, ryncsn, systemd-maint, yuwatana, zbyszek
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard: openqa
Fixed In Version: systemd-255~rc3-4.fc40 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2024-01-09 08:54:16 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
full journal none

Description Adam Williamson 2023-11-24 17:34:46 UTC 
In openQA tests recently, I've noticed the base_services_start test (which checks there are no failed services after boot) is sometimes failing because systemd-vconsole-setup.service shows as failed. Looking at the logs, it seems it gets started several times during boot for some reason, and sometimes systemd decides it's happening too fast and fails it for "Start request repeated too quickly.":

[adamw@xps13a tmp]$ journalctl --file var/log/journal/6b4ac659ca7c49fdba1022861e3b78e5/system.journal  | grep vconsole
Nov 24 01:46:35 localhost systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:35 localhost systemd[1]: Finished systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:35 localhost systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
Nov 24 01:46:35 localhost systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:35 localhost systemd[1]: Stopping systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:35 localhost systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:35 localhost systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
Nov 24 01:46:35 localhost systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:36 localhost systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:36 localhost systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
Nov 24 01:46:36 localhost systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:36 localhost systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:36 localhost systemd-vconsole-setup[408]: KD_FONT_OP_GET failed while trying to get the font metadata: Invalid argument
Nov 24 01:46:36 localhost systemd-vconsole-setup[408]: Fonts will not be copied to remaining consoles
Nov 24 01:46:36 localhost systemd[1]: Finished systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:39 localhost systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
Nov 24 01:46:39 localhost systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:39 localhost audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 24 01:46:39 localhost systemd[1]: Stopping systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:39 localhost systemd[1]: Starting systemd-vconsole-setup.service - Virtual Console Setup...
Nov 24 01:46:39 localhost systemd[1]: systemd-vconsole-setup.service: Deactivated successfully.
Nov 24 01:46:39 localhost systemd[1]: Stopped systemd-vconsole-setup.service - Virtual Console Setup.
Nov 24 01:46:39 localhost audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 24 01:46:39 localhost audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 24 01:46:39 localhost systemd[1]: systemd-vconsole-setup.service: Start request repeated too quickly.
Nov 24 01:46:39 localhost systemd[1]: systemd-vconsole-setup.service: Failed with result 'start-limit-hit'.
Nov 24 01:46:39 localhost systemd[1]: Failed to start systemd-vconsole-setup.service - Virtual Console Setup.

I think this is probably caused by systemd-255~rc3-1.fc40 . The bug didn't happen to hit that update itself, but since it landed, the test has failed 7 times out of 18 attempts (on update tests on the prod instance). Before that update landed, it had failed only twice in the previous 482 attempts, both on a previous systemd update which failed to boot at all.
Comment 1 Frantisek Sumsal 2023-11-24 17:52:22 UTC 
My guess would be https://github.com/systemd/systemd/pull/30024 (cc @zbyszek) since we had to update some upstream tests as well due to the same issue.
Comment 2 Adam Williamson 2023-11-24 18:02:36 UTC 
Created attachment 2001305 [details]
full journal
Comment 3 Adam Williamson 2023-11-29 18:43:58 UTC 
I'm backporting the fix for this to Rawhide because I'm tired of restarting openQA tests that fail on it...:D
Comment 4 Zbigniew Jędrzejewski-Szmek 2023-12-01 10:55:52 UTC 
Thanks!