splash_svc_handle() does not execute for scheduled services. When the next non-scheduled service gets started, svcs_done is recomputed appropriately and causes the progress bar to make a jump which hides the problem to an extent. The problem is that when we get rc_hook_service_start_out for the scheduled service in question, that service is ALREADY in scheduled state, so splash_init adds it to svcs_done (via rc_services_in_state for rc_service_scheduled), then later on, splash_svc_handle() does nothing because the service is in the svcs_done list. Consider this scenario, where sshd depends on net.ath0: - net.ath0 starts, going from stopped to starting - net.ath0 goes from starting to inactive - sshd gets scheduled <some time passes> - net.ath0 starts again, going from inactive to starting - net.ath0 goes from starting to started - sshd goes from scheduled to starting - sshd goes from starting to started The sequence of events is: net.ath0 start_in scheduled=0 inactive=0 wasinactive=0 starting=0 started=0 net.ath0 start_now scheduled=0 inactive=0 wasinactive=0 starting=1 started=0 splash_svc_handle(net.ath0) net.ath0 start_done scheduled=0 inactive=1 wasinactive=0 starting=0 started=0 net.ath0 start_out scheduled=0 inactive=1 wasinactive=0 starting=0 started=0 sshd start_in scheduled=0 inactive=0 wasinactive=0 starting=0 started=0 sshd start_out scheduled=1 inactive=0 wasinactive=0 starting=0 started=0 splash_svc_handle(z) net.ath0 start_in scheduled=0 inactive=1 wasinactive=0 starting=0 started=0 net.ath0 start_now scheduled=0 inactive=0 wasinactive=1 starting=1 started=0 net.ath0 start_done scheduled=0 inactive=0 wasinactive=0 starting=0 started=1 sshd start_in scheduled=1 inactive=0 wasinactive=0 starting=0 started=0 net.ath0 start_out scheduled=0 inactive=0 wasinactive=0 starting=0 started=1 sshd start_now scheduled=1 inactive=0 wasinactive=0 starting=1 started=0 sshd start_done scheduled=0 inactive=0 wasinactive=0 starting=0 started=1 sshd start_out scheduled=0 inactive=0 wasinactive=0 starting=0 started=1
To clarify: hooks were only logged for sshd and net.ath0, which explains why you don't see hooks for z despite it being handled in the middle of the logs. splash_svc_handle was never called for sshd.
Created attachment 121412 [details, diff] A possible fix for the problem The attached patch should fix the problem of splash_svc_handle() not being executed for scheduled services. Please test and let me know whether it works and affects #179591 in any way.
Seems to almost work: Counting is fixed -- it reaches 25 of 25, through increments of 1. It does splash_svc_handle and updates the progress bar for every service that gets scheduled. However, the progress bar going backwards issue is back. I say "is back" as it went away when I had only applied this change: +do_start: + /* If we've been inactive, do nothing since the service has + * already been handled before it went inactive. */ + if (rc_service_state(name, rc_service_wasinactive)) + return 0; I'll look into this later today.
Created attachment 121455 [details, diff] fix The problem is similar to the inactive-->starting case -- those services were being counted twice, and the 2nd time was causing the progress bar to step backwards. This time, the step backwards was caused by double counting of the scheduled services, which cause the progress bar to increment when they initially get scheduled (due to depending on a service that went inactive), and then again if they go from scheduled to starting while the splash is still active. In this case, the start_out hook gets called with scheduled=1 inactive=0 wasinactive=0 starting=1 started=0 so we can just ignore those cases.
Thanks for the patches and debugging. The problem should be fixed in 1.4.2.1.
