The StartDate of an exited container is later than the FinishedAt date.

[MetalArend]

Description

After a container has succesfully initiated and exited, sometimes the StartedAt date is being later than the FinishedAt date.

Reproduce

docker run --name=test20230501 --detach alpine sh -c "echo 'done'"
docker wait test20230501
docker inspect --format "StartedAt: {{ .State.StartedAt }}, FinishedAt: {{ .State.FinishedAt }}" test20230501

// This messes with the logs being output
docker logs test20230501
docker logs --since "$(docker inspect --format "{{ .State.StartedAt }}" test20230501)" test20230501

docker rm test20230501 > /dev/null

Expected behavior

The StartedAt time should always be before the FinishedAt time.

docker version

Client: Docker Engine - Community
 Version:           23.0.5
 API version:       1.42
 Go version:        go1.19.8
 Git commit:        bc4487a
 Built:             Wed Apr 26 16:21:07 2023
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          23.0.5
  API version:      1.42 (minimum version 1.12)
  Go version:       go1.19.8
  Git commit:       94d3ad6
  Built:            Wed Apr 26 16:21:07 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.20
  GitCommit:        2806fc1057397dbaeefbea0e4e17bddfbd388f38
 runc:
  Version:          1.1.5
  GitCommit:        v1.1.5-0-gf19387a
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.10.4
    Path:     /usr/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.17.3
    Path:     /usr/libexec/docker/cli-plugins/docker-compose
  scan: Docker Scan (Docker Inc.)
    Version:  v0.23.0
    Path:     /usr/libexec/docker/cli-plugins/docker-scan

Server:
 Containers: 23
  Running: 0
  Paused: 0
  Stopped: 23
 Images: 53
 Server Version: 23.0.5
 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 logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 2806fc1057397dbaeefbea0e4e17bddfbd388f38
 runc version: v1.1.5-0-gf19387a
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 5.19.0-41-generic
 Operating System: Ubuntu 22.04.2 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 15.29GiB
 Name: mammi
 ID: ZECH:RGJA:RAZH:K6SZ:L4PM:WQOR:RZQP:F3KE:EMO4:OUFC:RUE6:3CT3
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional Info

Output of the reproduction script:

834f698eeb90b32e96ac7c19085d7459198d187ea13e3ef5c783da4f78499ec8
0 // exit code, so the container exited
StartedAt: 2023-05-01T14:33:53.017722357Z, FinishedAt: 2023-05-01T14:33:53.022160634Z // this one is correct
done
done // twice the output, for both docker logs commands

Second run

f0eb39943010e8bf01d9a1866bfdf89e22e43c08cc68c4d637621226cef71bf4
0 // exit code, so the container exited
StartedAt: 2023-05-01T14:35:01.954531896Z, FinishedAt: 2023-05-01T14:35:01.954399908Z // StartedAt is slightly later than FinishedAt
done // only once the output

[cpuguy83]

Ah interesting.
It looks like the issue is that it sets the started at time (and generate said time) after it is started meanwhile the exit event may occur before that start time is even generated.

moby/daemon/start.go

Line 205 in 0ea9305

container.SetRunning(ctr, tsk, true)

[cpuguy83]

I think one potential way to fix without rewriting the whole thing is to generate a start time before calling start and pass that down to SetRunning.