[systemd-devel] [PATCH] Log failing start conditions

[Zbigniew Jędrzejewski-Szmek]

On Fri, Jul 05, 2013 at 09:07:15AM +0200, Harald Hoyer wrote:
> On 07/05/2013 07:46 AM, Zbigniew Jędrzejewski-Szmek wrote:
> > On Wed, Jul 03, 2013 at 06:35:53AM +0200, Zbigniew Jędrzejewski-Szmek wrote:
> >> On Wed, Jun 26, 2013 at 03:06:38PM +0200, harald at redhat.com wrote:
> >>> From: Harald Hoyer <harald at redhat.com>
> >>>
> >>> $ systemctl status dracut-initqueue.service
> >>> dracut-initqueue.service - dracut initqueue hook
> >>>    Loaded: loaded (/usr/lib/systemd/system/dracut-initqueue.service;
> >>> static)
> >>>    Active: inactive (dead)
> >>>           start condition failed at Wed 2013-06-26 13:01:05 UTC; 22s ago
> >>>      Docs: man:dracut-initqueue.service(8)
> >>>
> >>> Jun 26 13:01:05 lenovo systemd[1]: Starting of dracut-initqueue.service
> >>> skipped because the following start conditions were not met:
> >>>    ConditionKernelCommandLine:|rd.break=initqueue
> >>>    ConditionPathExistsGlob: |/lib/dracut/hooks/initqueue/timeout/*.sh
> >>>    ConditionPathExistsGlob: |/lib/dracut/hooks/initqueue/online/*.sh
> >>>    ConditionPathExistsGlob: |/lib/dracut/hooks/initqueue/finished/*.sh
> >>>    ConditionPathExistsGlob: |/lib/dracut/hooks/initqueue/settled/*.sh
> >>>    ConditionPathExistsGlob: |/lib/dracut/hooks/initqueue/*.sh
> >>>    ConditionPathExists: |/lib/dracut/need-initqueue
> >> Hi Harald,
> >>
> >> your patch seems to is better than mine, I somehow missed
> >> the question of muliple conditions. I think you should go ahead
> >> and appy this.
> > Hm, I missed one big problem with your patch: at levels >= INFO, the
> > messages about failing conditions are logged to the console. This is
> > definitly not OK. But with level == DEBUG, the messages are not
> > logged by default at all.
> > 
> > Maybe we don't need to take a bit more relaxed approach, and when
> > the triggering conditions are not met, simply log the fact in one
> > line: "Starting of service.service skipped because none of the trigger conditions were met." This might be good enough for the user, and remove the need for
> > patching the logging routines. (Changes done in patch 1/2 also have
> > the disadvantage that they slow down a very common path, for a
> > relatively minor goal.)
> 
> Well, the problem is, that in retrospect debugging, you cannot get the
> information from the journal, which of the conditions were not met.
With just one line of logs, you can: if it was the triggering conditions
then they must have *all* failed, and if it was a non-triggering condition,
then it's just the one that is logged.

Anyway, I think that the problem with log levels is the problem.

> We could make the MESSAGE a one liner. But I really would like to add the
> CONDITION_RESULTS. This of course requires the log_struct_internal() patch.
> 
> The slow down are two memchr(). I think that's worth the multiple lines capability.
> 
> log_struct_unit(LOG_NOTICE,
>                 u->id,
>                 MESSAGE_ID(SD_MESSAGE_UNIT_CONDITIONS),
>                 "MESSAGE=Starting of %s skipped because none of the start
> conditions were met.", u->id,
>                 "CONDITION_RESULTS=%s", buf,
>                 NULL);
> 
> 
> maybe rename CONDITION_RESULTS to CONDITIONS_FAILED

Zbyszek