2 minute delay on boot #434

aanderse · 2025-03-26T01:12:38Z

aanderse
Mar 26, 2025

every time i boot up my finit based laptop i notice there is roughly a 2 minute delay - in debug mode the output just stalls - at some point in finit running
i think basically about the time finit transitions from run level S to the desired run level is when the debug output just pauses for 2 minutes

i usually just suspend the laptop so it hasn't been a big priority until i decided to spend some time on it this weekend

i disabled almost all services on my system and still had the delay 🤔

then i saw this:

The unconditional mount of /run/lock is for DoS prevention.

the os i use on this laptop has 2 folders (symlinks) under /run which have a ton of other symlinks in them - if i run something like tree -l /run/folder | wc -l i easily end up with 30,000k+ - could this be the source of my problem? i poked around in logs and i am not convinced yet... maybe the pidfile plugin skips this directory because it is a symlink?

any advice is greatly appreciated 🙇

Answered by aanderse

Mar 29, 2025

thanks for your input @troglobit ... the more i poke around in your code the more i am appreciating the nice and straightforward c you write - i ended up being able to navigate this easier than i anticipated

i littered the code you suggested with dbg statements and found that between two print statements the code locked 🤯
i went through a process of elimination and removed all services one by one to figure out exactly what was going on... i found that it was my syslog daemon that was causing me the grief - if i disabled it or replaced it with rsyslog everything worked fine

i am not sure what i did wrong when compiling my syslog... but i'll have to look into that some other day, because it…

View full answer

troglobit · 2025-03-26T05:10:29Z

troglobit
Mar 26, 2025
Maintainer

Hmm, maybe ... you can check that theory by providing a /run mount in your fstab, the code path you reference is only executed if /run is not mounted.

I think it's more likely that you have a run or task stanza in runlevel S that has not completed. The idea is to guarantee all run/tasks to have run once per runlevel. So for a setup task like:

task [S] /lib/console-setup/console-setup.sh -- Setting up console font and keymap

Finit will wait for console-setup.sh to complete before moving on to runlevel 2.

Trying to find that key parapgraph in the documentation to link to, but this critical piece of information may be something we've completely forgotten to put in there 😬 if so, terribly sorry! I'll get right on it!

5 replies

aanderse Mar 27, 2025
Author

Hmm, maybe ... you can check that theory by providing a /run mount in your fstab, the code path you reference is only executed if /run is not mounted.

i mount /run beforehand so all good there 👍

i have tried to reduce/simplify my system as much as possible so i am booting into run level 1 and have the following services which are applicable to run level 1:

task [12345789] name:ctrl-alt-del restart:10 <sys/key/ctrlaltdel> /nix/store/2sbr2vhincphgf76kd8i9w5gm96yxkpm-finit-4.10/bin/initctl reboot -- rebooting system
task [S12345] name:suid-sgid-wrappers restart:10 log /nix/store/cq7fxryjsz8m70q588w6w82smdg6nqxs-suid-sgid-wrappers.sh -- create suid/sgid wrappers
service [S0123456789] name:syslogd restart:10 <run/udevadm:5/success> notify:pid /nix/store/iz51i1bz285xdbpc57wcz65pvvnn7rh0-sysklogd-2.7.1/bin/syslogd -F -k -- system logging daemon
service cgroup.system name:udevd notify:none pid:udevd log [S12345789] /nix/store/vl4fc11jg9kf4ijpfk0xvv0g26f136mv-eudev-3.2.14/bin/udevd -- device event daemon (eudev)
run nowarn cgroup.init :1 [S] <service/udevd/ready> log /nix/store/vl4fc11jg9kf4ijpfk0xvv0g26f136mv-eudev-3.2.14/bin/udevadm settle -t 0 --
run nowarn cgroup.init :2 [S] <service/udevd/ready> log /nix/store/vl4fc11jg9kf4ijpfk0xvv0g26f136mv-eudev-3.2.14/bin/udevadm control --reload --
run nowarn cgroup.init :3 [S] <service/udevd/ready> log /nix/store/vl4fc11jg9kf4ijpfk0xvv0g26f136mv-eudev-3.2.14/bin/udevadm trigger -c add -t devices -- requesting device events
run nowarn cgroup.init :4 [S] <service/udevd/ready> log /nix/store/vl4fc11jg9kf4ijpfk0xvv0g26f136mv-eudev-3.2.14/bin/udevadm trigger -c add -t subsystems -- requesting subsystem events
run nowarn cgroup.init :5 [S] <service/udevd/ready> log /nix/store/vl4fc11jg9kf4ijpfk0xvv0g26f136mv-eudev-3.2.14/bin/udevadm settle -t 30 -- waiting for udev to finish

