Skip to content

Commit 518c44c

Browse files
committed
fix(logs): recognize the IOS timestamp options Cisco documents
Cisco documents the IOS header as seq no:timestamp: %facility-severity-MNEMONIC:description where everything before the '%' varies with "service timestamps log [datetime|uptime] [msec] [localtime] [show-timezone]". Three of those options produced a header the parser could not read. show-timezone appends the zone name directly after the seconds, which lands in the TAG position: <187>Mar 1 18:46:11 UTC: %LINK-3-UPDOWN: Interface Serial0 up That parsed without error and set APP-NAME to "UTC", so every device sharing a timezone would route under a service named after it -- a misattribution with nothing to signal it, which is the failure this package is most concerned with. Absorb the zone into the TIMESTAMP instead. The test is narrow on purpose: two to five uppercase letters, terminated by a colon, and only when a Cisco mnemonic follows. Without that last condition a short uppercase TAG such as "GW: session opened" would be swallowed. msec appends fractional seconds, which is the shape Cisco's own Embedded Syslog Manager guide prints ("Mar 18 14:52:10.039:%LINK-5-CHANGED: ..."). The timestamp matched only its 15-byte prefix, leaving the parse to fail on the '.'; the message survived, since the wrapper always transmits the raw line, but it lost its sub-second precision, was flagged as a parse error, and had any CEF or LEEF payload inside it discarded. Accept the fraction on all four BSD layouts, as isoTimestampLen already did on the ISO ones. Cisco defines a leading '*' as meaning the clock never synchronized to a reliable source. Step over it so the header behind it parses. The marker is not kept in the TIMESTAMP, where it would defeat any downstream time parse; it stays visible in the content, which is transmitted verbatim. Uptime timestamps ("00:00:46:", "1w2d:") are deliberately left alone. They are time since reboot rather than wall clock, so there is nothing to extract and passing the line to MSG is already correct. benchstat over eight runs: geomean +0.01%, allocations unchanged. Parse_BSD alone shows +4.7% that I could not attribute -- ParseBSDLine exercises nearly the same path at +0.8% -- and it is likely code layout.
1 parent 461135d commit 518c44c

2 files changed

Lines changed: 277 additions & 12 deletions

File tree

pkg/logs/internal/parsers/syslog/syslog.go

