Repository: moby/moby (language: go)

Issue:
Syslog entry: "superfluous response.WriteHeader call" in Docker 25.x
### Description

When retrieving the logs for a container (via `docker logs` for example), a log entry is made in `/var/log/syslog`:

```
Feb 26 16:54:53 be-docker dockerd[410]: 2024/02/26 16:54:53 http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*respWriterWrapper).WriteHeader (wrap.go:98)
```

This appears to have been introduced alongside the OpenTelemetry addition in Docker 25.0.0 as this log message is not created on previous versions of Docker (for example 24.0.6).

### Reproduce

1. Install Docker 25.x
2. Create a container (any will do)
3. Monitor `/var/log/syslog` (via `tail -f` for example)
4. While monitoring, run `docker logs containername` 
5. Note the entry in syslog

### Expected behavior

No "superfluous response" message.

### docker version

```bash
Client: Docker Engine - Community
 Version:           25.0.3
 API version:       1.44
 Go version:        go1.21.6
 Git commit:        4debf41
 Built:             Tue Feb  6 21:14:17 2024
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          25.0.3
  API version:      1.44 (minimum version 1.24)
  Go version:       go1.21.6
  Git commit:       f417435
  Built:            Tue Feb  6 21:14:17 2024
  OS/Arch:          linux/amd64
  Experimental:     true
 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

```bash
Client: Docker Engine - Community
 Version:    25.0.3
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.12.1
    Path:     /usr/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.24.5
    Path:     /usr/libexec/docker/cli-plugins/docker-compose

Server:
 Containers: 10
  Running: 7
  Paused: 0
  Stopped: 3
 Images: 33
 Server Version: 25.0.3
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: gelf
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 Swarm: inactive
 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
 Kernel Version: 5.4.0-171-generic
 Operating System: Ubuntu 20.04.6 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 1.925GiB
 Name: be-docker
 ID: HJDW:MIDK:VVF2:ZZC5:CCHA:6KOE:CCZU:TXJ3:2YUM:2KHI:NKJX:7ID3
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Username: jcarppe
 Experimental: true
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No swap limit support
```


### Additional Info

While a single log line entry doesn't seem like much, when using a separate tool (such as Portainer) to view container logs that auto-refreshes, this can result in repeated syslog entries.


Discussion / hints:
docker compose stats will also create syslog messages
This line currently accounts for 8% of my total server syslog/journal logs (out of about 120k lines).
Please either suppress it if it's innocuous or fix the underlying problem, it's hard to look at system logs with this spam (journalctl does not support filters; inverse grepping works but breaks --follow for example).
Wonder if this is a bug in OTEL here; I see it keeps track whether it already wrote headers, but then proceeds calling `w.ResponseWriter.WriteHeader(statusCode)` to write headers anyway; https://github.com/moby/moby/blob/330d777c53fbbf734178d6a35c9dc0a5070ba4ac/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/wrap.go#L93-L99

It looks like `Write` has a protection for that (it will only call `WriteHeader` if it wasn't written yet), but the same does not apply when `WriteHeader` is called directly (see above); https://github.com/moby/moby/blob/330d777c53fbbf734178d6a35c9dc0a5070ba4ac/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/wrap.go#L76-L80

That said, the log itself seems to be coming from `het/http` in Go stdlib from either one of these two, and stdlib doesn't _prevent_ it being called multiple times, so maybe in this case something hits the wrapper's `Write()` (writing the header), before existing code is executed and calling `WriteHeader()` :thinking:;

- https://github.com/golang/go/blob/a73af5d91c4c335fb44ae99517d4c41d5f3960e0/src/net/http/server.go#L1157
- https://github.com/golang/go/blob/a73af5d91c4c335fb44ae99517d4c41d5f3960e0/src/net/http/server.go#L3675

It would be nice to have a way to disable telemetry either. 
I didn't find a way to do that.
Hello, 

we have the same problem with this message since Docker 25. I tried to update to 26 but no changes:

`http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*respWriterWrapper).WriteHeader (wrap.go:98)`

There are about 50000 Lines a day spamming the Syslog.

**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: 48
  Running: 26
  Paused: 0
  Stopped: 22
 Images: 36
 Server Version: 26.0.0
 Storage Driver: overlay2
  Backing Filesystem: xfs
  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: 63qhzfb68bifh1unoiwmp3b42
  Is Manager: true
  ClusterID: dwdlo1iwtmf1nojlzcjo4z620
  Managers: 3
  Nodes: 3
  Default Address Pool: 10.0.0.0/8  
  SubnetSize: 16
  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: 30 seconds
  CA Configuration:
   Expiry Duration: 3 months
   Force Rotate: 0
  Autolock Managers: false
  Root Rotation In Progress: false
  Node Address: xxxx
  Manager Addresses:
   xxxxx:2377
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: ae07eda36dd25f8a1b98dfbf587313b99c0190bb
 runc version: v1.1.12-0-g51d5e94
 init version: de40ad0
 Security Options:
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 5.15.0-204.147.6.2.el9uek.x86_64
 Operating System: Oracle Linux Server 9.3
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 11.24GiB
 Name: xxxx
 ID: 24a66a42-19c5-4935-aa24-f50c19f4c381
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false
```

