podman run -t issues CRLF, making for confusing 'podman logs' output

[edsantiago]

In window 1 (needed to differentiate podman-remote from podman, in logs):

$ bin/podman system service --timeout=0

In window 2:

$ ./bin/podman run --name foo -t alpine sh -c 'echo 1;echo 2'
1
2
$ ./bin/podman logs foo|cat -vT
1^M       <--- CR
2^M
$ ./bin/podman-remote logs foo|cat -vT
1         <--- podman-remote emits those as LF; two lines for the price of one

2

$ for i in "" "-remote";do ./bin/podman$i logs foo|wc -l;done                                                                                         -
2
4

master @ defb754, but seems to be in v2.1 and possibly older as well. Root as well as rootless.

This is, I believe, causing flakes in a podman logs test

[zhangguanzhang]

same with #7196 (comment) containers/conmon#195 (comment)

[edsantiago]

Indeed - thank you. This was a very hard problem to search for!

[eiffel-fl]

If this issue can be a good first one then I can try to investigate on this issue but can someone give me more information (if someone has some)?
Indeed, I did not understand if this problem was fixed by #7660 and where exactly this problem occurs (podman-remote or conmon).

[zhangguanzhang]

If this issue can be a good first one then I can try to investigate on this issue but can someone give me more information (if someone has some)?
Indeed, I did not understand if this problem was fixed by #7660 and where exactly this problem occurs (podman-remote or conmon).

The root cause is this

[psakar@localhost podman]$ podman run --rm --tty busybox echo 1 | cat -A
1^M$
    [psakar@localhost podman]$ podman run --rm --tty busybox echo 1 ; echo 2 | cat -A
1
2$
[psakar@localhost podman]$ 

-t will trigger it

[eiffel-fl]

Thank you, I do not promise to come back with a PR but I will investigate on this to try to narrow the root cause.

[eiffel-fl]

Unfortunately, I do not come with a solution and maybe more problems...

First, I printed buf in redirectResponseToOutputStreams after it was read with conn.Read(buf), for this example ./bin/podman --log-level debug run --rm --tty debian sh -c 'echo 1; echo 2' | cat -A I got the following from debug log:

...
buffer is [2 49 13 10 50 13 10]
...

Where 2 is the pipe where to write, 49 is ASCII code of '1', 13 that of \r and 10 that of \n.
Of course, running the above command without --tty remove the \r from buf.

So, I search what writes conn.
I looked into conmon code and after call to read into read_stdio I printed bufwhich gives (for the same command):

...
Read 1#015#0122#015#012 from read_stdio (10)
...

Here 1 is 1, 015 is 13 so \r and 012 is 10 so \n.
Of course, without --tty it removes 015 from this output.

My understanding of interactions between podman, conmon and crun is still limited.
If I understand well, podman is just the command line or the thing the user interacts with.
conmon can act as a daemon and comes after podman.
Finally, crun receives order from something and create cgroup by playing with the sysfs.

So, in this case, what is writing mainfd_stdout? Is it crun (I searched slightly and found nothing about this in crun code)? Or is it the process inside the container?

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[rhatdan]

@haircommander @giuseppe PTAL
Could you answer @eiffel-fl questions?

@eiffel-fl the problem is in both the cases of podman-remote and podman conmon/crun/PID1 are working the same way. The problem being reported here is that when podman-remote logs reports back, it seems to be confused.

[rhatdan]

Going back to @edsantiago original tests, I run

# podman run --tty --rm busybox echo 1; echo 2 | cat -vT
# podman-remote run --name foo2 -t alpine sh -c 'echo 1;echo 2'

And then look at the log files on disk and they are identical

# cat $(podman inspect --format '{{ .LogPath }}' foo1)
2020-11-08T07:08:05.549884452-05:00 stdout F 1
2020-11-08T07:08:05.549884452-05:00 stdout F 2
# cat $(podman inspect --format '{{ .LogPath }}' foo2)
2020-11-08T07:08:13.673393569-05:00 stdout F 1
2020-11-08T07:08:13.673393569-05:00 stdout F 2

So this is not an issue with running the containers, but viewing the container logs.

# podman logs foo1
1
2
# podman-remote logs foo1
1

2

@eiffel-fl I think you are exposing a different bug where the final character printed via podman run is different then podman-remote run. But that should be opened as a different issue.

Bottom line @edsantiago is reporting a bug in podman-remote logs

[rhatdan]

# cat -A $(podman inspect --format '{{ .LogPath }}' foo1)
2020-11-08T07:08:05.549884452-05:00 stdout F 1^M$
2020-11-08T07:08:05.549884452-05:00 stdout F 2^M$
# cat -A $(podman inspect --format '{{ .LogPath }}' foo2)
2020-11-08T07:08:13.673393569-05:00 stdout F 1^M$
2020-11-08T07:08:13.673393569-05:00 stdout F 2^M$

[eiffel-fl]

Hi @rhatdan.

I quickly read your messages, I will investigate more on the CRLF bug next week, unfortunately I am bit busy now...
By the way, it is good that you fixed the bug in podman log!
Moreover, with your precisions I will be able to search more precisely for the bug, thank you!

Best regards.

[rhatdan]

@eiffel-fl I think @jwhonce might have fixed your issue in podman-remote overlay. It definitely fixed this issue.

[eiffel-fl]

If this issue is fixed it is perfect! podman can advance and this is the important!

[rhatdan]

Awesome.