Why is the output of `docker logs -t` not the same for different containers?

Docker Engine General
1

When I use docker logs -t with my node:20-alpine image container, a formatted timestamp gets added

# docker logs node-sync 2>&1 | tail -1.  # no -t
sync() return items 2733 action sendlog

# docker logs -t node-sync 2>&1 | tail -1.  # with -t
2024-12-12T09:00:34.111148690Z sync() return items 2733 action sendlog

When I use docker logs -t with mcr.microsoft.com/mssql/server:2022-latest image container, the timestamp is not added, but it’s showing one supplied by the container app:

# docker logs db-sqlserver-1 2>&1 | tail -1  # no -t
2024-12-12 09:51:51.05 spid55      Using 'xplog70.dll' version '2022.160.4165' to execute extended stored procedure 'xp_msver'. This is an informational message only; no user action is required.

# docker logs -t db-sqlserver-1 2>&1 | tail -1  # with -t
2024-12-12 09:51:51.05 spid55      Using 'xplog70.dll' version '2022.160.4165' to execute extended stored procedure 'xp_msver'. This is an informational message only; no user action is required.

Why is the output different, why is docker logs not respecting -t for the same formatted timestamp output?

Both containers are configured with same json-file logging, when checking with inspect:

            "LogConfig": {
                "Type": "json-file",
                "Config": {}
            },

System Info

# docker version
Client: Docker Engine - Community
 Version:           27.4.0
 API version:       1.47
 Go version:        go1.22.10
 Git commit:        bde2b89
 Built:             Sat Dec  7 10:38:55 2024
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          27.4.0
  API version:      1.47 (minimum version 1.24)
  Go version:       go1.22.10
  Git commit:       92a8393
  Built:            Sat Dec  7 10:38:55 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.7.24
  GitCommit:        88bf19b2105c8b17560993bee28a01ddc2f97182
 runc:
  Version:          1.2.2
  GitCommit:        v1.2.2-0-g7cb3632
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

# docker info
Client: Docker Engine - Community
 Version:    27.4.0
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.19.2
    Path:     /usr/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.31.0
    Path:     /usr/libexec/docker/cli-plugins/docker-compose

Server:
 Containers: 17
  Running: 16
  Paused: 0
  Stopped: 1
 Images: 51
 Server Version: 27.4.0
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 88bf19b2105c8b17560993bee28a01ddc2f97182
 runc version: v1.2.2-0-g7cb3632
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.8.0-50-generic
 Operating System: Ubuntu 24.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 15.25GiB
 Name: myhost
 ID: d0b46f47-c57e-4b70-bdfe-39a9f8e01234
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled
2

IT is because the timestamp is actually added, but the log lines produced by the container from that image start with a carriage return character so the log line added after it overrides the timestamp. It loks like a bug. Docker should remove the carriage return character or at least treat replace it with a Linux-compatible line break. You can reproduce it this way:

docker run -d --name logtest2 bash echo -e "\rhello"

docker logs -t logtest2

Output

hello12-12T10:28:46.857325000Z
1 Like
3

I may be misunderstanding but it does not look like what’s happening here

I think they’re asking about the timestamps still being there for the second container, even when they do not specify -t
Edit: Rather, the timestamps are written in the container log, but Docker timestamps do not show with -t

4

I want the full Docker timestamp when using -t (…T…Z):

But in this case it’s just an internal timestamp, not the Docker one:

5

That makes sense, especially as it is a Microsoft container, they probably love \r\n :sweat_smile:

6

Yes, they are using that too, but also startng almost all lines with a \r. I checked the json file as root. The first couple of lines were not started with carriage return so if you can scroll back to the beginning of the container logs, you should find the docker-provided timestamp, but not later.

7

I created an issue on Moby Github.

1 Like