Discussion:
systemd hangs after Welcome message when LogLevel=debug
(too old to reply)
Barry Scott
2014-01-14 13:31:29 UTC
Permalink
systemd-208-9.fc20.x86_64

We have been porting a working configuration from fedora 19 to fedora 20.
After systemd prints the Welcome message it then hangs.

We found that changing the LogLevel from debug to info fixes the
hang. As does setting LogTarget=console.

It would seem that the default LogTarget cannot be used to log debug
messages. Does the default log target use debug itself and
deadlock or loop?

Here is the full system.conf:

[Manager]
LogLevel=debug
DumpCore=yes
DefaultStandardOutput=syslog
JoinControllers=

Barry
Holger Schurig
2014-01-15 15:44:21 UTC
Permalink
Educated guess (!)

With LogLevel=debug, you generate huge amounts of output.

With DefaultStandardOutput=syslog, you're asking systemd to send it's
output to syslog.

But while systemd is starting your system the syslog might not be
ready. Probably systemd has some buffer, where it buffers the output.
Once syslog becomes available, it will be fed with the buffer's
contents first. If the output is small enought, as with LogLevel=info,
this actually works. But when you generate gobs of output, the buffer
will overflow and the output routine will wait until the buffer get's
emptied, which it never will ...

So, you might try to use DefaultStandardOutput=syslog-or-kmsg or
DefaultStandardOutput=journal instead. The latter will eventually also
send the output to syslog, which is why it's a default.
David Timothy Strauss
2014-01-17 08:43:52 UTC
Permalink
We're running into this too with lots of automount units. They log a
fair bit as they start, and that overwhelms the journal buffer before
it starts.
Barry Scott
2014-01-20 13:42:38 UTC
Permalink
I drafted this last week, sorry for the delay.
Post by Holger Schurig
Educated guess (!)
With LogLevel=debug, you generate huge amounts of output.
With LogTarget=syslog-or-kmsg and kernel not quiet I would expect to see the
first few debug messages before it hung up. But nothing appears.
Post by Holger Schurig
With DefaultStandardOutput=syslog, you're asking systemd to send it's
output to syslog.
But while systemd is starting your system the syslog might not be
ready. Probably systemd has some buffer, where it buffers the output.
Once syslog becomes available, it will be fed with the buffer's
contents first. If the output is small enought, as with LogLevel=info,
this actually works. But when you generate gobs of output, the buffer
will overflow and the output routine will wait until the buffer get's
emptied, which it never will ...
So, you might try to use DefaultStandardOutput=syslog-or-kmsg or
DefaultStandardOutput=journal instead. The latter will eventually also
send the output to syslog, which is why it's a default.
I guess you are saying that because all output must go to syslog and syslog is
not running that systemd will hang. But why does the configuration work if
LogLevel=info in that case?

Barry
Lennart Poettering
2014-01-20 16:29:46 UTC
Permalink
Post by Barry Scott
Post by Holger Schurig
But while systemd is starting your system the syslog might not be
ready. Probably systemd has some buffer, where it buffers the output.
Once syslog becomes available, it will be fed with the buffer's
contents first. If the output is small enought, as with LogLevel=info,
this actually works. But when you generate gobs of output, the buffer
will overflow and the output routine will wait until the buffer get's
emptied, which it never will ...
So, you might try to use DefaultStandardOutput=syslog-or-kmsg or
DefaultStandardOutput=journal instead. The latter will eventually also
send the output to syslog, which is why it's a default.
I guess you are saying that because all output must go to syslog and syslog is
not running that systemd will hang. But why does the configuration work if
LogLevel=info in that case?
systemd will never hang on this. syslog-or-kmsg means that syslog is
used when it is up, and kmsg otherwise. We will not block on anything,
it's just a really simple condition check each time we write a msg.

