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;

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);

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() 🤔;

• 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, 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

  moby/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/wrap.go

  Lines 76 to 79 in f9dfd13

  	func (w *respWriterWrapper) Write(p []byte) (int, error) {
  	if !w.wroteHeader {
  	w.WriteHeader(http.StatusOK)
  	}

• The wrapper's WriteHeader() func is responsible for setting w.wroteHeader = true
  (Note: this value is set on the otel respWriterWrapper struct)
  

  moby/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/wrap.go

  Lines 93 to 99 in f9dfd13

  	func (w *respWriterWrapper) WriteHeader(statusCode int) {
  	if !w.wroteHeader {
  	w.wroteHeader = true
  	w.statusCode = statusCode
  	}
  	w.ResponseWriter.WriteHeader(statusCode)
  	}

• 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

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:

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).

Related to the above (at least from a discussion earlier today); c0391bf was (I think) where the "write headers early" was added)

edit: this was related 1cbf5a5

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 1cbf5a5.

Ahh, beat me to it @thaJeztah .

Opened a quick draft pr 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:

Same for logs.

Opened an issue over in the otelhttp repo: open-telemetry/opentelemetry-go-contrib#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.