extra newlines in logged container output

[liewegas]

container output, as seen in journald, has random newlines inserted.

Steps to reproduce the issue:

There is probably a simpler way to do this, but this is what I did:

cat > /etc/systemd/system/conmon-test.service
[Unit]
Description=test

[Service]
ExecPre=-podman rm conmon-test
ExecStart=podman run -d --rm --name conmon-test --log-driver journald --entrypoint bash centos -c "find /"

2. systemctl start conmon-test
3. journalctl -u conmon-test

Describe the results you received:

Output has random newlines. For example:

Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/10.6
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/10.7
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/12.0
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/12.1
Feb 27 00:37:34 smithi189 conmon[11377]: /proc
Feb 27 00:37:34 smithi189 conmon[11377]: /bus/pci/ff/13.0
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/13.1
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/13.2
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/bus/pci/ff/13.3

and

Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/82/spurious
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/82/smp_affinity
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/82/affinity_hint
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/82/smp_affinity_list
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/82/effective_affinity
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/
Feb 27 00:37:34 smithi189 conmon[11377]: irq/82/effective_affinity_list
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/84
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/84/node
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/84/spurious
Feb 27 00:37:34 smithi189 conmon[11377]: /proc/irq/84/ioat-msix

The number of newlines seems to vary.. in my actual workload (not this test) I get a half dozen per line of output.

Describe the results you expected:

No inserted newlines.

Additional information you deem important (e.g. issue happens only occasionally):

Output of conmon --version:

conmon version 2.0.26
commit: 

Output of podman version:

Version:      3.0.1
API Version:  3.0.0
Go Version:   go1.15.2
Built:        Thu Jan  1 00:00:00 1970
OS/Arch:      linux/amd64

Package info (e.g. output of rpm -q podman or apt list podman):

root@smithi189:/etc/systemd/system# apt list conman
Listing... Done
conman/focal 0.2.7-1build2 amd64

I've seen the same with podman 2.2.1 on centos too.

[haircommander]

very odd, I am unable to reproduce this behavior on fedora 33 and systemd 246 (with conmon 2.0.26 + podman 3.0.0/2.2.1)

what is the host OS and systemd version?

[liewegas]

[root@dael system]# rpm -qa|grep conmon
conmon-2.0.22-3.module_el8.4.0+641+6116a774.x86_64
[root@dael system]# rpm -qa|grep podman
podman-3.0.0-0.21.module_el8.4.0+641+6116a774.x86_64
cockpit-podman-27.1-2.module_el8.4.0+641+6116a774.noarch
podman-catatonit-3.0.0-0.21.module_el8.4.0+641+6116a774.x86_64
[root@dael system]# cat /etc/os-release 
NAME="CentOS Stream"
VERSION="8"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="8"
PLATFORM_ID="platform:el8"
PRETTY_NAME="CentOS Stream 8"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:8"
HOME_URL="https://centos.org/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux 8"
REDHAT_SUPPORT_PRODUCT_VERSION="CentOS Stream"

just now but i've seen the same behavior on ubuntu too.

[liewegas]

also

[root@gnit system]# cat /etc/os-release 
NAME=Fedora
VERSION="32 (Server Edition)"
ID=fedora
VERSION_ID=32
VERSION_CODENAME=""
PLATFORM_ID="platform:f32"
PRETTY_NAME="Fedora 32 (Server Edition)"
ANSI_COLOR="0;34"
LOGO=fedora-logo-icon
CPE_NAME="cpe:/o:fedoraproject:fedora:32"
HOME_URL="https://fedoraproject.org/"
DOCUMENTATION_URL="https://docs.fedoraproject.org/en-US/fedora/f32/system-administrators-guide/"
SUPPORT_URL="https://fedoraproject.org/wiki/Communicating_and_getting_help"
BUG_REPORT_URL="https://bugzilla.redhat.com/"
REDHAT_BUGZILLA_PRODUCT="Fedora"
REDHAT_BUGZILLA_PRODUCT_VERSION=32
REDHAT_SUPPORT_PRODUCT="Fedora"
REDHAT_SUPPORT_PRODUCT_VERSION=32
PRIVACY_POLICY_URL="https://fedoraproject.org/wiki/Legal:PrivacyPolicy"
VARIANT="Server Edition"
VARIANT_ID=server
[root@gnit system]# rpm -qa | grep conmon
conmon-2.0.25-1.fc32.x86_64
[root@gnit system]# rpm -qa | grep podman
podman-plugins-2.2.1-1.fc32.x86_64
podman-2.2.1-1.fc32.x86_64