**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:20:36 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:18:58 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
```

**Additional Info**
We are shipping our logs with a fluentbit container to a grafana/loki instance
Telemetry is disabled by default.
Its only enabled if the OTLP env vars are set.
IIRC you should also be able to forcibly disable it with `OTEL_SDK_DISABLED=1`, although I don't know if this may be triggered even with tracing disabled (or effectively no-ops).
> IIRC you should also be able to forcibly disable it with `OTEL_SDK_DISABLED=1`, although I don't know if this may be triggered even with tracing disabled (or effectively no-ops).

Not in Go 😢 : open-telemetry/opentelemetry-go#3559
our tracing code supports this explicitly.
If the var is set we don't setup tracing.
Ah, I see. Thank you!

But as [you suspected](https://github.com/moby/moby/issues/47448#issuecomment-2038126365), it doesn't seem to have any effect.
BTW, in our environment, those syslog entries seem to happen every time, a container does a health check.
I've done a bit of research into this issue with the help of @laurazard, here's the situation so far:

What seems to be happening is that the OTEL wrapper is unaware of any calls that are made to the underlying ResponseWriter.WriteHeader() func it is wrapping.   

In scenarios where the underlying `ResponseWriter` already has it's header set (and, therefore, `wroteHeader == true` in the underlying net/http `response` struct):

- The wrapper's safety check seen here will fail, meaning a call to the wrapper's `Write()` func will end up calling the wrapper's `WriteHeader()` func

    https://github.com/moby/moby/blob/f9dfd139ec0d169cf0cf6b534fad7d98137fcc23/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/wrap.go#L76-L79
 
- The wrapper's `WriteHeader()` func is responsible for setting `w.wroteHeader = true` 
  (**Note**: this value is set on the otel `respWriterWrapper` struct)  
    https://github.com/moby/moby/blob/f9dfd139ec0d169cf0cf6b534fad7d98137fcc23/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/wrap.go#L93-L99
    
- The wrapper's `WriteHeader()` func also calls `WriteHeader()` on the underlying `ResponseWriter` implementation, causing the `superfluous response.WriteHeader call` error to be logged [from the stdlib implementation](https://github.com/golang/go/blob/a73af5d91c4c335fb44ae99517d4c41d5f3960e0/src/net/http/server.go#L1155-L1159)


As a general question i've been having: should the otel wrapper be this opinionated? 

---

In the case of `docker compose stats`, as the example i used to reproduce the issue, we seem to call `Flush()` on the raw `http.ResponseWriter` (not yet wrapped by otel) here:

https://github.com/moby/moby/blob/f9dfd139ec0d169cf0cf6b534fad7d98137fcc23/daemon/stats.go#L47-L53

I'm not sure if we can (or should) change that implementation as a fix for this issue (the commit where this is included on our side is from quite a while back, see [here](https://github.com/krissetto/moby/commit/ae4ee974e80c5d650fdcbc0a6f5ab3245a7f1689#diff-b645c599465cae12a8a20d67c47bc131c486fa13133f8d8e6d8bfec511b5efd1)).


Related to the above (at least from a discussion earlier today); https://github.com/moby/moby/commit/c0391bf5545afef5e675138556c39e4c0e9bf91b was (I think) where the "write headers early" was added)

edit: this was related https://github.com/moby/moby/commit/1cbf5a54dae86e34d8e65508c5640b17cda0eed8


We also discussed briefly; what if we would make the writer we pass on a wrapped writer that ignores writing headers (as we know we already sent headers, so anything after us was not expected to send any)


To add a little more info, the "early write" was originally added in https://github.com/moby/moby/commit/1cbf5a54dae86e34d8e65508c5640b17cda0eed8.

Ahh, beat me to it @thaJeztah .
Opened a quick [draft pr](https://github.com/moby/moby/pull/47715) that should fix the `superfluous..` warning log when running `docker logs` and `docker compose stats`, but we might need to fix other areas where responses are streamed as well
@krissetto I think the simplest fix here may be best, which is to just call `wf.Write([]byte{})` before calling `Flush` here: https://github.com/moby/moby/blob/a73e63cfa6890bc68ea552288d53735ae99d6587/daemon/stats.go#L51

Same for logs.
Opened an issue over in the otelhttp repo: https://github.com/open-telemetry/opentelemetry-go-contrib/issues/5438

In the meantime we can change from using direct flush calls to writing an empty value so it triggers otelhttp.
Also I think we can skip the otelhttp wrapper when we we aren't recording traces.

Fix patch:
diff --git a/api/server/httputils/write_log_stream.go b/api/server/httputils/write_log_stream.go
index 8faacc029eb13..a2086b5276854 100644
--- a/api/server/httputils/write_log_stream.go
+++ b/api/server/httputils/write_log_stream.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 	"io"
+	"net/http"
 	"net/url"
 	"sort"
 
@@ -16,7 +17,11 @@ import (
 
 // WriteLogStream writes an encoded byte stream of log messages from the
 // messages channel, multiplexing them with a stdcopy.Writer if mux is true
-func WriteLogStream(_ context.Context, w io.Writer, msgs <-chan *backend.LogMessage, config *container.LogsOptions, mux bool) {
+func WriteLogStream(_ context.Context, w http.ResponseWriter, msgs <-chan *backend.LogMessage, config *container.LogsOptions, mux bool) {
+	// See https://github.com/moby/moby/issues/47448
+	// Trigger headers to be written immediately.
+	w.WriteHeader(http.StatusOK)
+
 	wf := ioutils.NewWriteFlusher(w)
 	defer wf.Close()
 
diff --git a/api/server/router/container/container_routes.go b/api/server/router/container/container_routes.go
index 3872028652f86..c33d3d29ffe57 100644
--- a/api/server/router/container/container_routes.go
+++ b/api/server/router/container/container_routes.go
@@ -112,9 +112,18 @@ func (s *containerRouter) getContainersStats(ctx context.Context, w http.Respons
 	}
 
 	return s.backend.ContainerStats(ctx, vars["name"], &backend.ContainerStatsConfig{
-		Stream:    stream,
-		OneShot:   oneShot,
-		OutStream: w,
+		Stream:  stream,
+		OneShot: oneShot,
+		OutStream: func() io.Writer {
+			// Assume that when this is called the request is OK.
+			w.WriteHeader(http.StatusOK)
+			if !stream {
+				return w
+			}
+			wf := ioutils.NewWriteFlusher(w)
+			wf.Flush()
+			return wf
+		},
 	})
 }
 
diff --git a/api/server/router/system/system_routes.go b/api/server/router/system/system_routes.go
index 1dd50d32315b1..fca29cb07e515 100644
--- a/api/server/router/system/system_routes.go
+++ b/api/server/router/system/system_routes.go
@@ -263,6 +263,7 @@ func (s *systemRouter) getEvents(ctx context.Context, w http.ResponseWriter, r *
 	}
 
 	w.Header().Set("Content-Type", "application/json")
+	w.WriteHeader(http.StatusOK)
 	output := ioutils.NewWriteFlusher(w)
 	defer output.Close()
 	output.Flush()
diff --git a/api/types/backend/backend.go b/api/types/backend/backend.go
index e4e760905d01c..b18a265dcc79f 100644
--- a/api/types/backend/backend.go
+++ b/api/types/backend/backend.go
@@ -89,7 +89,7 @@ type LogSelector struct {
 type ContainerStatsConfig struct {
 	Stream    bool
 	OneShot   bool
-	OutStream io.Writer
+	OutStream func() io.Writer
 }
 
 // ExecInspect holds information about a running process started
diff --git a/daemon/stats.go b/daemon/stats.go
index 5dcd6121d4400..314234479991d 100644
--- a/daemon/stats.go
+++ b/daemon/stats.go
@@ -12,7 +12,6 @@ import (
 	"github.com/docker/docker/api/types/backend"
 	"github.com/docker/docker/container"
 	"github.com/docker/docker/errdefs"
-	"github.com/docker/docker/pkg/ioutils"
 )
 
 // ContainerStats writes information about the container to the stream
@@ -27,9 +26,11 @@ func (daemon *Daemon) ContainerStats(ctx context.Context, prefixOrName string, c
 		return errdefs.InvalidParameter(errors.New("cannot have stream=true and one-shot=true"))
 	}
 
+	enc := json.NewEncoder(config.OutStream())
+
 	// If the container is either not running or restarting and requires no stream, return an empty stats.
 	if (!ctr.IsRunning() || ctr.IsRestarting()) && !config.Stream {
-		return json.NewEncoder(config.OutStream).Encode(&types.StatsJSON{
+		return enc.Encode(&types.StatsJSON{
 			Name: ctr.Name,
 			ID:   ctr.ID,
 		})
@@ -41,15 +42,7 @@ func (daemon *Daemon) ContainerStats(ctx context.Context, prefixOrName string, c
 		if err != nil {
 			return err
 		}
-		return json.NewEncoder(config.OutStream).Encode(stats)
-	}
-
-	outStream := config.OutStream
-	if config.Stream {
-		wf := ioutils.NewWriteFlusher(outStream)
-		defer wf.Close()
-		wf.Flush()
-		outStream = wf
+		return enc.Encode(stats)
 	}
 
 	var preCPUStats types.CPUStats
@@ -65,12 +58,11 @@ func (daemon *Daemon) ContainerStats(ctx context.Context, prefixOrName string, c
 		return &ss
 	}
 
-	enc := json.NewEncoder(outStream)
-
 	updates := daemon.subscribeToContainerStats(ctr)
 	defer daemon.unsubscribeToContainerStats(ctr, updates)
 
 	noStreamFirstFrame := !config.OneShot
+
 	for {
 		select {
 		case v, ok := <-updates:


Test patch: