daemon/server: fix requests not logged with --log-level=trace by thaJeztah · Pull Request #50986 · moby/moby

thaJeztah · 2025-09-16T08:03:25Z

Before this patch, debug and trace-level logs were enabled, but the debugging middleware was not, the request-body was not logged when enabling trace-level logs:

INFO[2025-09-16T07:55:07.500241927Z] Daemon has completed initialization
INFO[2025-09-16T07:55:07.500267802Z] API listen on /var/run/docker.sock
TRAC[2025-09-16T07:55:08.502387094Z] garbage collected                             d="437.583µs"
DEBU[2025-09-16T07:55:13.215510096Z] stat snapshot                                 key="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs
DEBU[2025-09-16T07:55:13.216532430Z] prepare snapshot                              key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init-key parent="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs
TRAC[2025-09-16T07:55:13.219691055Z] event published                               ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2025-09-16T07:55:13.226507180Z] commit snapshot                               key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init-key name=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init snapshotter=overlayfs
TRAC[2025-09-16T07:55:13.227871055Z] event published                               ns=moby topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2025-09-16T07:55:13.228132471Z] prepare snapshot                              key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 parent=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init snapshotter=overlayfs
TRAC[2025-09-16T07:55:13.229071055Z] event published                               ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2025-09-16T07:55:13.229489180Z] get snapshot mounts                           key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 snapshotter=overlayfs
DEBU[2025-09-16T07:55:13.229824721Z] container mounted via snapshotter             container=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 root=/var/lib/docker/rootfs/overlayfs/80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 snapshotter=overlayfs
DEBU[2025-09-16T07:55:13.229849096Z] container mounted via layerStore              container=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 root=/var/lib/docker/rootfs/overlayfs/80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 storage-driver=overlayfs

With this patch applied, the debugging middleware is enabled both with debug- and trace-level logging enabled:

INFO[2025-09-16T07:56:31.024794341Z] Daemon has completed initialization
INFO[2025-09-16T07:56:31.024856591Z] API listen on /var/run/docker.sock
TRAC[2025-09-16T07:56:32.026944049Z] garbage collected                             d="640.167µs"
DEBU[2025-09-16T07:56:36.729870218Z] handling HEAD request                         method=HEAD module=api request-url=/_ping vars="map[]"
DEBU[2025-09-16T07:56:36.731114885Z] handling POST request                         form-data="{\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":null,\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":null,\"HostConfig\":{\"AutoRemove\":false,\"Binds\":null,\"BlkioDeviceReadBps\":[],\"BlkioDeviceReadIOps\":[],\"BlkioDeviceWriteBps\":[],\"BlkioDeviceWriteIOps\":[],\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"\",\"ConsoleSize\":[23,104],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":[],\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"busybox\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{\"default\":{\"Aliases\":null,\"DNSNames\":null,\"DriverOpts\":null,\"EndpointID\":\"\",\"Gateway\":\"\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"GwPriority\":0,\"IPAMConfig\":null,\"IPAddress\":\"\",\"IPPrefixLen\":0,\"IPv6Gateway\":\"\",\"Links\":null,\"MacAddress\":\"\",\"NetworkID\":\"\"}}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}" method=POST module=api request-url=/v1.51/containers/create vars="map[version:1.51]"
DEBU[2025-09-16T07:56:36.751584218Z] stat snapshot                                 key="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs
DEBU[2025-09-16T07:56:36.752634302Z] prepare snapshot                              key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init-key parent="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs
TRAC[2025-09-16T07:56:36.755453593Z] event published                               ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2025-09-16T07:56:36.827076427Z] commit snapshot                               key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init-key name=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init snapshotter=overlayfs
TRAC[2025-09-16T07:56:36.828276635Z] event published                               ns=moby topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2025-09-16T07:56:36.828467885Z] prepare snapshot                              key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 parent=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init snapshotter=overlayfs
TRAC[2025-09-16T07:56:36.829163010Z] event published                               ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2025-09-16T07:56:36.829448927Z] get snapshot mounts                           key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 snapshotter=overlayfs
DEBU[2025-09-16T07:56:36.829850302Z] container mounted via snapshotter             container=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 root=/var/lib/docker/rootfs/overlayfs/786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 snapshotter=overlayfs
DEBU[2025-09-16T07:56:36.829872593Z] container mounted via layerStore              container=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 root=/var/lib/docker/rootfs/overlayfs/786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 storage-driver=overlayfs