and here are the relevant logs from boot with finit.debug=true:

Mar 26 20:14:33 finix finit[1]: service_step():udevadm:5: stopped, cleaning up timers and conditions ...
Mar 26 20:14:33 finix finit[1]: cond_clear_noupdate():pid/udevadm:5
Mar 26 20:14:33 finix finit[1]: cond_set_path():/run/finit/cond/pid/udevadm:5 <= 0
Mar 26 20:14:33 finix finit[1]: cond_set_oneshot():run/udevadm:5/success
Mar 26 20:14:33 finix finit[1]: cond_set_oneshot_noupdate():run/udevadm:5/success => /run/finit/cond/run/udevadm:5/success
Mar 26 20:14:33 finix finit[1]: cond_update():run/udevadm:5/success: match <run/udevadm:5/success> system logging daemon(/nix/store/iz51i1bz285xdbpc57wcz65pvvnn7rh0-sysklogd-2.7.1/bin/syslogd)
Mar 26 20:14:33 finix finit[1]: service_step():             syslogd(   0):  waiting  enabled/updated cond:on  
Mar 26 20:14:33 finix finit[1]: cond_clear_noupdate():service/syslogd/
Mar 26 20:14:33 finix finit[1]: cond_set_path():/run/finit/cond/service/syslogd/ <= 0
Mar 26 20:14:33 finix finit[1]: service_step():             syslogd(   0): -> starting
Mar 26 20:14:33 finix finit[1]: service_step():             syslogd(   0): starting  enabled/updated cond:on  
Mar 26 20:14:33 finix finit[1]: cgroup_leaf_init():group system, name syslogd, pid 656, cfg 
Mar 26 20:14:33 finix finit[1]: group_init():path /sys/fs/cgroup/system/syslogd, leaf 1, cfg 
Mar 26 20:14:33 finix finit[1]: iwatch_add1():adding new watcher for path /sys/fs/cgroup/system/syslogd/cgroup.events
Mar 26 20:14:33 finix finit[1]: service_start():Starting syslogd as PID 656
Mar 26 20:14:33 finix finit[1]: Starting syslogd[656]
Mar 26 20:14:33 finix finit[1]: cond_clear_noupdate():service/syslogd/
Mar 26 20:14:33 finix finit[1]: cond_set_path():/run/finit/cond/service/syslogd/ <= 0
Mar 26 20:14:33 finix finit[1]: cond_set_oneshot():service/syslogd/running
Mar 26 20:14:33 finix finit[1]: cond_set_oneshot_noupdate():service/syslogd/running => /run/finit/cond/service/syslogd/running
Mar 26 20:14:33 finix finit[1]: service_step():             syslogd( 656): ->  running
Mar 26 20:14:33 finix finit[1]: service_step():             syslogd( 656):  running  enabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: service_step():           udevadm:5(   0): ->     done
Mar 26 20:14:33 finix finit[1]: service_step():           udevadm:5(   0):     done  enabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: service_monitor():collected bootstrap task udevadm:5(611), removing.
Mar 26 20:14:33 finix finit[1]: sm_step():state: bootstrap/wait, runlevel: S, newlevel: -1, teardown: 0, reload: 0
Mar 26 20:14:33 finix finit[1]: service_step():               tty:1(   0):   halted disabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: service_step():               tty:3(   0):   halted disabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: service_step():        ctrl-alt-del(   0):   halted disabled/updated cond:off 
Mar 26 20:14:33 finix finit[1]: service_step():                dbus(   0):   halted disabled/updated cond:off 
Mar 26 20:14:33 finix finit[1]: service_step():              greetd(   0):   halted disabled/updated cond:off 
Mar 26 20:14:33 finix finit[1]: service_step():     network-manager(   0):   halted disabled/updated cond:off 
Mar 26 20:14:33 finix finit[1]: service_step():          nix-daemon(   0):   halted disabled/updated cond:off 
Mar 26 20:14:33 finix finit[1]: service_step():               seatd(   0):   halted disabled/updated cond:off 
Mar 26 20:14:33 finix finit[1]: service_step():  suid-sgid-wrappers(   0):     done  enabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: service_step():             syslogd( 656):  running  enabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: service_step():               udevd( 523):  running  enabled/clean   cond:on  
Mar 26 20:14:33 finix finit[1]: cond_set_noupdate():service/udevd/ready
Mar 26 20:14:33 finix finit[1]: cond_set_path():/run/finit/cond/service/udevd/ready <= 2
Mar 26 20:14:33 finix finit[1]: cond_set_oneshot():int/bootstrap
Mar 26 20:14:33 finix finit[1]: cond_set_oneshot_noupdate():int/bootstrap => /run/finit/cond/int/bootstrap
Mar 26 20:14:33 finix finit[1]: sigchld_cb():Collected child PID 614, status: 0
Mar 26 20:14:33 finix finit[1]: service_monitor():collected unknown PID 614
Mar 26 20:14:34 finix finit[1]: pidfile_update_conds():path: /run/syslogd.pid, mask: 00000002
Mar 26 20:14:34 finix finit[1]: pidfile_update_conds():Found svc syslogd for /run/syslogd.pid with pid 656
Mar 26 20:14:34 finix finit[1]: pidfile_update_conds():Setting syslogd PID file to /run/syslogd.pid
Mar 26 20:14:34 finix finit[1]: cond_set_noupdate():pid/syslogd
Mar 26 20:14:34 finix finit[1]: cond_set_path():/run/finit/cond/pid/syslogd <= 2
Mar 26 20:14:34 finix finit[1]: cond_set_noupdate():service/syslogd/ready
Mar 26 20:14:34 finix finit[1]: cond_set_path():/run/finit/cond/service/syslogd/ready <= 2
Mar 26 20:14:34 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready> d-bus message bus daemon(/nix/store/2zkzz05nvjn9q35zkw4pmahhz7k5ijxm-dbus-1.14.10/bin/dbus-daemon)
Mar 26 20:14:34 finix finit[1]: service_step():                dbus(   0):   halted disabled/updated cond:on  
Mar 26 20:14:34 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready,service/seatd/ready> greeter daemon(/nix/store/c9msdjjlpz40z7amcg4rybvf8ajj106p-greetd-0.10.3/bin/greetd)
Mar 26 20:14:34 finix finit[1]: service_step():              greetd(   0):   halted disabled/updated cond:off 
Mar 26 20:14:34 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready> network manager service(/nix/store/1fbfqdyj6hg9f90ricw3pdhgxk0fshc5-networkmanager-1.52.0/bin/NetworkManager)
Mar 26 20:16:35 finix finit[1]: service_step():     network-manager(   0):   halted disabled/updated cond:on  
Mar 26 20:16:35 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready> nix daemon(/nix/store/shaj16d4gry1a930h1rannl8y5y9wjl7-nix-2.24.12/bin/nix-daemon)
Mar 26 20:16:35 finix finit[1]: service_step():          nix-daemon(   0):   halted disabled/updated cond:on  
Mar 26 20:16:35 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready> seat management daemon(/nix/store/v4dhxr7736r3pnk9mc2xry7hvdqxlfqs-seatd-0.9.1-bin/bin/seatd)
Mar 26 20:16:35 finix finit[1]: service_step():               seatd(   0):   halted disabled/updated cond:on  
Mar 26 20:16:35 finix finit[1]: pidfile_update_conds():path: /run/syslogd.pid, mask: 00000008
Mar 26 20:16:35 finix finit[1]: pidfile_update_conds():Found svc syslogd for /run/syslogd.pid with pid 656
Mar 26 20:16:36 finix finit[1]: pidfile_update_conds():Setting syslogd PID file to /run/syslogd.pid
Mar 26 20:16:36 finix finit[1]: cond_set_noupdate():pid/syslogd
Mar 26 20:16:36 finix finit[1]: cond_set_path():/run/finit/cond/pid/syslogd <= 2
Mar 26 20:16:36 finix finit[1]: cond_set_noupdate():service/syslogd/ready
Mar 26 20:16:36 finix finit[1]: cond_set_path():/run/finit/cond/service/syslogd/ready <= 2
Mar 26 20:16:36 finix finit[1]: sm_check_bootstrap():Step all services ...
Mar 26 20:16:36 finix finit[1]: service_step():               tty:1(   0):   halted disabled/clean   cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():               tty:3(   0):   halted disabled/clean   cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():        ctrl-alt-del(   0):   halted disabled/updated cond:off 
Mar 26 20:16:36 finix finit[1]: service_step():                dbus(   0):   halted disabled/updated cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():              greetd(   0):   halted disabled/updated cond:off 
Mar 26 20:16:36 finix finit[1]: service_step():     network-manager(   0):   halted disabled/updated cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():          nix-daemon(   0):   halted disabled/updated cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():               seatd(   0):   halted disabled/updated cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():  suid-sgid-wrappers(   0):     done  enabled/clean   cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():             syslogd( 656):  running  enabled/clean   cond:on  
Mar 26 20:16:36 finix finit[1]: service_step():               udevd( 523):  running  enabled/clean   cond:on  
Mar 26 20:16:36 finix finit[1]: cond_set_noupdate():service/udevd/ready
Mar 26 20:16:36 finix finit[1]: cond_set_path():/run/finit/cond/service/udevd/ready <= 2
Mar 26 20:16:36 finix finit[1]: service_completed():suid-sgid-wrappers has completed ...
Mar 26 20:16:36 finix finit[1]: sm_check_bootstrap():All run/task have completed, resuming bootstrap.
Mar 26 20:16:36 finix finit[1]: sm_check_bootstrap():Flushing pending .conf file events ...
Mar 26 20:16:37 finix finit[1]: sm_check_bootstrap():Change to default runlevel(1), starting all services ...

