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

[Lennart Poettering]

On Thu, 13.06.13 21:28, Umut Tezduyar (umut at tezduyar.com) wrote:

> 
> 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.