- What I did

- How I did it

- How to verify it

- Human readable description for the release notes

Fix requests not being logged when running the daemon with `--log-level=trace`.

- A picture of a cute animal (not mandatory but encouraged)

Before this patch, debug and trace-level logs were enabled, but the debugging middleware was not, the request-body was not logged when enabling trace-level logs: INFO[2025-09-16T07:55:07.500241927Z] Daemon has completed initialization INFO[2025-09-16T07:55:07.500267802Z] API listen on /var/run/docker.sock TRAC[2025-09-16T07:55:08.502387094Z] garbage collected d="437.583µs" DEBU[2025-09-16T07:55:13.215510096Z] stat snapshot key="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs DEBU[2025-09-16T07:55:13.216532430Z] prepare snapshot key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init-key parent="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs TRAC[2025-09-16T07:55:13.219691055Z] event published ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare DEBU[2025-09-16T07:55:13.226507180Z] commit snapshot key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init-key name=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init snapshotter=overlayfs TRAC[2025-09-16T07:55:13.227871055Z] event published ns=moby topic=/snapshot/commit type=containerd.events.SnapshotCommit DEBU[2025-09-16T07:55:13.228132471Z] prepare snapshot key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 parent=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485-init snapshotter=overlayfs TRAC[2025-09-16T07:55:13.229071055Z] event published ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare DEBU[2025-09-16T07:55:13.229489180Z] get snapshot mounts key=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 snapshotter=overlayfs DEBU[2025-09-16T07:55:13.229824721Z] container mounted via snapshotter container=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 root=/var/lib/docker/rootfs/overlayfs/80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 snapshotter=overlayfs DEBU[2025-09-16T07:55:13.229849096Z] container mounted via layerStore container=80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 root=/var/lib/docker/rootfs/overlayfs/80813e376c0610bcd3fc1cbe7b6b1f3427a22eca06e4d34f6d5fb9c4d4589485 storage-driver=overlayfs With this patch applied, the debugging middleware is enabled both with debug- and trace-level logging enabled: INFO[2025-09-16T07:56:31.024794341Z] Daemon has completed initialization INFO[2025-09-16T07:56:31.024856591Z] API listen on /var/run/docker.sock TRAC[2025-09-16T07:56:32.026944049Z] garbage collected d="640.167µs" DEBU[2025-09-16T07:56:36.729870218Z] handling HEAD request method=HEAD module=api request-url=/_ping vars="map[]" DEBU[2025-09-16T07:56:36.731114885Z] handling POST request form-data="{\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":null,\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":null,\"HostConfig\":{\"AutoRemove\":false,\"Binds\":null,\"BlkioDeviceReadBps\":[],\"BlkioDeviceReadIOps\":[],\"BlkioDeviceWriteBps\":[],\"BlkioDeviceWriteIOps\":[],\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"\",\"ConsoleSize\":[23,104],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":[],\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"busybox\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{\"default\":{\"Aliases\":null,\"DNSNames\":null,\"DriverOpts\":null,\"EndpointID\":\"\",\"Gateway\":\"\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"GwPriority\":0,\"IPAMConfig\":null,\"IPAddress\":\"\",\"IPPrefixLen\":0,\"IPv6Gateway\":\"\",\"Links\":null,\"MacAddress\":\"\",\"NetworkID\":\"\"}}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}" method=POST module=api request-url=/v1.51/containers/create vars="map[version:1.51]" DEBU[2025-09-16T07:56:36.751584218Z] stat snapshot key="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs DEBU[2025-09-16T07:56:36.752634302Z] prepare snapshot key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init-key parent="sha256:6aba5e0d32d91e3e923854dcb30588dc4112bfa1dae82b89535ad31d322a7b19" snapshotter=overlayfs TRAC[2025-09-16T07:56:36.755453593Z] event published ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare DEBU[2025-09-16T07:56:36.827076427Z] commit snapshot key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init-key name=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init snapshotter=overlayfs TRAC[2025-09-16T07:56:36.828276635Z] event published ns=moby topic=/snapshot/commit type=containerd.events.SnapshotCommit DEBU[2025-09-16T07:56:36.828467885Z] prepare snapshot key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 parent=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41-init snapshotter=overlayfs TRAC[2025-09-16T07:56:36.829163010Z] event published ns=moby topic=/snapshot/prepare type=containerd.events.SnapshotPrepare DEBU[2025-09-16T07:56:36.829448927Z] get snapshot mounts key=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 snapshotter=overlayfs DEBU[2025-09-16T07:56:36.829850302Z] container mounted via snapshotter container=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 root=/var/lib/docker/rootfs/overlayfs/786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 snapshotter=overlayfs DEBU[2025-09-16T07:56:36.829872593Z] container mounted via layerStore container=786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 root=/var/lib/docker/rootfs/overlayfs/786e5174c57aa5057b4fd0a3c01013fe98d6fa3e5aaf9f1f89224175be74ba41 storage-driver=overlayfs Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah · 2025-09-16T09:55:46Z