notice how the time jumps from 20:14:34 to 20:16:35 - this is because of the 120 timeout that you coded in... but why? there are a few other services mentioned here, but they aren't relevant because they aren't in run level 1 so we can ignore them

at the point where the logs pause for 2 minutes all services in run level 1 are already up and running, all tasks complete - this can be validated by the service_step lines

can you think of any simple patches i can apply to finit to get more information about this pause? or does anything jump out at you?

i apologize for the hassle but greatly appreciate any help you can provide here... 🙇‍♂️

troglobit Mar 27, 2025
Maintainer

Very difficult to tell what's going on, but it looks just like Finit locks up between the two lines:

Mar 26 20:14:34 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready> network manager service(/nix/store/1fbfqdyj6hg9f90ricw3pdhgxk0fshc5-networkmanager-1.52.0/bin/NetworkManager)
Mar 26 20:16:35 finix finit[1]: service_step():     network-manager(   0):   halted disabled/updated cond:on

If we look at the previous such pair of lines we can see they execute within the same second:

Mar 26 20:14:34 finix finit[1]: cond_update():service/syslogd/ready: match <service/syslogd/ready,service/seatd/ready> greeter daemon(/nix/store/c9msdjjlpz40z7amcg4rybvf8ajj106p-greetd-0.10.3/bin/greetd)
Mar 26 20:14:34 finix finit[1]: service_step():              greetd(   0):   halted disabled/updated cond:off

