Skip to content

Commit 461135d

Browse files
committed
fix(logs): require a complete PRI before reading an octet-counted length
Frame detection accepted an RFC 6587 octet-counted frame after seeing only "<" and a single digit following the MSG-LEN and its space. Ordinary prose supplies that shape readily, so a newline-framed line such as 54 <1 minute elapsed was classified as MSG-LEN=54. MSG-LEN is the authoritative frame boundary and the body it declares is never re-scanned for frame starts, so the declared body ran past the newline and tore the following frame in half: [0] "<1 minute elapsed\n<134>Feb 10 12:00:00 flushhost FLUSH" [1] "TAG[1]: well_formed_message" That is the same corruption the MSG-LEN signature check exists to prevent, one byte further along in the signature. Require a whole PRI -- "<", a 1-3 digit PRIVAL, ">" -- through priLen, and route both classifyOctetPrefix and isSyslogFrameStart through it so that resynchronizing accepts exactly what the frame reader accepts. Otherwise a malformed run is cut short at a candidate the reader would then reject, splitting one coherent malformed frame into fragments. A PRI straddling a TCP read still reports needMore rather than being rejected outright. maxFrameStartLookbehind becomes a computed bound on the longest signature it has to cover. The value is unchanged at 16 bytes. Each new test was checked against the unfixed framer to confirm it reproduces the corruption rather than passing vacuously. Reported by Codex review on the pull request.
1 parent 8d39410 commit 461135d

2 files changed

Lines changed: 133 additions & 48 deletions

File tree

pkg/logs/internal/framer/syslog.go

