[systemd-devel] Unbuffered stderr for my systemd service?

[WANG Chao]

Hi,

I have a service (a script) running under systemd and need its stderr to
be output'd immediately, not line buffered. I tried serveral ways but
didn't work out. I hope to get some feedback here :)

Here's my foobar.service:
--
[Service]
Type=oneshot
ExecStart=-/bin/foobar.sh
StandardInput=null
StandardOutput=syslog
StandardError=syslog+console
--

My foobar.sh:
--
#!/bin/sh
echo "Here we go"
for i in `seq 1 10`; do
echo -n a >&2
sleep 0.1
done
--

If run `/bin/foobar.sh` directly, I get char 'a' popping up to console
one by one each 0.1 second. And this is what I expect.

But if I run `systemctl restart foobar.service`, a string "aaaaaaaaaa"
altogether pops up after 1 second.

I've got a ugly workaround by redirecting stderr to /dev/console.
However, I lost the systemd journal feature though :(

I look into the systemd.exec(5), it says in the "StandardOutput=" part:
"[..]syslog+console, journal+console and kmsg+console work similarly but
copy the output to the system console as well"

So systemd first write to syslog/journal then copy the output to
console. And it looks like systemd would use line buffering for both
stdout and stderr.

I'm wondering if there's a way to change the output buffer mode to
unbuffered for a systemd service.

If not, should systemd change stderr buffer mode to unbuffered? Like the
most common situations in Linux.

Also I want to mention that with line buffering, it's impossible to
update information in-place (something like calling times of echo -e
"blah\r", later output will override the former one).

Any comments are welcome! Thanks!
WANG Chao

[Vivek Goyal]

Post by WANG Chao
Hi,
I have a service (a script) running under systemd and need its stderr to
be output'd immediately, not line buffered. I tried serveral ways but
didn't work out. I hope to get some feedback here :)
--
[Service]
Type=oneshot
ExecStart=-/bin/foobar.sh
StandardInput=null
StandardOutput=syslog
StandardError=syslog+console
--
--
#!/bin/sh
echo "Here we go"
for i in `seq 1 10`; do
echo -n a >&2
sleep 0.1
done
--
If run `/bin/foobar.sh` directly, I get char 'a' popping up to console
one by one each 0.1 second. And this is what I expect.
But if I run `systemctl restart foobar.service`, a string "aaaaaaaaaa"
altogether pops up after 1 second.
I've got a ugly workaround by redirecting stderr to /dev/console.
However, I lost the systemd journal feature though :(
"[..]syslog+console, journal+console and kmsg+console work similarly but
copy the output to the system console as well"
So systemd first write to syslog/journal then copy the output to
console. And it looks like systemd would use line buffering for both
stdout and stderr.
I'm wondering if there's a way to change the output buffer mode to
unbuffered for a systemd service.
If not, should systemd change stderr buffer mode to unbuffered? Like the
most common situations in Linux.
Also I want to mention that with line buffering, it's impossible to
update information in-place (something like calling times of echo -e
"blah\r", later output will override the former one).

CCing Lennart.

This is important functionality for us. makeudmpfile utility (utility which
filters kernel crash dump and shows the progress bar), run in kdump
kernel. For large machines it displays the progress bar in kernel. Right
now all the code runs from initramfs in the context of a service and
we don't get progress messages. Just we get a 100% message at the end.

Right now we bypassed journal by sending everything to /dev/console but
it is a generic question that any serivce displaying some kind of
progress bar, how is it handled with current journal mechanism.

Thanks
Vivek

Post by WANG Chao
Any comments are welcome! Thanks!
WANG Chao

[Mantas Mikulėnas]

Post by Vivek Goyal
This is important functionality for us. makeudmpfile utility (utility which
filters kernel crash dump and shows the progress bar), run in kdump
kernel. For large machines it displays the progress bar in kernel. Right
now all the code runs from initramfs in the context of a service and
we don't get progress messages. Just we get a 100% message at the end.
Right now we bypassed journal by sending everything to /dev/console but
it is a generic question that any serivce displaying some kind of
progress bar, how is it handled with current journal mechanism.

The journal works the same way as syslog has worked for ages – have
you ever seen an animated progress bar in your /var/log/syslog? I'd
guess no, because syslog wouldn't accept it, and most services do not
display those in the first place – they either write periodic *full*
messages (e.g. every 10%) to the log, or have a way to check progress
via their own fooservicectl tools. systemd also provides a way to
display arbitrary text in `systemctl status` using the "notify"
feature; see systemd-notify(1) and sd_notify(3).

The only exception I can think of is the boot fsck service
(systemd-***@.service), which needs to run before `systemctl` or the
syslog become accessible. And it uses /dev/console for this:

console = fopen("/dev/console", "w");
…
while (!feof(f)) {
…
p = percent(pass, cur, max);
fprintf(console, "\r%s: fsck %3.1f%% complete...\r%n",
device, p, &m);
fflush(console);
…
}

--
Mantas Mikulėnas <***@gmail.com>

[Lennart Poettering]

Post by Vivek Goyal
CCing Lennart.
This is important functionality for us. makeudmpfile utility (utility which
filters kernel crash dump and shows the progress bar), run in kdump
kernel. For large machines it displays the progress bar in kernel. Right
now all the code runs from initramfs in the context of a service and
we don't get progress messages. Just we get a 100% message at the end.
Right now we bypassed journal by sending everything to /dev/console but
it is a generic question that any serivce displaying some kind of
progress bar, how is it handled with current journal mechanism.

if you want to do fancier output then do facnier ouput directly on the
console, but do not pumpt this through a log system, that's really not
what it is for...

Lennart

[Vivek Goyal]

Post by Lennart Poettering

Post by Vivek Goyal
CCing Lennart.
This is important functionality for us. makeudmpfile utility (utility which
filters kernel crash dump and shows the progress bar), run in kdump
kernel. For large machines it displays the progress bar in kernel. Right
now all the code runs from initramfs in the context of a service and
we don't get progress messages. Just we get a 100% message at the end.
Right now we bypassed journal by sending everything to /dev/console but
it is a generic question that any serivce displaying some kind of
progress bar, how is it handled with current journal mechanism.

if you want to do fancier output then do facnier ouput directly on the
console, but do not pumpt this through a log system, that's really not
what it is for...

That's fine. But that means services have to change now. In the
past stdout/stderr was not logged by default. So fancy outputs could
go to stdout/stderr without any issues. Now stdout/stderr is being
logged.

Well, for my use case change is easy and we have already done it.
So we will stick to it.

Thanks
Vivek

[Lennart Poettering]

Post by Vivek Goyal

Post by Lennart Poettering

Post by Vivek Goyal
CCing Lennart.
This is important functionality for us. makeudmpfile utility (utility which
filters kernel crash dump and shows the progress bar), run in kdump
kernel. For large machines it displays the progress bar in kernel. Right
now all the code runs from initramfs in the context of a service and
we don't get progress messages. Just we get a 100% message at the end.
Right now we bypassed journal by sending everything to /dev/console but
it is a generic question that any serivce displaying some kind of
progress bar, how is it handled with current journal mechanism.

if you want to do fancier output then do facnier ouput directly on the
console, but do not pumpt this through a log system, that's really not
what it is for...

That's fine. But that means services have to change now. In the
past stdout/stderr was not logged by default. So fancy outputs could
go to stdout/stderr without any issues. Now stdout/stderr is being
logged.

Yupp, this indeed is a change of behaviour due to system. You can revert
to the old behaviour by using StandardOutput=console or so, but you
already figured that out... ;-)

Lennart

[Lennart Poettering]

Post by WANG Chao
Hi,
I have a service (a script) running under systemd and need its stderr to
be output'd immediately, not line buffered. I tried serveral ways but
didn't work out. I hope to get some feedback here :)

This is not supported. Logging doesn't deal in individual
characters, really, but in log lines. Syslog doesn't do that, and
neither does the Journal.

And we will never support that, as allowing this would require us to
always store the context a character was printed in so that lines could
later be reassembled. But we cannot really do that.

So, I fear I have to tell you that this is not supported and never
will...
(Humm, please do not use "--" on a single line in the middle of an
email, that's indication for many MUAs that this is where the signature
starts, and they chop this off when replying...)

Lennart

[WANG Chao]

Post by Lennart Poettering

Post by WANG Chao
Hi,
I have a service (a script) running under systemd and need its stderr to
be output'd immediately, not line buffered. I tried serveral ways but
didn't work out. I hope to get some feedback here :)

This is not supported. Logging doesn't deal in individual
characters, really, but in log lines. Syslog doesn't do that, and
neither does the Journal.
And we will never support that, as allowing this would require us to
always store the context a character was printed in so that lines could
later be reassembled. But we cannot really do that.
So, I fear I have to tell you that this is not supported and never
will...

I understand that. Record the context of a character is printed would
never be a good idea. But still, I feel pity about line buffered stderr
stream in Journal :(

Post by Lennart Poettering
(Humm, please do not use "--" on a single line in the middle of an
email, that's indication for many MUAs that this is where the signature
starts, and they chop this off when replying...)

Sorry about "--", never thought that would be an issue. Thanks for
telling!

WANG Chao

[Kay Sievers]

Post by WANG Chao

Post by Lennart Poettering
(Humm, please do not use "--" on a single line in the middle of an
email, that's indication for many MUAs that this is where the signature
starts, and they chop this off when replying...)

Sorry about "--", never thought that would be an issue. Thanks for
telling!

It would only happen on _really_ broken mail programs, because the
convention includes a trailing space character which you didn't add.
The delimiter line is defined as "-- ".

http://tools.ietf.org/html/rfc3676#section-4.3

Kay

[WANG Chao]

Post by Kay Sievers

Post by WANG Chao

Post by Lennart Poettering
(Humm, please do not use "--" on a single line in the middle of an
email, that's indication for many MUAs that this is where the signature
starts, and they chop this off when replying...)

Sorry about "--", never thought that would be an issue. Thanks for
telling!

It would only happen on _really_ broken mail programs, because the
convention includes a trailing space character which you didn't add.
The delimiter line is defined as "-- ".
http://tools.ietf.org/html/rfc3676#section-4.3

Great to know!

I'm curious about what mail client Lennart has been using. Surely he
deserves a better one :P

WANG Chao

[Kay Sievers]

This post might be inappropriate. Click to display it.

[WANG Chao]

Post by Kay Sievers

Post by WANG Chao

Post by Lennart Poettering

Post by WANG Chao
I have a service (a script) running under systemd and need its stderr to
be output'd immediately, not line buffered. I tried serveral ways but
didn't work out. I hope to get some feedback here :)

This is not supported. Logging doesn't deal in individual
characters, really, but in log lines. Syslog doesn't do that, and
neither does the Journal.
And we will never support that, as allowing this would require us to
always store the context a character was printed in so that lines could
later be reassembled. But we cannot really do that.
So, I fear I have to tell you that this is not supported and never
will...

I understand that. Record the context of a character is printed would
never be a good idea. But still, I feel pity about line buffered stderr
stream in Journal :(

It is the right thing to buffer just buffer them to full lines.

Yes. Or buffer wouldn't be called "buffer".

Post by Kay Sievers
For the kernel counterpart, we added unbuffered console magic to the
kernel. It is really nasty and broken hack and really makes not much
sense in th eend. The code does work in the most common case, but just
does stupid things as soon as things start to compete about the log.
http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=084681d14e429cb6192262ac7437f00e2c02f26a
http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=eab072609e11a357181806ab5a5c309ef6eb76f5
Pretending to support pushing "animations" through a log system is a
pretty bad idea and relies on technical promises nobody can really
hold without inventing something that isn't logging anymore. But we
have that already, it's the console. :)

I couldn't agree more. Log system can't really record "animations" in a
common way. So in my case, console is right thing to use. Thanks for
your information here. Have a good day!

WANG Chao