split output lines look like

...
Mar 01 12:31:03 gnit conmon[3957664]: /proc/irq/39/eno1-tx-0
Mar 01 12:31:03 gnit conmon[3957664]: /proc/irq/39/smp_affinity
Mar 01 12:31:03 gnit conmon[3957664]: /proc/irq/39/af
Mar 01 12:31:03 gnit conmon[3957664]: finity_hint
Mar 01 12:31:03 gnit conmon[3957664]: /proc/irq/39/smp_affinity_list
Mar 01 12:31:03 gnit conmon[3957664]: /proc/irq/39/effective_affinity
Mar 01 12:31:03 gnit conmon[3957664]: /proc/irq/39/effective_affinity_list
...

[huww98]

To reproduce, try this:

repo_242.cpp

#include <iostream>
#include <thread>

using namespace std;

int main() {
    cerr << "This should be";
    std::this_thread::sleep_for(1s);
    cerr << " on the same line" << endl;
    return 0;
}

Dockerfile

FROM buildpack-deps

COPY repo_242.cpp /repo_242.cpp
RUN g++ /repo_242.cpp -o /repo_242

ENTRYPOINT [ "/repo_242" ]

Run:

podman build . -t debug
podman run --rm --log-driver journald debug
journalctl -e _COMM=conmon

It will show something like:

Mar 02 08:34:59 gpu024 conmon[31672]: This should be
Mar 02 08:35:00 gpu024 conmon[31672]:  on the same line

[haircommander]

Okay I've also reproduced. Looking at the code, the fix is not trivial, and I don't think I have the cycles to tackle it right now. Does anyone want to take a shot? the root of the issue is we call a read() to read the stdout/err from the container, and that read doesn't wait for alll the output before returning. We'd need to implement some sort of buffer for the journald log driver to save the data until there's a newline (or find a better read() function, I don't know of any)

[rhatdan]

@giuseppe PTAL

[giuseppe]

is it what we want though?

With buffering we risk that a message that has no \n won't be printed, or be printed with delay

[liewegas]

In the example above, perhaps conmon should print Mar 02 08:34:59 gpu024 conmon[31672]: This should be, wait for more input, and then on the same line\n (i.e., do not insert \nMar 02 08:35:00 gpu024 conmon[31672]: in the middle of a line of output).

[huww98]

I think breaking a log line in the middle is unacceptable. This will break any existing log analysis tools, and make the log much harder for humans to interpret. We may need to flush the buffer when the program exits to avoid losing any message.

Anyway, if the stdout is connected directly to journald, journald will do buffering, too (Can be verified by running the above test program with systemd-run then check the log). It seems there is no easy way to avoid the delay in this case.

relevant lines from journald:
https://github.com/systemd/systemd/blob/9706d27cbeb66d7db425c959a8368e0aaded86d4/src/journal/journald-stream.c#L598-L605

[apollo13]

With buffering we risk that a message that has no \n won't be printed, or be printed with delay

True, but I think it would still be preferred over breaking up loglines. Any ideas on what docker does in this case?

[eburnette]

Are you sure the sleep is necessary to reproduce this? I found this ticket when researching split log lines in an openshift deployment, and mine are coming in the middle of atomic log calls like log("This is a long message").

[huww98]

No, it is not necessary. It just makes this easier to reproduce.