logging shows timestamp on each (control) character

[tobwen]

/kind bug

Description
Warning about a not-wellformed tag when parsing language.

Steps to reproduce the issue:
1st window: podman --log-level debug run -it --rm --read-only busybox sh (returns af49b446cf34...)
2nd window: podman logs -ft af49b446cf34

Describe the results you received:
019-03-01T04:53:12.517290493Z / # 2019-03-01T04:53:33.565339544Z 2019-03-01T04:53:33.626659047Z 2019-03-01T04:53:33.687523235Z 2019-03-01T04:53:33.708198635Z 2019-03-01T04:53:33.767723803Z 2019-03-01T04:53:33.827842903Z 2019-03-01T04:53:33.8487504Z 2019-03-01T04:53:33.908428489Z 2019-03-01T04:53:33.967692938Z 2019-03-01T04:53:33.991472119Z 2019-03-01T04:53:34.051359604Z 2019-03-01T04:53:34.111670887Z 2019-03-01T04:53:34.132360549Z 2019-03-01T04:53:34.192956436Z 2019-03-01T04:53:34.252802312Z 2019-03-01T04:53:34.334168968Z 2019-03-01T04:53:34.393670188Z 2019-03-01T04:53:34.487301865Z 2019-03-01T04:53:34.546584874Z 2019-03-01T04:54:08.993315313Z 2019-03-01T04:54:12.025890929Z 2019-03-01T04:54:16.420445Z 2019-03-01T04:54:16.947456176Z 2019-03-01T04:54:17.006923129Z 2019-03-01T04:54:17.139674739Z 2019-03-01T04:54:17.668521897Z 2019-03-01T04:54:17.728321548Z 2019-03-01T04:54:17.788493409Z 2019-03-01T04:54:17.849062338Z 2019-03-01T04:54:17.909409104Z 2019-03-01T04:54:17.969603528Z 2019-03-01T04:54:18.028831379Z 2019-03-01T04:54:18.087902127Z 2019-03-01T04:54:18.147525757Z 2019-03-01T04:55:03.98441397Z

While typing interactively inside the container, a timestamp get pasted on each keystroke.

Describe the results you expected:
One timestamp at each new line.

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

# locale
LANG=en_US.UTF-8
LANGUAGE=
LC_CTYPE="en_US.UTF-8"
LC_NUMERIC="en_US.UTF-8"
LC_TIME="en_US.UTF-8"
LC_COLLATE="en_US.UTF-8"
LC_MONETARY="en_US.UTF-8"
LC_MESSAGES="en_US.UTF-8"
LC_PAPER="en_US.UTF-8"
LC_NAME="en_US.UTF-8"
LC_ADDRESS="en_US.UTF-8"
LC_TELEPHONE="en_US.UTF-8"
LC_MEASUREMENT="en_US.UTF-8"
LC_IDENTIFICATION="en_US.UTF-8"
LC_ALL=

Output of podman version:

podman version 1.2.0-dev

Output of podman info --debug:

debug:
  compiler: gc
  git commit: 91373151335a84c5b78dbe46362cb678807d7509
  go version: go1.11.5
  podman version: 1.2.0-dev
host:
  BuildahVersion: 1.7.1
  Conmon:
    package: Unknown
    path: /usr/libexec/podman/conmon
    version: 'conmon version 1.14.0-dev, commit: 8de2ffc9e0809e98a72b93e35b74b8e5d4b0c29c'
  Distribution:
    distribution: debian
    version: "9"
  MemFree: 32108892160
  MemTotal: 38205562880
  OCIRuntime:
    package: Unknown
    path: /usr/bin/runc
    version: |-
      runc version 1.0.0-rc6+dev
      commit: f79e211b1d5763d25fb8debda70a764ca86a0f23
      spec: 1.0.1-dev
  SwapFree: 8586784768
  SwapTotal: 8586784768
  arch: amd64
  cpus: 8
  hostname: pgsql
  kernel: 4.19.0-0.bpo.2-amd64
  os: linux
  rootless: false
  uptime: 26h 48m 2.64s (Approximately 1.08 days)
insecure registries:
  registries: []
registries:
  registries:
  - docker.io
  - registry.fedoraproject.org
  - registry.access.redhat.com
store:
  ConfigFile: /etc/containers/storage.conf
  ContainerStore:
    number: 0
  GraphDriverName: overlay
  GraphOptions: null
  GraphRoot: /var/lib/containers/storage
  GraphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  ImageStore:
    number: 0
  RunRoot: /var/run/containers/storage
  VolumePath: /var/lib/containers/storage/volumes

Additional environment details (AWS, VirtualBox, physical, etc.):
VirtualBox 6 on Windows 10, running Debian 9 (stable)

[mheon]

I think this may be related to our handling of control characters with logs, but not certain yet.

[mheon]

Not control characters.

We seem to print each character as it comes in, with full timestamp, when timestamps are requested.

Probably an artifact of how we read from conmon?

It doesn't help that there are seemingly no newlines being printed, either.

[mheon]

Partial fix in #2513 - will greatly improve readability by ensuring that each timestamp is on a separate line. Does not deal with user input appearing one character at a time, a timestamp for each, though.

[tobwen]

@mheon Sorry for asking this, but could you right pad with zeros?

See the hashtag

2019-03-03T21:11:29.460432834-05:00 [root@d5003ddef6a5 /]# 
2019-03-03T21:11:29.60151061#-05:00 
2019-03-03T21:11:29.602178337-05:00

This might it even more readable, since the columns won't jump - or does this degrade performance too much?

[mheon]

@tobwen Went ahead and fixed the actual issue (the entire line should now appear under a single timestamp), so we should be good

[tobwen]

@mheon But can you right-pad the timestamp please? I hate jumping columns :D

[mheon]

Alternative question: why are some timestamps missing a digit? Is it omitting zeroes, or is there something else going on here?

I'll take a look

[mheon]

From the Go documentation: The RFC3339Nano format removes trailing zeros from the seconds field and thus may not sort correctly once formatted.

And that, there, explains our missing zeroes.

[tobwen]

@mheon
https://stackoverflow.com/questions/25637440/how-to-pad-a-number-with-zeros-when-printing

[mheon]

#2522 with the final formatting fix

[tobwen]

Thanks @-->-->----