strip cariage-returns in log-entries (added by TTY)

[thaJeztah]

- What I did

Updated daemon/logger/copier.go to remove trailing CR's (\r).

fixes #15722

- How to verify it

When running a container with a tty (-t / -tty), the TTY automatically converts LF to CRLF.
Strip those trailing CR's as they are not part of the original output.

This also prevents the systemd journal from treating those log-entries as "blob data":

  docker run -it --rm --log-driver=journald --name=tester hello-world

  journalctl CONTAINER_NAME=tester
  -- Logs begin at Wed 2016-04-27 18:40:30 EDT, end at Mon 2016-05-02 07:45:16 EDT. --
  May 02 07:39:05 ubuntu-2gb-ams3-01 docker[27908]: [1B blob data]
  May 02 07:39:05 ubuntu-2gb-ams3-01 docker[27908]: [19B blob data]
  ...
  ...

After this change is applied;

  docker run -it --rm --log-driver=journald --name=tester hello-world

  journalctl CONTAINER_NAME=tester
  -- Logs begin at Wed 2016-04-27 18:40:30 EDT, end at Mon 2016-05-02 07:45:16 EDT. --
  May 02 07:40:55 ubuntu-2gb-ams3-01 dockerd[28324]:
  May 02 07:40:55 ubuntu-2gb-ams3-01 dockerd[28324]: Hello from Docker.
  May 02 07:40:55 ubuntu-2gb-ams3-01 dockerd[28324]: This message shows that your installation appears to be working correctly.
  ...
  ...

Finally, this upates unit tests, to check if trailing CR's are stripped, and adds new tests to test logging of long log-lines (without newlines), and trailing log- lines.

- Description for the changelog

Fixed systemd journal treating container log entries as "blob data" if the container is started with a TTY (-t)

- A picture of a cute animal (not mandatory but encouraged)

[thaJeztah]

ping @LK4D4 @nalind @bobrik 😄

[bobrik]

LGTM

[thaJeztah]

hm, looks like win2lin is having memory issues;
https://jenkins.dockerproject.org/job/Docker-PRs-Win2Lin/25484/console

13:34:01 Building: bundles/1.12.0-dev/binary-daemon/dockerd-1.12.0-dev
13:44:32 # github.com/docker/docker/cmd/dockerd
13:44:32 /usr/local/go/pkg/tool/linux_amd64/link: running gcc failed: fork/exec /usr/bin/gcc: cannot allocate memory

[ashb]

Any progress on this? I guess the test failure was just a CI issue and not related to this change?

[thaJeztah]

It just needs a review

[tonistiigi]

@thaJeztah Maybe the trimming could happen in the journald logdriver instead?

[thaJeztah]

@tonistiigi given that these extra newlines are not in the message that's logged, but added by the TTY, I thought it would make sense to strip them for any log-driver (same as we strip the \n that is added as well)

[tonistiigi]

@thaJeztah Idk, I was just thinking that if someone wants to play back the logs(joining with nl) they might expect to get the real output of the app. And that includes cr in tty mode.

[thaJeztah]

Well, they can join with \r\n 😄. idk, is there a known case where the output of this is played back.

ping @sirupsen perhaps you have some thoughts on this, given that you do a lot with logging 😇

[tonistiigi]

@thaJeztah Yes, but we don't store the separation character(s) together with the log data.

[ashb]

I imagine to most people the "\r" is a surprise, at least it was to me.