Lennart
--
Lennart Poettering, Red Hat
Lennart Poettering
2014-01-17 20:17:04 UTC
Permalink
Post by Barry Scott
systemd-208-9.fc20.x86_64
We have been porting a working configuration from fedora 19 to fedora 20.
After systemd prints the Welcome message it then hangs.
What do you mean by "hangs"? Is it just the output that doesn't continue
anymore or does the entire system lock up?

Note that during really early boot the journal is not available yet,
which means we can only log to kmsg then (and thus the
console). However, as soon as the journal is available we then start
logging directly to the journal. This might appear from the outside as
if only during the first part of the boot output is generated if you
only look at the console.

You can use LogTarget=kmsg to redirect output to kmsg unconditionally,
so that you get everything in kmsg and thus the console.

Lennart
--
Lennart Poettering, Red Hat
David Timothy Strauss
2014-01-18 00:49:05 UTC
Permalink
On Fri, Jan 17, 2014 at 12:17 PM, Lennart Poettering
Post by Lennart Poettering
Note that during really early boot the journal is not available yet,
which means we can only log to kmsg then (and thus the
console). However, as soon as the journal is available we then start
logging directly to the journal. This might appear from the outside as
if only during the first part of the boot output is generated if you
only look at the console.
The way we're seeing it manifest as freezes for 60 seconds a line in
bootup. After each 60 second timeout, we see a single line of kmsg
output, and then bootup continues until another item gets logged.
Post by Lennart Poettering
You can use LogTarget=kmsg to redirect output to kmsg unconditionally,
so that you get everything in kmsg and thus the console.
This seems to have major performance impacts versus logging to the journal.
David Timothy Strauss
2014-01-18 00:52:44 UTC
Permalink
It would be nice if bootup could realize the journal queue is full and
wait for journal startup before proceeding further. It might cause
some annoying non-determinism, though.