Lines changed: 61 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ type syslogFrameMatcher struct {
6262
//
6363
// When the leading byte is not a valid syslog frame start ('<' or digit),
6464
// the matcher scans forward for the next probable frame start — either a
65-
// PRI header (<[0-9]) or an octet-counting prefix (digit+ SP <digit).
65+
// PRI header (<[0-9]{1,3}>) or an octet-counting prefix (digit+ SP PRI).
6666
// Everything before that sync point is emitted as a single malformed frame
6767
// so the downstream parser can log it coherently rather than producing one
6868
// empty message per byte.
@@ -98,9 +98,8 @@ func (m *syslogFrameMatcher) FindFrame(buf []byte, seen int) ([]byte, int, bool)
9898
// omits the PRI produces them routinely — rsyslog's file templates drop
9999
// it, so anything relaying such a rendering arrives as a bare timestamp
100100
// — as do epoch prefixes and thread ids ("54 [main] INFO ...").
101-
// Require the full MSG-LEN SP PRI signature before committing,
102-
// otherwise the digits would be consumed as a length and the declared
103-
// body would swallow every following frame.
101+
// classifyOctetPrefix demands the full MSG-LEN SP PRI signature before
102+
// any of those bytes are read as a length.
104103
switch classifyOctetPrefix(buf) {
105104
case octetPrefixYes:
106105
return m.findOctetCounted(buf, seen)
@@ -124,13 +123,10 @@ func (m *syslogFrameMatcher) FindFrame(buf []byte, seen int) ([]byte, int, bool)
124123

125124
// maxFrameStartLookbehind bounds how far scanMalformed rewinds behind the
126125
// already-scanned prefix (seen) before resuming its search for the next frame
127-
// start. It must cover the longest frame-start signature isSyslogFrameStart can
128-
// match across a read boundary so a signature whose tail only arrives in the
129-
// current read is still detected: up to 10 length digits (the cap enforced by
130-
// findOctetCounted) + SP + "<" + digit, i.e. ~13 bytes. 16 adds margin. Any
131-
// "octet header" longer than this is rejected as malformed anyway, so there is
132-
// no valid frame start beyond the look-behind to miss.
133-
const maxFrameStartLookbehind = 16
126+
// start, so a signature whose tail only arrives in the current read is still
127+
// found. It is the longest such signature: MSG-LEN SP PRI. Anything beginning
128+
// further back fitted entirely within the previous read and was decided then.
129+
const maxFrameStartLookbehind = maxOctetLenDigits + 1 + maxPRIDigits + 2
134130

135131
// scanMalformed consumes bytes that do not start a valid syslog frame. buf[0]
136132
// is known malformed (the FindFrame dispatch handles frame starts and stray
@@ -202,29 +198,23 @@ func (m *syslogFrameMatcher) scanMalformed(buf []byte, seen int, continuation bo
202198
// isSyslogFrameStart returns true if buf[i] looks like the start of a valid
203199
// syslog frame. Two patterns are recognized:
204200
//
205-
// - Non-transparent PRI header: <[0-9] (e.g. "<134>...")
206-
// - Octet-counting prefix: [1-9][0-9]* SP <[0-9] (e.g. "62 <134>...")
201+
// - Non-transparent PRI header: <[0-9]{1,3}> (e.g. "<134>...")
202+
// - Octet-counting prefix: [1-9][0-9]* SP <[0-9]{1,3}> (e.g. "62 <134>...")
207203
//
208-
// The octet-counting check requires the full "digits SP <digit" signature
209-
// to avoid false positives on bare digits in non-syslog content (e.g.,
210-
// timestamps like "2026-04-20T12:00:00Z" or JSON values). Previously, any
211-
// digit 1-9 was treated as a sync point, which caused a single JSON line
212-
// to fragment into 13+ entries.
204+
// Both are delegated — to priLen and classifyOctetPrefix — so that
205+
// resynchronizing applies exactly the tests that admit a frame in the first
206+
// place, and a malformed run cannot be cut short at something the reader would
207+
// then reject. An incomplete signature is not a sync point: unlike the caller
208+
// that reads frames, a resync can wait for the scan to reach a later candidate
209+
// instead of having to decide on the bytes in hand.
213210
func isSyslogFrameStart(buf []byte, i int) bool {
214211
b := buf[i]
215-
if b == '<' && i+1 < len(buf) && buf[i+1] >= '0' && buf[i+1] <= '9' {
216-
return true
212+
if b == '<' {
213+
n, _ := priLen(buf[i:])
214+
return n > 0
217215
}
218216
if b >= '1' && b <= '9' {
219-
j := i
220-
for j < len(buf) && buf[j] >= '0' && buf[j] <= '9' {
221-
j++
222-
}
223-
if j < len(buf) && buf[j] == ' ' &&
224-
j+1 < len(buf) && buf[j+1] == '<' &&
225-
j+2 < len(buf) && buf[j+2] >= '0' && buf[j+2] <= '9' {
226-
return true
227-
}
217+
return classifyOctetPrefix(buf[i:]) == octetPrefixYes
228218
}
229219
return false
230220
}
@@ -233,6 +223,10 @@ func isSyslogFrameStart(buf []byte, i int) bool {
233223
// not a plausible length, so the leading bytes are not an octet-counting header.
234224
const maxOctetLenDigits = 10
235225

226+
// maxPRIDigits is the widest PRIVAL RFC 5424 §6.2.1 allows, "<191>" being the
227+
// largest valid PRI.
228+
const maxPRIDigits = 3
229+
236230
// octetPrefixVerdict is the result of testing whether buf begins an RFC 6587
237231
// octet-counted frame. It is three-way rather than boolean: a TCP read can split
238232
// anywhere, so when the signature is still incomplete at the end of buf neither
@@ -248,15 +242,10 @@ const (
248242
)
249243

250244
// classifyOctetPrefix reports whether buf starts an octet-counted frame:
251-
// MSG-LEN SP SYSLOG-MSG, where SYSLOG-MSG begins with a PRI ("<" digit) because
245+
// MSG-LEN SP SYSLOG-MSG, where SYSLOG-MSG begins with a whole PRI because
252246
// RFC 6587 §3.4.1 carries RFC 5424 messages. buf[0] is known to be '1'-'9'.
253247
//
254-
// This is the same signature isSyslogFrameStart requires when resynchronizing,
255-
// so frame detection agrees on entry and on resync. Without the full
256-
// signature a line that merely starts with digits and a space would have its
257-
// digits consumed as a length, and the declared body would then swallow every
258-
// following frame (MSG-LEN being the authoritative boundary, the body is never
259-
// re-scanned for frame starts).
248+
// Nothing less than the whole signature will do; see priLen.
260249
func classifyOctetPrefix(buf []byte) octetPrefixVerdict {
261250
i := 0
262251
for i < len(buf) && buf[i] >= '0' && buf[i] <= '9' {
@@ -272,20 +261,47 @@ func classifyOctetPrefix(buf []byte) octetPrefixVerdict {
272261
if buf[i] != ' ' {
273262
return octetPrefixNo
274263
}
275-
// The two bytes after the SP must be "<" followed by a digit.
276-
if i+1 >= len(buf) {
264+
// What follows the SP must be a whole PRI.
265+
n, needMore := priLen(buf[i+1:])
266+
switch {
267+
case needMore:
277268
return octetPrefixNeedMore
278-
}
279-
if buf[i+1] != '<' {
269+
case n == 0:
280270
return octetPrefixNo
281271
}
282-
if i+2 >= len(buf) {
283-
return octetPrefixNeedMore
272+
return octetPrefixYes
273+
}
274+
275+
// priLen returns the length of a complete PRI — "<", a 1-3 digit PRIVAL, ">" —
276+
// at the start of buf, or 0 if buf does not begin with one. needMore reports
277+
// that buf ended before the PRI could be decided, which only the caller knows
278+
// how to handle: a reader that must commit now has to wait, while a scan
279+
// looking for the next frame start can carry on and pick it up next read.
280+
//
281+
// The closing ">" is what makes this worth checking in full. "<" and a digit
282+
// alone also open ordinary prose ("54 <1 minute elapsed"), and accepting that
283+
// is enough for the digits ahead of it to be read as a MSG-LEN. Because
284+
// MSG-LEN is the authoritative frame boundary and the body it declares is
285+
// never re-scanned, that body then runs past the newline and swallows the
286+
// frames behind it.
287+
func priLen(buf []byte) (n int, needMore bool) {
288+
if len(buf) == 0 {
289+
return 0, true
284290
}
285-
if buf[i+2] < '0' || buf[i+2] > '9' {
286-
return octetPrefixNo
291+
if buf[0] != '<' {
292+
return 0, false
287293
}
288-
return octetPrefixYes
294+
i := 1
295+
for i < len(buf) && i-1 < maxPRIDigits && buf[i] >= '0' && buf[i] <= '9' {
296+
i++
297+
}
298+
if i == len(buf) {
299+
return 0, true
300+
}
301+
if i == 1 || buf[i] != '>' {
302+
return 0, false
303+
}
304+
return i + 1, false
289305
}
290306

291307
// findOctetCounted parses MSG-LEN SP SYSLOG-MSG from the beginning of buf.

pkg/logs/internal/framer/syslog_octet_prefix_test.go

Lines changed: 72 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,70 @@ func TestSyslogDigitPrefixIsNotAlwaysOctetCount(t *testing.T) {
7676
})
7777
}
7878

79+
// Digits and a space followed by "<" and a digit are still not an octet count
80+
// unless the PRI is complete. Prose supplies that shape readily — "<1 minute",
81+
// "<2 sec" — and without the closing ">" the digits ahead of it are read as a
82+
// MSG-LEN whose body runs past the newline and tears apart the frames behind
83+
// it, which is the corruption the length prefix is supposed to prevent.
84+
func TestSyslogPartialPRIIsNotOctetCount(t *testing.T) {
85+
good := "<134>Feb 10 12:00:00 flushhost FLUSHTAG[1]: well_formed_message"
86+
87+
cases := []struct {
88+
name string
89+
line string
90+
}{
91+
{
92+
// "54 " would be read as MSG-LEN=54, long enough to reach well
93+
// into the frame that follows.
94+
name: "elapsed time in angle brackets",
95+
line: "54 <1 minute elapsed",
96+
},
97+
{
98+
name: "countdown in angle brackets",
99+
line: "100 <2 sec remaining until timeout occurs and the job is retried",
100+
},
101+
{
102+
// A closing ">" is present but too far along to form a PRI.
103+
name: "bracketed item count",
104+
line: "12 <3 items> pending",
105+
},
106+
}
107+
108+
for _, tc := range cases {
109+
t.Run(tc.name, func(t *testing.T) {
110+
stream := tc.line + "\n" + good + "\n" + good + "\n"
111+
got, _ := processSyslog(t, 262144, [][]byte{[]byte(stream)})
112+
113+
require.Len(t, got, 3, "each line is framed on its LF delimiter")
114+
assert.Equal(t, tc.line, got[0], "emitted whole, not split at the '<'")
115+
assert.Equal(t, good, got[1], "the following frame is neither swallowed nor truncated")
116+
assert.Equal(t, good, got[2])
117+
})
118+
}
119+
}
120+
121+
// Resynchronizing must accept exactly what the frame reader accepts, otherwise
122+
// a malformed run is cut short at a candidate that would then be rejected.
123+
func TestIsSyslogFrameStartRequiresCompletePRI(t *testing.T) {
124+
cases := []struct {
125+
in string
126+
want bool
127+
}{
128+
{"<134>x", true},
129+
{"<0>", true},
130+
{"<191>x", true},
131+
{"62 <134>x", true},
132+
{"<1 minute", false},
133+
{"<1234>x", false}, // PRIVAL is at most 3 digits
134+
{"<>", false},
135+
{"<13", false}, // undecidable here; the look-behind re-examines it
136+
{"54 <1 min", false},
137+
}
138+
for _, tc := range cases {
139+
assert.Equal(t, tc.want, isSyslogFrameStart([]byte(tc.in), 0), "input %q", tc.in)
140+
}
141+
}
142+
79143
// Genuine octet-counted frames must keep working, including when the length
80144
// prefix is split across reads: an incomplete signature has to wait for more
81145
// bytes rather than be declared malformed.
@@ -122,10 +186,15 @@ func TestClassifyOctetPrefix(t *testing.T) {
122186
{"2024-04-04T08:05:06", octetPrefixNo},
123187
{"71 x134>", octetPrefixNo},
124188
{"71 <x", octetPrefixNo},
189+
{"71 <>", octetPrefixNo},
125190
{"12345678901 <134>", octetPrefixNo}, // more digits than any plausible length
126-
{"71", octetPrefixNeedMore}, // digit run may continue
127-
{"71 ", octetPrefixNeedMore}, // need the byte after SP
128-
{"71 <", octetPrefixNeedMore}, // need the digit after '<'
191+
{"71 <1234>", octetPrefixNo}, // PRIVAL is at most 3 digits
192+
{"54 <1 minute elapsed", octetPrefixNo},
193+
{"71", octetPrefixNeedMore}, // digit run may continue
194+
{"71 ", octetPrefixNeedMore}, // need the byte after SP
195+
{"71 <", octetPrefixNeedMore}, // need the digit after '<'
196+
{"71 <1", octetPrefixNeedMore}, // PRIVAL may continue
197+
{"71 <134", octetPrefixNeedMore},
129198
}
130199
for _, tc := range cases {
131200
assert.Equal(t, tc.want, classifyOctetPrefix([]byte(tc.in)), "input %q", tc.in)

0 commit comments

Comments
 (0)