Skip to content

Commit da94522

Browse files
authored
fix(logs): strip injected timestamps from >16KB Docker TTY container log lines (#51024)
## Summary - Fixes AGNTLOG-81: Docker `--tty` containers with log lines >16KB had a timestamp marker injected into the log payload every 16KB by the Docker daemon (upstream moby/moby#19696). - The root cause: Docker injects a `TIMESTAMP SPACE` prefix before each 16KB buffer chunk in TTY mode. For multi-chunk log lines the intermediate timestamps appeared verbatim in the delivered message. - Fix: added `removeTTYPartialTimestamps` in `pkg/logs/internal/parsers/dockerstream/docker_stream.go`, mirroring the existing `removePartialDockerMetadata` used for the non-TTY path but without the 8-byte stream header. - Added two unit tests (`TestDockerStandaloneParserShouldHandleLargeTtyMessage`, `TestDockerStandaloneParserShouldRemoveTTYPartialTimestamps`) that cover single-chunk (exactly 16KB+) and multi-chunk (16KB+50, 3×16KB+50) cases. ## Manual QA **Environment**: macOS arm64, Docker Engine 29.3.1, colima VM backend. **Reproduced the bug before the fix:** ```bash # Start a TTY container generating 20,000-char log lines docker run --rm -d --name tty-test --tty alpine sh -c \ 'while true; do dd if=/dev/zero bs=20000 count=1 2>/dev/null | tr "\0" "A"; echo ""; sleep 3; done' # Capture raw Docker API stream with timestamps curl -sN --unix-socket ~/.colima/default/docker.sock \ "http://./containers/tty-test/logs?stdout=1&stderr=1&timestamps=1" > /tmp/all_logs.bin ``` Python verification of raw data showed: ``` Raw first line length: 20062 bytes Embedded timestamp at offset 16384 in content (BEFORE fix) ``` Content was 20031 bytes (20000 'A's + 31-byte embedded timestamp `2026-05-19T14:12:36.172399096Z `) — confirming the bug. **Verified the fix on the same raw data:** Running `removeTTYPartialTimestamps` on the captured data: ``` After fix: Timestamp: 2026-05-19T14:12:36.172399096Z Content length: 20000 Content is clean (all 'A' chars): YES Embedded timestamp removed: YES ``` The 31-byte embedded timestamp is stripped; content is exactly 20000 clean bytes. **Unit tests:** `go test -tags docker ./pkg/logs/internal/parsers/dockerstream/...` — all pass, including 2 new TTY-specific tests. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: brian.floersch <brian.floersch@datadoghq.com>
1 parent 83d4ec8 commit da94522

3 files changed

Lines changed: 235 additions & 8 deletions

File tree

pkg/logs/internal/parsers/dockerstream/docker_stream.go

Lines changed: 92 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@ package dockerstream
1212
import (
1313
"bytes"
1414
"fmt"
15+
"time"
1516

1617
pkgconfigsetup "github.com/DataDog/datadog-agent/pkg/config/setup"
1718
"github.com/DataDog/datadog-agent/pkg/logs/internal/parsers"
@@ -66,19 +67,32 @@ func parseDockerStream(msg *message.Message, containerID string) (*message.Messa
6667
return msg, fmt.Errorf("cannot parse docker message for container %v: expected a 8 bytes header", containerID)
6768
}
6869

69-
// Read the first byte to get the status
70+
// Read the first byte to get the status. Non-TTY containers prefix every
71+
// chunk with an 8-byte header where byte 0 is 1 (stdout) or 2 (stderr);
72+
// TTY containers omit this header entirely (the daemon emits raw
73+
// "RFC3339Nano SPACE content" instead). getDockerSeverity returns "" for
74+
// the TTY case, which is the gate for everything below.
7075
status := getDockerSeverity(content)
7176
if status == "" {
72-
73-
// When tailing logs coming from a container running with a tty, docker
74-
// does not add the header. In that case, the message only contains
75-
// the timestamp followed by whatever comes from what is running in the
76-
// container (and maybe stdin). As a fallback, set the status to info.
77+
// TTY path — no 8-byte header. The body looks like:
78+
// RFC3339Nano SPACE content...
79+
// and for log lines spanning more than one 16KB Docker buffer:
80+
// TS1 SPACE content1(16KB) TS2 SPACE content2(16KB) ... TSn SPACE contentn
81+
// (see https://github.com/moby/moby/issues/19696). When this happens
82+
// we need to strip the intermediate TSi SPACE markers so the caller
83+
// only sees the concatenated raw content. Spaces inside the user's
84+
// log content are preserved — the stripping operates on fixed 16KB
85+
// chunk boundaries, not on space lookups inside content.
7786
status = message.StatusInfo
87+
if len(content) > dockerBufferSize {
88+
content = removeTTYPartialTimestamps(content)
89+
}
7890

7991
} else {
80-
81-
// remove partial headers that are added by docker when the message gets too long
92+
// Non-TTY path — 8-byte stream header present. Each 16KB partial chunk
93+
// includes its own header + RFC3339Nano timestamp + space, handled by
94+
// removePartialDockerMetadata. The new TTY helper above is never
95+
// reached on this branch.
8296
if len(content) > dockerBufferSize {
8397
content = removePartialDockerMetadata(content)
8498
}
@@ -176,6 +190,76 @@ func getDockerMetadataLength(msg []byte) int {
176190
return dockerHeaderLength + idx + 1
177191
}
178192

193+
// removeTTYPartialTimestamps removes the timestamp and space that Docker injects
194+
// before each 16KB chunk of content when a container runs in TTY mode.
195+
//
196+
// In TTY mode the 8-byte stream header is absent, so the wire format for a
197+
// message that spans multiple 16KB buffers is:
198+
//
199+
// TS1 SPACE CONTENT1(16KB) TS2 SPACE CONTENT2(16KB) ... TSn SPACE CONTENTn
200+
//
201+
// This function keeps the very first "TS1 SPACE" and concatenates each
202+
// subsequent content chunk without its leading timestamp prefix:
203+
//
204+
// Input: TS1 SPACE CONTENT1 TS2 SPACE CONTENT2 TS3 SPACE CONTENT3
205+
// Output: TS1 SPACE CONTENT1 CONTENT2 CONTENT3
206+
//
207+
// If the tail after a chunk does not begin with a valid RFC3339Nano timestamp
208+
// followed by a space (for example a single non-Docker frame longer than 16KB,
209+
// or a truncated frame), the remainder is appended verbatim instead of being
210+
// reinterpreted as another chunk boundary.
211+
func removeTTYPartialTimestamps(msgToClean []byte) []byte {
212+
metadataLen, ok := getTTYMetadataLength(msgToClean)
213+
if !ok {
214+
return msgToClean
215+
}
216+
217+
msg := []byte{}
218+
start := 0
219+
end := min(len(msgToClean), dockerBufferSize+metadataLen)
220+
221+
for end > 0 {
222+
msg = append(msg, msgToClean[start:end]...)
223+
msgToClean = msgToClean[end:]
224+
if len(msgToClean) == 0 {
225+
break
226+
}
227+
metadataLen, ok = getTTYMetadataLength(msgToClean)
228+
if !ok {
229+
// Remainder doesn't look like another Docker chunk boundary.
230+
// Append the unmatched tail unchanged rather than stripping
231+
// bytes that might be part of the user's log content.
232+
msg = append(msg, msgToClean...)
233+
break
234+
}
235+
start = metadataLen
236+
end = min(len(msgToClean), dockerBufferSize+metadataLen)
237+
}
238+
239+
return msg
240+
}
241+
242+
// getTTYMetadataLength returns the length of the timestamp and trailing space
243+
// that Docker prepends to each TTY-mode buffer chunk. In TTY mode there is no
244+
// 8-byte stream header, so the metadata is just the RFC3339Nano timestamp
245+
// followed by a single space character.
246+
//
247+
// Returns (metadataLen, true) when the message begins with a valid
248+
// RFC3339Nano timestamp + space, and (0, false) otherwise. The second
249+
// return guards against treating ordinary user content (which may contain
250+
// spaces but does not start with a parseable timestamp) as a chunk
251+
// boundary.
252+
func getTTYMetadataLength(msg []byte) (int, bool) {
253+
idx := bytes.Index(msg, []byte{' '})
254+
if idx == -1 {
255+
return 0, false
256+
}
257+
if _, err := time.Parse(time.RFC3339Nano, string(msg[:idx])); err != nil {
258+
return 0, false
259+
}
260+
return idx + 1, true
261+
}
262+
179263
// isEmptyMessage tests if the entire message is in the form of escaped new line
180264
// i.e. \\n or \\r or \\r\\n
181265
func isEmptyMessage(content []byte) bool {

pkg/logs/internal/parsers/dockerstream/docker_stream_test.go

Lines changed: 128 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -165,3 +165,131 @@ func buildPartialMessage(r rune, count int) string {
165165
func buildMessage(r rune, count int) string {
166166
return strings.Repeat(string(r), count)
167167
}
168+
169+
// ttyTimestamp is a sample RFC3339Nano timestamp used in TTY-mode tests.
170+
var ttyTimestamp = "2018-06-14T18:27:03.246999277Z"
171+
172+
// buildTTYPartialMessage returns a TTY-mode chunk as Docker would send it:
173+
// a bare RFC3339Nano timestamp followed by a space and count repetitions of r.
174+
// There is no 8-byte stream header.
175+
func buildTTYPartialMessage(r rune, count int) string {
176+
return ttyTimestamp + " " + strings.Repeat(string(r), count)
177+
}
178+
179+
func TestDockerStandaloneParserShouldHandleLargeTtyMessage(t *testing.T) {
180+
// A single 16KB TTY log line: no intermediate timestamp injection expected.
181+
input := buildTTYPartialMessage('a', dockerBufferSize)
182+
logMessage := message.NewMessage([]byte(input), nil, "", 0)
183+
msg, err := container1Parser.Parse(logMessage)
184+
assert.Nil(t, err)
185+
assert.False(t, msg.ParsingExtra.IsPartial)
186+
assert.Equal(t, ttyTimestamp, msg.ParsingExtra.Timestamp)
187+
assert.Equal(t, message.StatusInfo, msg.Status)
188+
assert.Equal(t, []byte(buildMessage('a', dockerBufferSize)), msg.GetContent())
189+
assert.Equal(t, dockerBufferSize, len(msg.GetContent()))
190+
}
191+
192+
func TestDockerStandaloneParserShouldRemoveTTYPartialTimestamps(t *testing.T) {
193+
// A TTY log line >16KB: Docker prepends a timestamp to each 16KB chunk.
194+
// The parser must strip the intermediate timestamps so users see clean content.
195+
196+
// two chunks: 16KB + 50 bytes
197+
input := buildTTYPartialMessage('a', dockerBufferSize) + buildTTYPartialMessage('b', 50)
198+
expectedContent := buildMessage('a', dockerBufferSize) + buildMessage('b', 50)
199+
logMessage := message.NewMessage([]byte(input), nil, "", 0)
200+
msg, err := container1Parser.Parse(logMessage)
201+
assert.Nil(t, err)
202+
assert.False(t, msg.ParsingExtra.IsPartial)
203+
assert.Equal(t, ttyTimestamp, msg.ParsingExtra.Timestamp)
204+
assert.Equal(t, message.StatusInfo, msg.Status)
205+
assert.Equal(t, []byte(expectedContent), msg.GetContent())
206+
assert.Equal(t, dockerBufferSize+50, len(msg.GetContent()))
207+
208+
// three full 16KB chunks + a 50-byte tail (mirrors the non-TTY test)
209+
input = buildTTYPartialMessage('a', dockerBufferSize) +
210+
buildTTYPartialMessage('a', dockerBufferSize) +
211+
buildTTYPartialMessage('a', dockerBufferSize) +
212+
buildTTYPartialMessage('b', 50)
213+
expectedContent = buildMessage('a', 3*dockerBufferSize) + buildMessage('b', 50)
214+
logMessage.SetContent([]byte(input))
215+
msg, err = container1Parser.Parse(logMessage)
216+
assert.Nil(t, err)
217+
assert.False(t, msg.ParsingExtra.IsPartial)
218+
assert.Equal(t, ttyTimestamp, msg.ParsingExtra.Timestamp)
219+
assert.Equal(t, message.StatusInfo, msg.Status)
220+
assert.Equal(t, []byte(expectedContent), msg.GetContent())
221+
assert.Equal(t, 3*dockerBufferSize+50, len(msg.GetContent()))
222+
}
223+
224+
// TestDockerStandaloneParserTTYPreservesSpacesInContent guards against the
225+
// theoretical risk that removeTTYPartialTimestamps could misinterpret a space
226+
// inside the user's log content as a chunk-boundary timestamp marker. The
227+
// stripping operates on fixed 16KB chunk windows, not on space lookups inside
228+
// content, so embedded spaces must round-trip untouched.
229+
func TestDockerStandaloneParserTTYPreservesSpacesInContent(t *testing.T) {
230+
// Build a 16KB chunk whose content contains a space NOT at the boundary.
231+
// Layout: 8000 'a' + 1 space + 8383 'b' = 16384 bytes (= dockerBufferSize).
232+
chunk1Content := strings.Repeat("a", 8000) + " " + strings.Repeat("b", 8383)
233+
assert.Equal(t, dockerBufferSize, len(chunk1Content))
234+
235+
// Second chunk: shorter, with its own embedded space.
236+
chunk2Content := "hello world tail"
237+
238+
input := ttyTimestamp + " " + chunk1Content + ttyTimestamp + " " + chunk2Content
239+
expectedContent := chunk1Content + chunk2Content
240+
241+
logMessage := message.NewMessage([]byte(input), nil, "", 0)
242+
msg, err := container1Parser.Parse(logMessage)
243+
assert.Nil(t, err)
244+
assert.False(t, msg.ParsingExtra.IsPartial)
245+
assert.Equal(t, ttyTimestamp, msg.ParsingExtra.Timestamp)
246+
assert.Equal(t, message.StatusInfo, msg.Status)
247+
assert.Equal(t, []byte(expectedContent), msg.GetContent())
248+
// Confirm the embedded boundary survived — would be lost if the stripper
249+
// used space-search inside content instead of fixed 16KB windows.
250+
assert.Equal(t, dockerBufferSize+len(chunk2Content), len(msg.GetContent()))
251+
assert.Contains(t, string(msg.GetContent()), "aaaa b")
252+
assert.Contains(t, string(msg.GetContent()), "hello world tail")
253+
}
254+
255+
// TestDockerStandaloneParserTTYPreservesUnmatchedTail guards against the
256+
// codex review finding: when the tail after the first 16KB chunk does NOT
257+
// begin with a valid RFC3339Nano timestamp + space (for example a single
258+
// non-Docker frame slightly longer than 16KB, or a truncated frame), the
259+
// stripper must not drop the tail or misinterpret content-internal spaces
260+
// as a chunk boundary. The previous (loose) version returned 0 for tails
261+
// without a space and silently truncated the message.
262+
func TestDockerStandaloneParserTTYPreservesUnmatchedTail(t *testing.T) {
263+
// (a) Tail with no space at all: previous code dropped it entirely.
264+
chunk1 := strings.Repeat("a", dockerBufferSize)
265+
tail := "tail-without-space" // no space, no TS, must be preserved verbatim
266+
input := ttyTimestamp + " " + chunk1 + tail
267+
expectedContent := chunk1 + tail
268+
269+
logMessage := message.NewMessage([]byte(input), nil, "", 0)
270+
msg, err := container1Parser.Parse(logMessage)
271+
assert.Nil(t, err)
272+
assert.False(t, msg.ParsingExtra.IsPartial)
273+
assert.Equal(t, ttyTimestamp, msg.ParsingExtra.Timestamp)
274+
assert.Equal(t, message.StatusInfo, msg.Status)
275+
assert.Equal(t, []byte(expectedContent), msg.GetContent())
276+
assert.Equal(t, dockerBufferSize+len(tail), len(msg.GetContent()))
277+
278+
// (b) Tail with a space but no valid timestamp before it: previous code
279+
// would strip the prefix up to the space as if it were a TS marker.
280+
tail = "hello world, no timestamp prefix"
281+
input = ttyTimestamp + " " + chunk1 + tail
282+
expectedContent = chunk1 + tail
283+
284+
logMessage = message.NewMessage([]byte(input), nil, "", 0)
285+
msg, err = container1Parser.Parse(logMessage)
286+
assert.Nil(t, err)
287+
assert.False(t, msg.ParsingExtra.IsPartial)
288+
assert.Equal(t, ttyTimestamp, msg.ParsingExtra.Timestamp)
289+
assert.Equal(t, message.StatusInfo, msg.Status)
290+
assert.Equal(t, []byte(expectedContent), msg.GetContent())
291+
assert.Equal(t, dockerBufferSize+len(tail), len(msg.GetContent()))
292+
// Verify the leading "hello" of the tail is NOT stripped (would happen
293+
// if the function treated the first space as a chunk-boundary marker).
294+
assert.Contains(t, string(msg.GetContent()), "hello world, no timestamp prefix")
295+
}
Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
# Each section from every release note are combined when the
2+
# CHANGELOG.rst is rendered. So the text needs to be worded so that
3+
# it does not depend on any information only available in another
4+
# section. This may mean repeating some details, but each section
5+
# must be readable independently of the other.
6+
#
7+
# Each section note must be formatted as reStructuredText.
8+
---
9+
fixes:
10+
- |
11+
Fix Docker log parsing for TTY-mode containers when a single log line exceeds the
12+
16KB Docker buffer size. Previously, the Agent retained the per-chunk timestamp
13+
prefix that Docker inserts at every 16KB boundary, causing those timestamps to
14+
appear inside the collected log content. The parser now strips the intermediate
15+
timestamps so the log line is reassembled correctly.

0 commit comments

Comments
 (0)