We primarily see the problem with the logging from automounts and mount units.
Dominique Michel
2014-01-18 16:45:02 UTC
Permalink
Le Fri, 17 Jan 2014 16:52:44 -0800,
Post by David Timothy Strauss
It would be nice if bootup could realize the journal queue is full and
wait for journal startup before proceeding further. It might cause
some annoying non-determinism, though.
We primarily see the problem with the logging from automounts and mount units.
In /etc/fstab, we can set if a partition must be mounted or not at
boot time, but not if, in the case it must be mounted, that partition is
vital for the system (i.e. / or /var) and the system must wait for it to
be mounted, or if that partition is not vital (i.e. /mnt/*) and the
system don't need to wait for it to boot. It would be great if such a
feature could be implemented in systemd or elsewhere.

Dominique
Tom Gundersen
2014-01-18 16:26:24 UTC
Permalink
On Sat, Jan 18, 2014 at 5:45 PM, Dominique Michel
Post by Dominique Michel
Le Fri, 17 Jan 2014 16:52:44 -0800,
Post by David Timothy Strauss
It would be nice if bootup could realize the journal queue is full and
wait for journal startup before proceeding further. It might cause
some annoying non-determinism, though.
We primarily see the problem with the logging from automounts and mount units.
In /etc/fstab, we can set if a partition must be mounted or not at
boot time, but not if, in the case it must be mounted, that partition is
vital for the system (i.e. / or /var) and the system must wait for it to
be mounted, or if that partition is not vital (i.e. /mnt/*) and the
system don't need to wait for it to boot. It would be great if such a
feature could be implemented in systemd or elsewhere.
Isn't this precisely what 'fail'/'nofail' allows?

Cheers,

Tom
David Timothy Strauss
2014-01-19 04:04:53 UTC
Permalink
On Sat, Jan 18, 2014 at 8:45 AM, Dominique Michel
Post by Dominique Michel
In /etc/fstab, we can set if a partition must be mounted or not at
boot time, but not if, in the case it must be mounted, that partition is
vital for the system (i.e. / or /var) and the system must wait for it to
be mounted, or if that partition is not vital (i.e. /mnt/*) and the
system don't need to wait for it to boot. It would be great if such a
feature could be implemented in systemd or elsewhere.
We're using systemd automounts. Even if we weren't, auto-mounting on
first access isn't an fstab thing.
Lennart Poettering
2014-01-20 12:18:10 UTC
Permalink
Post by David Timothy Strauss
It would be nice if bootup could realize the journal queue is full and
wait for journal startup before proceeding further. It might cause
some annoying non-determinism, though.
Not following here. Logging in syslog and the journal is synhchronous:
as soon as the socket fills up the clients start to block until the
other side made space again. THis means that no messages should be lost
and boot-up should be neatly synchronized to the logging sserver speed.

Note that by default the socket buffer is really small. The kernel puts
a limit to 15 messages by default, (/proc/sys/net/unix/max_dgram_qlen
can be used to change this, unfortunately only globally), and the socket
buffer limit in bytes is pretty short too... -- the latter is now bumped
if possible with systemd git, but that only works with priviliged
clients...

Lennart
--
Lennart Poettering, Red Hat
Barry Scott
2014-01-20 11:22:02 UTC
Permalink
Post by Lennart Poettering
Post by Barry Scott
systemd-208-9.fc20.x86_64
We have been porting a working configuration from fedora 19 to fedora 20.
After systemd prints the Welcome message it then hangs.
What do you mean by "hangs"? Is it just the output that doesn't continue
anymore or does the entire system lock up?
After a few minutes nothing is output after the Welcome message.
No evidence that any unit start.
Post by Lennart Poettering
Note that during really early boot the journal is not available yet,
which means we can only log to kmsg then (and thus the
console). However, as soon as the journal is available we then start
logging directly to the journal. This might appear from the outside as
if only during the first part of the boot output is generated if you
only look at the console.
Understood and recall that I'm porting from F19 to F20 and this
works in F19.

With my engineer hat on I wonder why info messages can be output but not one
debug message?
Post by Lennart Poettering
You can use LogTarget=kmsg to redirect output to kmsg unconditionally,
so that you get everything in kmsg and thus the console.
And by using the kernel option log_buf_len=128M we can make sure all the
messages are kept.

Barry
Lennart Poettering
2014-01-20 12:21:14 UTC
Permalink
Post by Barry Scott
Post by Lennart Poettering
Post by Barry Scott
systemd-208-9.fc20.x86_64
We have been porting a working configuration from fedora 19 to fedora 20.
After systemd prints the Welcome message it then hangs.
What do you mean by "hangs"? Is it just the output that doesn't continue
anymore or does the entire system lock up?
After a few minutes nothing is output after the Welcome message.
No evidence that any unit start.
It would be good to if I could have a look at the output of "journalctl
-o short-monotonic -b" of the log messages around the time where this
happens...
Post by Barry Scott
With my engineer hat on I wonder why info messages can be output but not one
debug message?
Not following?

Lennart
--
Lennart Poettering, Red Hat
Barry Scott
2014-01-20 13:23:43 UTC
Permalink
Post by Lennart Poettering
Post by Barry Scott
Post by Lennart Poettering
Post by Barry Scott
systemd-208-9.fc20.x86_64
We have been porting a working configuration from fedora 19 to fedora 20.
After systemd prints the Welcome message it then hangs.
What do you mean by "hangs"? Is it just the output that doesn't continue
anymore or does the entire system lock up?
After a few minutes nothing is output after the Welcome message.
No evidence that any unit start.
It would be good to if I could have a look at the output of "journalctl
-o short-monotonic -b" of the log messages around the time where this
happens...
Post by Barry Scott
With my engineer hat on I wonder why info messages can be output but not
one debug message?
Not following?
Given this problem has not trigger an insight from your selves I clearly
need to dig deeper to get more information.

I'm very busy at work at the moment but hope to come back to this to
help bottom out what is happening.

Barry
Continue reading on narkive:
Loading...