Lines changed: 105 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -215,6 +215,11 @@ func Parse(line []byte) (SyslogMessage, error) {
215215
}
216216
case (b >= 'A' && b <= 'Z') || (b >= 'a' && b <= 'z'):
217217
msg, err = parseBSD(line, pri, pos)
218+
case b == '*':
219+
// Cisco IOS marks an unsynchronized clock with '*' before the
220+
// TIMESTAMP. parseBSD steps over it; if no timestamp follows it falls
221+
// back to treating the remainder as MSG.
222+
msg, err = parseBSD(line, pri, pos)
218223
default:
219224
// RFC 3164 §4.3.2: valid PRI, but what follows is neither a digit
220225
// (RFC 5424 VERSION) nor a letter (BSD TIMESTAMP month). Treat the
@@ -444,7 +449,29 @@ func parseBSD(line []byte, pri int, pos int) (SyslogMessage, error) {
444449
// Cisco ASA/FTD and Picus send in place of the BSD form. The ISO layout also
445450
// turns up in tailed files regardless of sender, because rsyslog's default
446451
// file template renders the timestamp as RFC 3339 and drops the PRI.
452+
// Cisco IOS writes '*' ahead of the TIMESTAMP when the system clock has
453+
// never synchronized to a reliable source. It is a marker rather than part
454+
// of the time, so step over it and record the timestamp itself; the '*'
455+
// stays visible in the content, which is transmitted verbatim. Only skip it
456+
// when a timestamp actually follows, so a body opening with '*' is left as
457+
// MSG.
458+
if pos < len(line) && line[pos] == '*' {
459+
if n, _ := timestampLen(line[pos+1:]); n > 0 {
460+
pos++
461+
}
462+
}
463+
447464
tsLen, isISOTimestamp := timestampLen(line[pos:])
465+
if !isISOTimestamp && tsLen > 0 {
466+
// "show-timezone" appends the zone name to the BSD layouts. It belongs
467+
// to the timestamp, not to the TAG position it occupies. A zone opens
468+
// with an uppercase letter and an ordinary HOSTNAME almost never does,
469+
// so that byte is tested before the call rather than inside it.
470+
if end := pos + tsLen; end+1 < len(line) &&
471+
line[end] == ' ' && line[end+1] >= 'A' && line[end+1] <= 'Z' {
472+
tsLen += bsdZoneSuffixLen(line[end:])
473+
}
474+
}
448475
if tsLen == 0 {
449476
if pos < len(line) && pri >= 0 {
450477
// RFC 3164 §4.3.2: valid PRI, content present but no valid
@@ -787,24 +814,90 @@ func bsdTimestampLen(b []byte) int {
787814
// opens with a month abbreviation. One look at the first byte therefore
788815
// picks the family, and the abbreviation is validated once rather than
789816
// once per layout.
817+
n := 0
790818
if isDigit(b[0]) {
791-
if isValidBSDTimestampYearFirst(b) {
792-
return 20
819+
if !isValidBSDTimestampYearFirst(b) {
820+
return 0
793821
}
822+
n = 20
823+
} else {
824+
if !isValidMonthAbbrev(b) {
825+
return 0
826+
}
827+
switch {
828+
case isValidBSDTimestamp(b):
829+
n = 15
830+
case isValidBSDTimestampSingleSpaceDay(b):
831+
n = 14
832+
case isValidBSDTimestampWithYear(b):
833+
n = 20
834+
default:
835+
return 0
836+
}
837+
}
838+
// Every layout ends in seconds, so an optional fraction attaches the same
839+
// way to all of them. The '.' is tested here so the common case of a
840+
// timestamp without one costs a single comparison.
841+
if len(b) > n && b[n] == '.' {
842+
n += bsdFractionLen(b[n:])
843+
}
844+
return n
845+
}
846+
847+
// bsdFractionLen returns the length of a fractional-seconds suffix — '.' and at
848+
// least one digit — at the start of b, or 0 if there is none. Cisco IOS appends
849+
// one under "service timestamps log datetime msec" ("Mar 18 14:52:10.039"),
850+
// which its own documentation uses throughout. Every BSD layout ends in seconds,
851+
// so the suffix attaches the same way to all of them, and isoTimestampLen
852+
// already accepts the equivalent on the ISO layouts.
853+
func bsdFractionLen(b []byte) int {
854+
if len(b) < 2 || b[0] != '.' || !isDigit(b[1]) {
794855
return 0
795856
}
796-
if !isValidMonthAbbrev(b) {
857+
i := 2
858+
for i < len(b) && isDigit(b[i]) {
859+
i++
860+
}
861+
return i
862+
}
863+
864+
// maxZoneAbbrevLen bounds a timezone abbreviation. Four letters covers the
865+
// longest in common use ("AEDT", "CEST"); five leaves room to spare.
866+
const maxZoneAbbrevLen = 5
867+
868+
// bsdZoneSuffixLen returns the length of a " ZONE" suffix following a BSD
869+
// TIMESTAMP, or 0 if there is none. Cisco IOS appends the zone name under
870+
// "service timestamps log datetime show-timezone", putting it exactly where a
871+
// TAG would sit:
872+
//
873+
// Mar 1 18:46:11 UTC: %LINK-3-UPDOWN: Interface Serial0 up
874+
//
875+
// Read as a TAG it becomes the APP-NAME, which then drives service routing from
876+
// a timezone. A bare uppercase token is far too weak a signal to act on, so the
877+
// suffix only counts when a Cisco mnemonic follows the colon that ends it —
878+
// leaving a genuine uppercase TAG ("GW: session opened") alone. The colon itself
879+
// is left in place for skipCiscoSeparator.
880+
func bsdZoneSuffixLen(b []byte) int {
881+
// A lowercase byte here is the overwhelmingly common case — an ordinary
882+
// HOSTNAME — so it is rejected before anything else runs.
883+
if len(b) < 2 || b[0] != ' ' || b[1] < 'A' || b[1] > 'Z' {
797884
return 0
798885
}
799-
switch {
800-
case isValidBSDTimestamp(b):
801-
return 15
802-
case isValidBSDTimestampSingleSpaceDay(b):
803-
return 14
804-
case isValidBSDTimestampWithYear(b):
805-
return 20
806-
}
807-
return 0
886+
i := 1
887+
for i < len(b) && i-1 < maxZoneAbbrevLen && b[i] >= 'A' && b[i] <= 'Z' {
888+
i++
889+
}
890+
if i-1 < 2 || i >= len(b) || b[i] != ':' {
891+
return 0
892+
}
893+
rest := b[i+1:]
894+
for len(rest) > 0 && rest[0] == ' ' {
895+
rest = rest[1:]
896+
}
897+
if !startsWithCiscoMnemonic(rest) {
898+
return 0
899+
}
900+
return i
808901
}
809902

810903
// timestampLen returns the length of the TIMESTAMP at the start of b and

pkg/logs/internal/parsers/syslog/timestamp_variants_test.go

Lines changed: 172 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -210,6 +210,66 @@ func TestParseUnrecognizedTimestampLayouts(t *testing.T) {
210210
procid: nilvalue,
211211
msg: ": %FTD-6-305012: Teardown dynamic UDP translation",
212212
},
213+
{
214+
// Cisco documents the IOS header as
215+
// "seq no:timestamp: %facility-severity-MNEMONIC:description", the
216+
// part before the '%' varying with "service timestamps log". The
217+
// msec option is what its own Embedded Syslog Manager guide prints:
218+
// "000013: Mar 18 14:52:10.039:%LINK-5-CHANGED: ...". Without the
219+
// fractional seconds the timestamp ends mid-token and the header
220+
// fails to parse at all.
221+
name: "cisco ios datetime msec",
222+
line: "<187>Mar 18 14:52:10.039: %LINK-5-CHANGED: Interface Serial3/3, changed state to administratively down",
223+
timestamp: "Mar 18 14:52:10.039",
224+
hostname: nilvalue,
225+
appname: nilvalue,
226+
procid: nilvalue,
227+
msg: "%LINK-5-CHANGED: Interface Serial3/3, changed state to administratively down",
228+
},
229+
{
230+
// The same guide prints no space between the colon and the '%'.
231+
name: "cisco ios datetime msec, no space before mnemonic",
232+
line: "<187>Mar 18 14:52:10.039:%LINK-5-CHANGED: Interface Serial3/3, changed state",
233+
timestamp: "Mar 18 14:52:10.039",
234+
hostname: nilvalue,
235+
appname: nilvalue,
236+
procid: nilvalue,
237+
msg: "%LINK-5-CHANGED: Interface Serial3/3, changed state",
238+
},
239+
{
240+
// "service timestamps log datetime show-timezone" appends the zone
241+
// name, which lands in the TAG position. Read as a TAG it becomes
242+
// the APP-NAME, so every device in a given zone would route under
243+
// a service named after its timezone.
244+
name: "cisco ios show-timezone",
245+
line: "<187>Mar 1 18:46:11 UTC: %LINK-3-UPDOWN: Interface Serial0, changed state to up",
246+
timestamp: "Mar 1 18:46:11 UTC",
247+
hostname: nilvalue,
248+
appname: nilvalue,
249+
procid: nilvalue,
250+
msg: "%LINK-3-UPDOWN: Interface Serial0, changed state to up",
251+
},
252+
{
253+
name: "cisco ios msec and show-timezone together",
254+
line: "<187>Mar 18 14:52:10.039 CEST: %LINK-5-CHANGED: Interface Serial3/3, changed state",
255+
timestamp: "Mar 18 14:52:10.039 CEST",
256+
hostname: nilvalue,
257+
appname: nilvalue,
258+
procid: nilvalue,
259+
msg: "%LINK-5-CHANGED: Interface Serial3/3, changed state",
260+
},
261+
{
262+
// Cisco documents '*' before the time as meaning the system clock
263+
// never synchronized to a reliable source. It is a marker, not part
264+
// of the time, and the header behind it parses normally.
265+
name: "cisco ios unsynchronized clock marker",
266+
line: "<187>*Mar 1 18:46:11.000: %LINK-3-UPDOWN: Interface Serial0, changed state to up",
267+
timestamp: "Mar 1 18:46:11.000",
268+
hostname: nilvalue,
269+
appname: nilvalue,
270+
procid: nilvalue,
271+
msg: "%LINK-3-UPDOWN: Interface Serial0, changed state to up",
272+
},
213273
}
214274

215275
for _, tc := range cases {
@@ -231,6 +291,87 @@ func TestParseUnrecognizedTimestampLayouts(t *testing.T) {
231291
}
232292
}
233293

294+
// Absorbing a timezone name into the TIMESTAMP is only safe while it stays
295+
// narrow. An uppercase token after the time is otherwise indistinguishable from
296+
// a short TAG or a hostname, so nothing here may be given up to recognize a
297+
// zone: the Cisco mnemonic behind the colon is the whole justification.
298+
func TestTimezoneSuffixDoesNotEatTags(t *testing.T) {
299+
cases := []struct {
300+
name string
301+
line string
302+
timestamp string
303+
hostname string
304+
appname string
305+
msg string
306+
}{
307+
{
308+
// Shaped exactly like the zone case but without a mnemonic, so the
309+
// token is a TAG and has to stay one.
310+
name: "uppercase tag is not a timezone",
311+
line: "<134>Jan 1 00:00:00 GW: session opened for user root",
312+
timestamp: "Jan 1 00:00:00",
313+
hostname: nilvalue,
314+
appname: "GW",
315+
msg: "session opened for user root",
316+
},
317+
{
318+
// A zone-shaped token in the HOSTNAME position with no colon is a
319+
// hostname, whatever it is named.
320+
name: "zone-shaped hostname is left alone",
321+
line: "<134>Feb 10 12:00:00 UTC sshd: not a mnemonic body",
322+
timestamp: "Feb 10 12:00:00",
323+
hostname: "UTC",
324+
appname: "sshd",
325+
msg: "not a mnemonic body",
326+
},
327+
{
328+
// Only the token directly after the timestamp can be a zone; once a
329+
// HOSTNAME has been read, the next one is a TAG.
330+
name: "zone-shaped tag after a hostname",
331+
line: "<134>Feb 10 12:00:00 myhost UTC: still a tag",
332+
timestamp: "Feb 10 12:00:00",
333+
hostname: "myhost",
334+
appname: "UTC",
335+
msg: "still a tag",
336+
},
337+
{
338+
// Fractional seconds end at the digits and must not run into the
339+
// HOSTNAME behind them.
340+
name: "fraction does not consume the hostname",
341+
line: "<134>Feb 10 12:00:00.5 myhost sshd: ok",
342+
timestamp: "Feb 10 12:00:00.5",
343+
hostname: "myhost",
344+
appname: "sshd",
345+
msg: "ok",
346+
},
347+
}
348+
349+
for _, tc := range cases {
350+
t.Run(tc.name, func(t *testing.T) {
351+
msg, err := Parse([]byte(tc.line))
352+
require.NoError(t, err)
353+
assert.Equal(t, tc.timestamp, msg.Timestamp, "timestamp")
354+
assert.Equal(t, tc.hostname, msg.Hostname, "hostname")
355+
assert.Equal(t, tc.appname, msg.AppName, "appname")
356+
assert.Equal(t, tc.msg, string(msg.Msg), "msg")
357+
})
358+
}
359+
}
360+
361+
// '*' is only a clock marker when a timestamp follows it. Anywhere else it is
362+
// ordinary content and must reach MSG intact.
363+
func TestAsteriskWithoutTimestampIsContent(t *testing.T) {
364+
for _, line := range []string{
365+
"<134>*** ALERT *** disk full on /var",
366+
"<134>*not a timestamp at all",
367+
} {
368+
msg, err := Parse([]byte(line))
369+
require.NoError(t, err)
370+
assert.Equal(t, nilvalue, msg.Timestamp)
371+
assert.Equal(t, line[len("<134>"):], string(msg.Msg), "input %q", line)
372+
}
373+
}
374+
234375
// The colon ASA writes after an ISO timestamp is skipped whatever follows it,
235376
// not only a Cisco mnemonic. Every ASA and FTD sample happens to carry one, so
236377
// nothing else in the suite covers the general case: drop this handling and a
@@ -519,8 +660,39 @@ func TestBSDTimestampLen(t *testing.T) {
519660
{"Jan 9 03-47-40", 0},
520661
{"2024-04-04T08:05:06Z", 0},
521662
{"", 0},
663+
664+
// Fractional seconds attach to every layout.
665+
{"Mar 18 14:52:10.039", 19},
666+
{"Jan 9 03:47:40.5", 16},
667+
{"Apr 04 2024 08:05:06.123456", 27},
668+
{"2024 Apr 04 08:05:06.039", 24},
669+
{"Mar 18 14:52:10.", 15}, // '.' with no digits is not a fraction
670+
{"Mar 18 14:52:10.x", 15}, // nor is a non-digit
671+
{"Mar 18 14:52:10 UTC", 15}, // the zone is not part of the bare layout
522672
}
523673
for _, tc := range cases {
524674
assert.Equal(t, tc.want, bsdTimestampLen([]byte(tc.in)), "input %q", tc.in)
525675
}
526676
}
677+
678+
func TestBSDZoneSuffixLen(t *testing.T) {
679+
cases := []struct {
680+
in string
681+
want int
682+
}{
683+
{" UTC: %LINK-3-UPDOWN: up", 4},
684+
{" CEST: %ASA-6-302013: built", 5},
685+
{" AEDT:%FTD-1-430003: x", 5},
686+
{" UTC: %SYS-5-CONFIG_I: x", 4}, // Cisco allows spaces after the colon
687+
{" GW: session opened", 0}, // no mnemonic: a TAG, not a zone
688+
{" UTC %LINK-3-UPDOWN: up", 0}, // no colon terminating the zone
689+
{" U: %LINK-3-UPDOWN: up", 0}, // too short to be a zone
690+
{" TOOLONGZONE: %LINK-3-UPDOWN: up", 0},
691+
{" utc: %LINK-3-UPDOWN: up", 0}, // zone names are uppercase
692+
{"UTC: %LINK-3-UPDOWN: up", 0}, // must be preceded by SP
693+
{"", 0},
694+
}
695+
for _, tc := range cases {
696+
assert.Equal(t, tc.want, bsdZoneSuffixLen([]byte(tc.in)), "input %q", tc.in)
697+
}
698+
}

0 commit comments

Comments
 (0)