Docker service logs are not returned in chronological order

[pveierland]

Description

docker service logs <service> does not return results in chronological order.

Reproduce

1. Run docker service logs --timestamps <service>.

Example output:

2024-04-02T02:22:14.799036157Z service | bad service
2024-04-02T02:23:06.141097002Z service | bad service
2024-04-02T02:22:48.642065164Z service | good service
2024-04-02T02:22:14.799081539Z service | bad service
2024-04-02T02:23:07.541907132Z service | bad service
2024-04-02T02:22:20.755475776Z service | bad service

Expected behavior

The expected results from the command is to see log results in chronological order as determined by their timestamps.

• Showing log results in non-chronological order can be highly distracting during debugging, as something that may appear to be a fault has already been resolved, except that the erroneous condition is being shown last in the log output.
• Although the docker internals may store the log results in non-chronological order, the docker cli should have the functionality to perform sorting of log results before/while displaying them.
• The docker cli should have the sorting functionality built-in, either as default or behind a flag. It should not be necessary to patch the docker cli using shell functions to achieve this functionality.
• All relevant log commands should be updated with the same functionality.

docker version

Client: Docker Engine - Community
 Version:           26.0.0
 API version:       1.45
 Go version:        go1.21.8
 Git commit:        2ae903e
 Built:             Wed Mar 20 15:17:48 2024
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          26.0.0
  API version:      1.45 (minimum version 1.24)
  Go version:       go1.21.8
  Git commit:       8b79278
  Built:            Wed Mar 20 15:17:48 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.28
  GitCommit:        ae07eda36dd25f8a1b98dfbf587313b99c0190bb
 runc:
  Version:          1.1.12
  GitCommit:        v1.1.12-0-g51d5e94
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client: Docker Engine - Community
 Version:    26.0.0
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.13.1
    Path:     /usr/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.25.0
    Path:     /usr/libexec/docker/cli-plugins/docker-compose

Server:
 Containers: 27
  Running: 19
  Paused: 0
  Stopped: 8
 Images: 31
 Server Version: 26.0.0
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: false
  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: active
  NodeID: gf1ty2kauu87qxsgb10p0neup
  Is Manager: true
  ClusterID: ddk2cf6pgp8wt27kje55gibgt
  Managers: 1
  Nodes: 2
  Default Address Pool: 10.0.0.0/8
  SubnetSize: 24
  Data Path Port: 4789
  Orchestration:
   Task History Retention Limit: 5
  Raft:
   Snapshot Interval: 10000
   Number of Old Snapshots to Retain: 0
   Heartbeat Tick: 1
   Election Tick: 10
  Dispatcher:
   Heartbeat Period: 5 seconds
  CA Configuration:
   Expiry Duration: 3 months
   Force Rotate: 0
  Autolock Managers: false
  Root Rotation In Progress: false
  Node Address: 10.1.0.4
  Manager Addresses:
   10.1.0.4:2377
 Runtimes: runc io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: ae07eda36dd25f8a1b98dfbf587313b99c0190bb
 runc version: v1.1.12-0-g51d5e94
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.5.0-1017-azure
 Operating System: Ubuntu 22.04.4 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 7.743GiB
 Name: teleagent-prod-master-1
 ID: 4cb928b4-b500-47e2-affe-bda3001c10b3
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional Info

No response

[thaJeztah]

Thanks for reporting

I'm not sure if this is possible to fix, or at least this would require careful consideration; when running swarm services, those services are distributed in the cluster, and may be running on different nodes. In addition, the logs printed can originate from STDOUT and STDERR, one of which is buffered, the other is not; for the latter one there's a (still open) ticket; moby/moby#31706

The docker service logs will print such logs when they arrive which, in a distributed system, may mean that log entries from different nodes may arrive at different moment. So to sort these log entries, all log-entries would have to be buffered before they can be sorted, which would only be possible in the "one-off" (without --follow) case, and in that case would still have a potential of requiring a large amount of memory to be used (buffering all log entries). For the --folow case, things will be more complicated, as there's no real way to predict when new log-entries arrive (if any) from all instances of a service.

For debugging purposes, you could consider using sort to sort the output to see if that addresses your immediate issue;

docker service logs --timestamps myservice 2>&1 | sort

For collecting logs of your swarm cluster, using a log-aggregator can also be a good option; in that case logs from the cluster can be collected centrally (https://docs.docker.com/config/containers/logging/configure/)