So if you want to delve further into this, I'd start looking at what cond_update() does for the network-manager that delays that call to service_step(). There are very few lines of code between the calls, so if you could sprinkle some dbg() statements around that part of the code maybe we can figure out what's going on.

aanderse Mar 29, 2025
Author

thanks for your input @troglobit ... the more i poke around in your code the more i am appreciating the nice and straightforward c you write - i ended up being able to navigate this easier than i anticipated

i littered the code you suggested with dbg statements and found that between two print statements the code locked 🤯
i went through a process of elimination and removed all services one by one to figure out exactly what was going on... i found that it was my syslog daemon that was causing me the grief - if i disabled it or replaced it with rsyslog everything worked fine

i am not sure what i did wrong when compiling my syslog... but i'll have to look into that some other day, because it seems like a very nice syslog implementation 😉

Answer selected by aanderse

troglobit Mar 29, 2025
Maintainer

Thank you for those kind words 😊 I've found that the more intricate the code, the buggier it usually is.

I'm very curious about between which lines the code locked, could you share some more detail please? I'm using sysklogd in almost all embedded systems I maintain, usually along with Finit, so this kinda spooked me a bit. Really like to get to the bottom of it

aanderse Mar 29, 2025
Author

Really like to get to the bottom of it

i would too! after the kids are in bed i will sit down with this and prepare a useful report for you in the next few nights

i appreciate your willingness to help me with this 🙇‍♂️

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

2 minute delay on boot #434

{{title}}

Replies: 1 comment 5 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

2 minute delay on boot #434

aanderse Mar 26, 2025

Replies: 1 comment · 5 replies

troglobit Mar 26, 2025 Maintainer

aanderse Mar 27, 2025 Author

troglobit Mar 27, 2025 Maintainer

aanderse Mar 29, 2025 Author

troglobit Mar 29, 2025 Maintainer

aanderse Mar 29, 2025 Author

aanderse
Mar 26, 2025

Replies: 1 comment 5 replies

troglobit
Mar 26, 2025
Maintainer

aanderse Mar 27, 2025
Author

troglobit Mar 27, 2025
Maintainer

aanderse Mar 29, 2025
Author

troglobit Mar 29, 2025
Maintainer

aanderse Mar 29, 2025
Author