Repository: moby/moby (language: go)

Issue:
The StartDate of an exited container is later than the FinishedAt date.
### 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

```bash
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

```bash
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
```


Discussion / hints:
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.

https://github.com/moby/moby/blob/0ea9305f99566cb8adf36ff04a28b9e949999254/daemon/start.go#L205
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`.

Fix patch:
diff --git a/container/state.go b/container/state.go
index cdf88fe371f75..b3bba4ba2bf9e 100644
--- a/container/state.go
+++ b/container/state.go
@@ -268,13 +268,23 @@ func (s *State) SetExitCode(ec int) {
 	s.ExitCodeValue = ec
 }
 
-// SetRunning sets the state of the container to "running".
-func (s *State) SetRunning(ctr libcontainerdtypes.Container, tsk libcontainerdtypes.Task, initial bool) {
+// SetRunning sets the running state along with StartedAt time.
+func (s *State) SetRunning(ctr libcontainerdtypes.Container, tsk libcontainerdtypes.Task, start time.Time) {
+	s.setRunning(ctr, tsk, &start)
+}
+
+// SetRunningExternal sets the running state without setting the `StartedAt` time (used for containers not started by Docker instead of SetRunning).
+func (s *State) SetRunningExternal(ctr libcontainerdtypes.Container, tsk libcontainerdtypes.Task) {
+	s.setRunning(ctr, tsk, nil)
+}
+
+// setRunning sets the state of the container to "running".
+func (s *State) setRunning(ctr libcontainerdtypes.Container, tsk libcontainerdtypes.Task, start *time.Time) {
 	s.ErrorMsg = ""
 	s.Paused = false
 	s.Running = true
 	s.Restarting = false
-	if initial {
+	if start != nil {
 		s.Paused = false
 	}
 	s.ExitCodeValue = 0
@@ -286,8 +296,8 @@ func (s *State) SetRunning(ctr libcontainerdtypes.Container, tsk libcontainerdty
 		s.Pid = 0
 	}
 	s.OOMKilled = false
-	if initial {
-		s.StartedAt = time.Now().UTC()
+	if start != nil {
+		s.StartedAt = start.UTC()
 	}
 }
 
diff --git a/daemon/monitor.go b/daemon/monitor.go
index 4734fe45e5148..3cad773e14f05 100644
--- a/daemon/monitor.go
+++ b/daemon/monitor.go
@@ -254,7 +254,7 @@ func (daemon *Daemon) ProcessEvent(id string, e libcontainerdtypes.EventType, ei
 				}
 				return err
 			}
-			c.SetRunning(ctr, tsk, false)
+			c.SetRunningExternal(ctr, tsk)
 			c.HasBeenManuallyStopped = false
 			c.HasBeenStartedBefore = true
 			daemon.setStateCounter(c)
diff --git a/daemon/start.go b/daemon/start.go
index 948f458c0e45c..b55062c61940a 100644
--- a/daemon/start.go
+++ b/daemon/start.go
@@ -199,6 +199,7 @@ func (daemon *Daemon) containerStart(ctx context.Context, daemonCfg *configStore
 		return setExitCodeFromError(container.SetExitCode, err)
 	}
 
+	startupTime := time.Now()
 	// TODO(mlaventure): we need to specify checkpoint options here
 	tsk, err := ctr.Start(context.TODO(), // Passing ctx to ctr.Start caused integration tests to be stuck in the cleanup phase
 		checkpointDir, container.StreamConfig.Stdin() != nil || container.Config.Tty,
@@ -212,7 +213,7 @@ func (daemon *Daemon) containerStart(ctx context.Context, daemonCfg *configStore
 	}
 
 	container.HasBeenManuallyRestarted = false
-	container.SetRunning(ctr, tsk, true)
+	container.SetRunning(ctr, tsk, startupTime)
 	container.HasBeenStartedBefore = true
 	daemon.setStateCounter(container)
 


Test patch:
diff --git a/container/state_test.go b/container/state_test.go
index f4f22f70d6841..2043a660535c9 100644
--- a/container/state_test.go
+++ b/container/state_test.go
@@ -68,7 +68,7 @@ func TestStateRunStop(t *testing.T) {
 
 		// Set the state to "Running".
 		s.Lock()
-		s.SetRunning(nil, &mockTask{pid: uint32(i)}, true)
+		s.SetRunning(nil, &mockTask{pid: uint32(i)}, time.Now())
 		s.Unlock()
 
 		// Assert desired state.
@@ -133,7 +133,7 @@ func TestStateTimeoutWait(t *testing.T) {
 	s := NewState()
 
 	s.Lock()
-	s.SetRunning(nil, nil, true)
+	s.SetRunning(nil, nil, time.Now())
 	s.Unlock()
 
 	// Start a wait with a timeout.
@@ -182,7 +182,7 @@ func TestCorrectStateWaitResultAfterRestart(t *testing.T) {
 	s := NewState()
 
 	s.Lock()
-	s.SetRunning(nil, nil, true)
+	s.SetRunning(nil, nil, time.Now())
 	s.Unlock()
 
 	waitC := s.Wait(context.Background(), WaitConditionNotRunning)
@@ -193,7 +193,7 @@ func TestCorrectStateWaitResultAfterRestart(t *testing.T) {
 	s.Unlock()
 
 	s.Lock()
-	s.SetRunning(nil, nil, true)
+	s.SetRunning(nil, nil, time.Now())
 	s.Unlock()
 
 	got := <-waitC
diff --git a/daemon/delete_test.go b/daemon/delete_test.go
index 9733498cac4ea..fe727edcdf526 100644
--- a/daemon/delete_test.go
+++ b/daemon/delete_test.go
@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"os"
 	"testing"
+	"time"
 
 	"github.com/docker/docker/api/types/backend"
 	containertypes "github.com/docker/docker/api/types/container"
@@ -52,7 +53,7 @@ func TestContainerDelete(t *testing.T) {
 			errMsg: "container is restarting: stop the container before removing or force remove",
 			initContainer: func() *container.Container {
 				c := newContainerWithState(container.NewState())
-				c.SetRunning(nil, nil, true)
+				c.SetRunning(nil, nil, time.Now())
 				c.SetRestarting(&container.ExitStatus{})
 				return c
 			},
diff --git a/integration/container/daemon_linux_test.go b/integration/container/daemon_linux_test.go
index 41bddd96f9f2b..3b60a39d6848e 100644
--- a/integration/container/daemon_linux_test.go
+++ b/integration/container/daemon_linux_test.go
@@ -256,7 +256,7 @@ func TestHardRestartWhenContainerIsRunning(t *testing.T) {
 
 	for _, id := range []string{noPolicy, onFailure} {
 		d.TamperWithContainerConfig(t, id, func(c *realcontainer.Container) {
-			c.SetRunning(nil, nil, true)
+			c.SetRunning(nil, nil, time.Now())
 			c.HasBeenStartedBefore = true
 		})
 	}