To me (and everyone I've worked with) the point of a logging driver is so that you can ship it to Kibana or some other aggregator - which will do it's own multi-message combining if need (i.e. to get java stacktraces back to a single log event) so including things other than the direct print is actively unhelpful. (i.e. the "\r" is a side-effect, not something the program chose to print itself)

[LK4D4]

@thaJeztah I don't understand where we here :/

[thaJeztah]

@LK4D4 discussion is if the \r that's automatically added by TTY should be considered part of the logged message, or not. I'm not sure what's a regular approach for that (strip it / keep it)

[LK4D4]

@thaJeztah I think we should strip, I move to design-review though to hear other opinions.

[tonistiigi]

Don't want to block this as it is not that important. The main reason I was for keeping it was that if someone does

docker run -it --name foo busybox ls -l > foo1.txt
docker logs foo > foo2.txt

I'd expect the files to match.

[thaJeztah]

@LK4D4 @tonistiigi @nalind PTAL

Rebased this PR, to accomodate for the changes in #22982.
I rewrote stripping the suffix to make use of the p and q indexes, instead of bytes.TrimSuffix() to prevent the extra overhead of finding/calculating the index of the CR to strip.

I also added an extra unit-test that tests handling of trailing lines (without line-ending), and long lines (> bufSize), which was implemented in #22982 (513ec73),
but untested so far.

[crosbymichael]

I don't know if we should be modifying the log data. tty output is blob data, its not plain text that is why it has to have the tty interpret it. Why cannot log drivers just log what they get and not modify it? I think this is a bad idea to do.

[thaJeztah]

@crosbymichael wondering if we should also keep the \n in the logs then; we're currently stripping it. Now that log entries are either added if a newline is found or if it reaches buffer length, reconstructing the original output won't be possible.

[bobrik]

@crosbymichael, somebody has to strip trailing \r: systemd/systemd#3416 (comment)

[nalind]

@thaJeztah We should be logging a "partial" attribute to track if the incoming message was only a partial line, and consulting that in the "logs" handler to add newlines at only the right places, to make the output that the client sees look the same as what the docker daemon received. If you're seeing different behavior, I can have another look at it.

[thaJeztah]

@nalind ah, didn't know the partial property was used for that; I see it being set in https://github.com/docker/docker/pull/22982/files#diff-0e0dba78caf4a57795625b5ce9943c9eR100, so probably not an issue then.

@nalind what's your opinion on this change; strip / don't strip?

[nalind]

@thaJeztah Personally I lean slightly toward leaving the behavior unchanged while updating the docs to suggest using journalctl --all. I'm basing that on being able to describe the output of docker logs as being byte-for-byte what the daemon got from the container, with an asterisk noting that the container output is affected by terminal modes if a pseudo-tty is being used. But that's kind of a mouthful, and I can also see the appeal of trying to make the observed output the same regardless of whether or not there's a pseudo-tty.
The current patch LGTM, FWIW.

[crosbymichael]

@bobrik since they merged that change shouldn't we just bump the systemd package that we depend on and it will strip for us?

[tiborvass]

@crosbymichael 👍

[thaJeztah]

Following the discussion above, I agree with not stripping the \r, however, I can open a PR just for the extra test that tests the buffer, if you think it's good to have

[crosbymichael]

no, the systemd lib that we use was updated to strip it so we just need to bump it's version and then it will solve the problem.

[bobrik]

@crosbymichael can you link to the commit in systemd lib? I don't see anything here:

• https://github.com/coreos/go-systemd/blob/bfdc81d0d7e0fb19447b08571f63b774495251ce/journal/journal.go

[crosbymichael]

@bobrik the change was made in the C lib. https://github.com/systemd/systemd/pull/3636/files

[nalind]

@crosbymichael That's part of the writing API, though, and the log driver only calls into the C library for reading from the journal. The driver handles writes by calling github.com/coreos/go-systemd/journal, which writes data directly to the journald socket.

[crosbymichael]

@nalind ok, so we need to make an update to go-systemd then

[LK4D4]

@thaJeztah mind closing it and open update PR with test?

[thaJeztah]

A fix for the newlines will be coming through RunC; opencontainers/runc#1146 (thanks @cyphar), so I'll open a new PR with just the test

[thaJeztah]

@LK4D4 @crosbymichael @nalind opened #28035 for just the tests