[systemd-devel] [PATCH] core: switch to journal when socket is listening

[Umut Tezduyar]

>> On Thu, Jun 13, 2013 at 9:26 PM, Umut Tezduyar <umut at tezduyar.com> wrote:
>> > systemd starts using journal as soon as the journal
>> > socket is in listening state instead of waiting for
>> > journal's socket to switch to 'running' state.
>> > ---
>> >  src/core/manager.c | 3 ++-
>> >  1 file changed, 2 insertions(+), 1 deletion(-)
>> >
>> > diff --git a/src/core/manager.c b/src/core/manager.c
>> > index f16621a..cebc43e 100644
>> > --- a/src/core/manager.c
>> > +++ b/src/core/manager.c
>> > @@ -2613,7 +2613,8 @@ void manager_recheck_journal(Manager *m) {
>> >                  return;
>> >
>> >          u = manager_get_unit(m, SPECIAL_JOURNALD_SOCKET);
>> > -        if (u && SOCKET(u)->state != SOCKET_RUNNING) {
>> > +        if (u && SOCKET(u)->state != SOCKET_RUNNING &&
>> > +                 SOCKET(u)->state != SOCKET_LISTENING) {
>> >                  log_close_journal();
>> >                  return;
>> >          }
>> >
>>
>> Hi,
>>
>> Due to a race condition (at least I think) between systemd and
>> journald, systemd might keep logging to kmsg even though journal is up
>> and running. Systemd switches to using journal for logging when both
>> journal's socket and service are in running state. Occasionally  I
>> have ended up finding my system in the following state after booting
>> to basic.target.
>>
>> systemd-journald.service   loaded active   running     Journal Service
>> systemd-journald.socket    loaded active   listening   Journal Socket
>>
>> At this point journal is up, program's stdout/err is sent to journal
>> (can be seen by journalctl) but systemd still thinks journal is not
>> usable for its own logging and keeps logging to kmsg.
>>
>> If you are using kernel < 3.5, the effect of the problem is not being
>> able to see systemds logs in journalctl.
>>
>> -------------------------------
>>
>> I think what is happening is both journald and systemd are racing for
>> the EPOLLIN event on the journal's sockets. If journal is receiving
>> EPOLLIN events all the time, then systemd will never get notified of
>> the activity on the sockets and never switch the socket to running
>> state.
>>
>> If I disable the EPOLLIN event registration on the journald side, I
>> can see that systemd-journald.socket switches to running state %100.
>>
>> Since systemd-journal.socket and systemd-journal.service are starting
>> on boot up anyways, I don't see the necessity of waiting for
>> systemd-journald.socket to go to running state.
>>
>> If anyone would like to get more information, I can reproduce the
>> problem pretty often. I have tried both kernel 3.4 and 3.8 as well as
>> different ISAs.
>
> I see the problem. In most other cases it never mattered that the
> socket's state is correctly updated. I guess it actually does for the
> journald socket at least.
>
> The cleanest way to fix this appears to me is updating the socket's
> state to RUNNING as soon as its matching service is activated, instead
> of only when we receive EPOLLIN. We already get notifications when the
> service dies, we should just extend that for when the service starts up.
>
> As it turns out this recently became a bit easier with the unit logic,
> there's now a trigger_notify() callback in UnitVTable that is invoked
> each time a unit that is triggered by a unit changes state. It's
> probably just a matter of adding a callback in there, and doing a simple
> state change. Patch appreciated (though I added this to the TODO list,
> too.)
>
> (In fact, service.c's service_notify_sockets_dead() should probably be
> replaced by the same trigger_notify() handler, if possible, but that's
> just the cherry on top).
>
> Lennart
>
> --
> Lennart Poettering - Red Hat, Inc.

Hi Lennart,

I didn't quite understand how this could end up in a deadlock
(http://lists.freedesktop.org/archives/systemd-devel/2013-June/011404.html)

I think in general we could be having a problem when a service could
be started by both socket activation and as part of a target.wants. It
could be that first data coming in the socket might trigger an event
that is being caught by systemd but not the service itself (even
though service is up) and this might cause the service receive the
first package delayed (in the event of the next data).

I will try to implement your changes with trigger_notify in couple of
weeks if no one gets to it before me.

Thanks.