Flaky test; tracked in #50595

=== Failed
=== FAIL: amd64.docker.docker.integration.networking TestBridgeICC/IPv6_link-local_address_on_internal_network (4.57s)
    firewall.go:69: Firewalld reload completed at 2025-09-16T08:26:11Z
    bridge_linux_test.go:218: assertion failed: 1 (res.ExitCode int) != 0 (int)
    bridge_linux_test.go:220: assertion failed: string "PING fe80::2%eth0 (fe80::2): 56 data bytes\n\n--- fe80::2%eth0 ping statistics ---\n1 packets transmitted, 0 packets received, 100% packet loss\n" does not contain "1 packets transmitted, 1 packets received"
    --- FAIL: TestBridgeICC/IPv6_link-local_address_on_internal_network (4.57s)

=== FAIL: amd64.docker.docker.integration.networking TestBridgeICC (27.13s)

Also various BuildKit flaky tests on Windows; looks like potential race condition?
https://github.com/moby/moby/actions/runs/17759006036/job/50468925269?pr=50986

=== Failed
=== FAIL: client TestIntegration/slice=2-4/TestLocalSourceDiffer/worker=dockerd-containerd/differ=metadata (0.80s)
    client_test.go:2206: 
        	Error Trace:	D:/a/moby/moby/buildkit/client/client_test.go:2206
        	            				D:/a/moby/moby/buildkit/client/client_test.go:2140
        	Error:      	Not equal: 
        	            	expected: []byte{0x66, 0x6f, 0x6f}
        	            	actual  : []byte{0x62, 0x61, 0x72}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,3 +1,3 @@
        	            	 ([]uint8) (len=3) {
        	            	- 00000000  66 6f 6f                                          |foo|
        	            	+ 00000000  62 61 72                                          |bar|
        	            	 }
        	Test:       	TestIntegration/slice=2-4/TestLocalSourceDiffer/worker=dockerd-containerd/differ=metadata
        --- FAIL: TestIntegration/slice=2-4/TestLocalSourceDiffer/worker=dockerd-containerd/differ=metadata (0.80s)

thaJeztah added this to the 29.0.0 milestone Sep 16, 2025

thaJeztah added status/2-code-review impact/changelog area/daemon Core Engine kind/bugfix PR's that fix bugs labels Sep 16, 2025

vvoland approved these changes Sep 16, 2025

View reviewed changes

robmry approved these changes Sep 16, 2025

View reviewed changes

thaJeztah merged commit 5028544 into moby:master Sep 16, 2025
293 of 295 checks passed

thaJeztah deleted the trace_logging branch September 16, 2025 10:47

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

daemon/server: fix requests not logged with --log-level=trace#50986

daemon/server: fix requests not logged with --log-level=trace#50986
thaJeztah merged 1 commit intomoby:masterfrom
thaJeztah:trace_logging

thaJeztah commented Sep 16, 2025

Uh oh!

thaJeztah commented Sep 16, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

thaJeztah commented Sep 16, 2025

Uh oh!

thaJeztah commented Sep 16, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants