-
-
Notifications
You must be signed in to change notification settings - Fork 7
feat(rfc3164): extend RFC3164 parser to support Cisco IOS logs #22
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Conversation
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thank you for your contribution!
Aside from the test errors (we'll focus on those later),
I think these sequence changes (not in the RFC3164 AFAIK) should be hidden behind a machine option.
Meaning, I would like to have a WithSequence() or WithCiscoSequence() machine option to expressly change the behavior of the parsing machine.
Can you please iterate on this? 🙏
|
Another thing I'm noticing now is... Where is the priority part in the example message you reported? I never saw (not that I remember) a Syslog message like this one... Shouldn't it be something like the following one? |
|
That seems reasonable. 4b1f2a2 makes this sequence parsing optional. I had to update the test structure a bit to allow options to be passed in -- let me know if you think there's a better way. As for the missing priority, I think that's because I pasted output from tcpdump which itself parses the priority into facility and severity: |
leodido
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thank you for your contribution. ❤️
I did a first review round and left some comments/questions.
|
Hi, I have stumbled across the same issue of cisco logs not getting ingested due to their syslog format beeing malformed. Is there still work ongoing on this PR? I'd love to see this merged. I'd be happy to help out, but my go skills are a little lacking, i cant seem to get alloy (with the imports overwritten) to compile with these changes. |
|
Thanks for the nudge @go3ranh -- I've been busy with other things but made some time to iterate again on this PR. |
rfc3164/machine.go.rl
Outdated
| // WithSequence enables parsing of non-standard Cisco iOS logs that include a sequence number. | ||
| // | ||
| // See https://www.cisco.com/c/en/us/td/docs/routers/access/wireless/software/guide/SysMsgLogging.html#wp1054751 | ||
| // and https://www.cisco.com/c/en/us/td/docs/ios-xml/ios/esm/command/esm-cr-book/book_cjab_m_escalate-a-cisco-jabber-group_chapter_00.html#wp4026302234 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'd put the config explanation here - something like:
To ensure your IOS device sending logs in a compatible format, be sure to disable logging sequence numbers by setting no service sequence-numbers in configuration mode. The device will still send a message counter, which you cant see in the log on device. This is enabled by default and can manually be enabled with the following command: logging message-counter syslog. This option should for now not be disabled, as it merely removes the number, not the colon behind it, resulting in invalid log messages.
When debugging with packet captures, your log messages should look like this:
"<189>237: *Jan 8 19:46:03.295..."
Ensure ntp sync on your device, to remove the star in front of the timestamp - the star will lead to the logs being dropped.
Feel free to rephrase anything, english is not my first language.
@leodido let me know, if this is not the place you want this verbose sort of documentation, I'll gladly put it somewhere else.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks, that's super helpful! I've updated the comment, though I omitted the bit about the NTP sync, because the pattern I have here should match the * (though I've just now made it optional).
|
@leodido Pardon me bugging you again but would you be willing to merge this? Is there anything, you'd like to see changed before? |
|
This looks like great addition! Is there a chance it would also work with optional hostname/ip (origin) header is also can be included in cisco syslog format? This is normally added with command: Message would be:
instead of: p.s. in rsyslog, this can be turned on/off in parser with https://www.rsyslog.com/doc/configuration/modules/pmciscoios.html#present-origin . there is also additional parser toggle for ios xr logging. |
since Cisco does not seem to be RFC compliant in any way, this might not really fit in this rfc3164 parser :D |
leodido
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Left a comment about partialtime for now. Will continue review later.
Regarding #22 (comment) see PR #25. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think the work done here by you folks is valuable. ❤️
But we need to give it a bit of structure... :)
I would approach it by splitting it into the following main tasks:
- Implement
WithMessageCounter()option and related conditional grammar changes intomachine.go.rl - Implement
WithSequenceNumber()option and related conditional grammar changes intomachine.go.rl - Possibly implement also an option for Cisco IOS hostname into
machine.go.rl - Implement
rfc3164.WithCiscoIOSComponents()(or similar name) that sets the above machine options, plus theWithSecondFractions()I've done in PR #25
This last point can also be approached by creating 3 different rfc3164 optioner functions, but it's probably overkill.
Another approach (probably better) would be to have :
rfc3164.WithCiscoIOSComponents(
MessageCounterOff | SequenceNumberOff | HostnameWhateverOff
)
to selectively enable/disable the component of the Cisco IOS syslog that the user wants or not.
Please rebase this PR on top of the current default main branch.
These devices seem to send non-standard logs that include a sequence
number, and a couple of extra characters (for good luck, I assume).
For example:
```
10.51.101.233.50433 > 10.51.101.164.514: SYSLOG, length: 112 Facility local7 (23), Severity notice (5)
Msg: 485: *Jan 8 21:50:03.406: %LINEPROTO-5-UPDOWN: Line protocol on Interface Loopback100, changed state to up
```
Note the `485: *` here. This is the sequence number (and a `*` -- no
idea).
It also includes a ms-precision timestamp.
…2 new fields) Signed-off-by: Leonardo Di Donato <[email protected]>
…fields) Signed-off-by: Leonardo Di Donato <[email protected]>
leodido
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ok, last mile...
I've fixed the examples/tests that were failing. I would need you to write some more test cases.
In particular, we would need to test a few combinations of Cisco IOS errors by disabling some components.
| // hostname parsers enabled then the message counter would be parsed as the | ||
| // sequence number, and the sequence number as the hostname. | ||
| opts: []syslog.MachineOption{ | ||
| WithCiscoIOSComponents(ciscoios.DisableMessageCounter | ciscoios.DisableSequenceNumber | ciscoios.DisableHostname), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@leodido regarding the note in the comment here, I'm not good enough with Ragel to know whether this can be solved, or if this is the best we can hope for given that the message counter is a valid sequence number, and the sequence number is a valid hostname.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hmmm, this is either precedence territory (see the Ragel guide at page 11) and/or lookahead territory.
But we must first understand the problem.
For this purpose, we should answer an important question. Is the ordering of the message counter, the sequence number, and the hostname fixed?
If the order is fixed, we could scan the message as a set of colon-delimited components, with a minimum of one component and a maximum of four components.
Considering only the Cisco IOS components (excluding the time fractions one):
*?<timestamp>: // All components disabled
<hostname>: *?<timestamp>: // Message count and sequence number disabled
<seqnum>: <hostname>: *?<timestamp>: // Message count disabled
<msgcount>: <seqnum>: <hostname>: *?<timestamp>: // None disabled (default)
This assuming that the colon following each component is present only when that component is present, which is still unclear...
An approach could be to span (fgoto) to a new machine that parses all those colon-delimited components. When this is done successfully, return the control to the main machine.
Anyway, before progressing further... Can we have examples of Cisco IOS logs with and without those components?
An example log with the message counter versus the same without it. Same for the other components. It would help framing the problem we are trying to solve better.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@go3ranh can you help out with some examples here?
For example, is it possible to disable say msgcount and leave seqnum (and what does it look like?)
What happens if we disable everything except hostname? (etc etc)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
ill hopefully get to it tomorrow!
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@go3ranh do you have some time to look at this?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm sorry for the delay, didn't have a device on hand:
The following are extracted from pcap files, every reading from ... line denotes a new capture file with settings changed. I am sorry for having the structured arguments block (almost) always turned on
reading from file ./all-logging-settings-turned-on.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E.........7..........M...}9.<189>106: [syslog@9 s_sn="25" s_id ="sw1:666"]: *Jan 2 00:18:01: %SYS-5-CONFIG_I: Configured from console by console
E.........7..........M.... .<187>107: [syslog@9 s_sn="26" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/1, changed state to down
E.........7..........M.... .<187>108: [syslog@9 s_sn="27" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/2, changed state to down
E.........7..........M.... .<187>109: [syslog@9 s_sn="28" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/3, changed state to down
E.........7..........M......<187>110: [syslog@9 s_sn="29" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/4, changed state to down
E.........7..........M......<187>111: [syslog@9 s_sn="30" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/5, changed state to down
E.........7..........M......<187>112: [syslog@9 s_sn="31" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/6, changed state to down
E.........7..........M......<187>113: [syslog@9 s_sn="32" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/7, changed state to down
E.... ....7..........M......<187>114: [syslog@9 s_sn="33" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/8, changed state to down
E....!....7..........M......<187>115: [syslog@9 s_sn="34" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/9, changed state to down
E...."....7..........M....n.<187>116: [syslog@9 s_sn="35" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/10, changed state to down
E....#....7..........M....m.<187>117: [syslog@9 s_sn="36" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/11, changed state to down
E....$....7..........M....l.<187>118: [syslog@9 s_sn="37" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/12, changed state to down
E....%....7..........M....k.<187>119: [syslog@9 s_sn="38" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/13, changed state to down
E....&....7..........M....i.<187>120: [syslog@9 s_sn="39" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/14, changed state to down
E....'....7..........M....g.<187>121: [syslog@9 s_sn="40" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/15, changed state to down
E....(....7..........M....f.<187>122: [syslog@9 s_sn="41" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/16, changed state to down
E....)....7..........M....e.<187>123: [syslog@9 s_sn="42" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/17, changed state to down
E....*....7..........M....d.<187>124: [syslog@9 s_sn="43" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/18, changed state to down
E....+....7..........M....c.<187>125: [syslog@9 s_sn="44" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/19, changed state to down
E....,....7..........M....l.<187>126: [syslog@9 s_sn="45" s_id ="sw1:666"]: *Jan 2 00:18:03: %LINK-3-UPDOWN: Interface GigabitEthernet0/20, changed state to down
reading from file ./uptime-timestamp.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E....Y....7..........M...}<.<189>171: [syslog@9 s_sn="90" s_id ="sw1:666"]: 000167: 00:24:07: %SYS-5-CONFIG_I: Configured from console by console
E....Z....7..........M...};.<189>172: [syslog@9 s_sn="91" s_id ="sw1:666"]: 000168: 00:24:19: %SYS-5-CONFIG_I: Configured from console by console
E....[....7..........M.....$<189>173: [syslog@9 s_sn="92" s_id ="sw1:666"]: 000169: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/1, changed state to administratively down
E....\....7..........M.....+<189>174: [syslog@9 s_sn="93" s_id ="sw1:666"]: 000170: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/2, changed state to administratively down
E....]....7..........M.....(<189>175: [syslog@9 s_sn="94" s_id ="sw1:666"]: 000171: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/3, changed state to administratively down
E....^....7..........M.....%<189>176: [syslog@9 s_sn="95" s_id ="sw1:666"]: 000172: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/4, changed state to administratively down
E...._....7..........M....."<189>177: [syslog@9 s_sn="96" s_id ="sw1:666"]: 000173: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/5, changed state to administratively down
E....`....7..........M......<189>178: [syslog@9 s_sn="97" s_id ="sw1:666"]: 000174: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/6, changed state to administratively down
E....a....7..........M......<189>179: [syslog@9 s_sn="98" s_id ="sw1:666"]: 000175: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/7, changed state to administratively down
E....b....7..........M.....#<189>180: [syslog@9 s_sn="99" s_id ="sw1:666"]: 000176: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/8, changed state to administratively down
E....c....7..........M......<189>181: [syslog@9 s_sn="100" s_id ="sw1:666"]: 000177: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/9, changed state to administratively down
E....d....7..........M......<189>182: [syslog@9 s_sn="101" s_id ="sw1:666"]: 000178: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/10, changed state to administratively down
E....e....7..........M......<189>183: [syslog@9 s_sn="102" s_id ="sw1:666"]: 000179: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/11, changed state to administratively down
E....f....7~.........M......<189>184: [syslog@9 s_sn="103" s_id ="sw1:666"]: 000180: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/12, changed state to administratively down
E....g....7}.........M......<189>185: [syslog@9 s_sn="104" s_id ="sw1:666"]: 000181: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/13, changed state to administratively down
E....h....7|.........M......<189>186: [syslog@9 s_sn="105" s_id ="sw1:666"]: 000182: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/14, changed state to administratively down
E....i....7{.........M......<189>187: [syslog@9 s_sn="106" s_id ="sw1:666"]: 000183: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/15, changed state to administratively down
E....j....7z.........M......<189>188: [syslog@9 s_sn="107" s_id ="sw1:666"]: 000184: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/16, changed state to administratively down
E....k....7y.........M......<189>189: [syslog@9 s_sn="108" s_id ="sw1:666"]: 000185: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/17, changed state to administratively down
E....l....7x.........M......<189>190: [syslog@9 s_sn="109" s_id ="sw1:666"]: 000186: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/18, changed state to administratively down
E....m....7w.........M......<189>191: [syslog@9 s_sn="110" s_id ="sw1:666"]: 000187: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/19, changed state to administratively down
E....n....7v.........M......<189>192: [syslog@9 s_sn="111" s_id ="sw1:666"]: 000188: 00:24:21: %LINK-5-CHANGED: Interface GigabitEthernet0/20, changed state to administratively down
reading from file ./session-id-hostname.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E.........8..............r..<189>33: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:21: %SYS-5-CONFIG_I: Configured from console by console
E.........8..............r..<189>34: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:36: %SYS-5-CONFIG_I: Configured from console by console
E.... ....7...............3.<189>35: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/1, changed state to administratively down
E....
E.........7...............1.<189>37: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/3, changed state to administratively down
E.........7...............0.<189>38: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/4, changed state to administratively down
E.........7.............../.<189>39: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/5, changed state to administratively down
E.........7...............8.<189>40: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/6, changed state to administratively down
E.........7...............7.<189>41: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/7, changed state to administratively down
E.........7...............6.<189>42: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/8, changed state to administratively down
E.........7...............5.<189>43: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/9, changed state to administratively down
E.........7...............S.<189>44: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/10, changed state to administratively down
E.........7...............Q.<189>45: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/11, changed state to administratively down
E.........7...............O.<189>46: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/12, changed state to administratively down
E.........7...............M.<189>47: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/13, changed state to administratively down
E.........7...............K.<189>48: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/14, changed state to administratively down
E.........7...............I.<189>49: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/15, changed state to administratively down
E.........7...............Q.<189>50: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/16, changed state to administratively down
E.........7...............O.<189>51: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/17, changed state to administratively down
E.........7...............M.<189>52: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/18, changed state to administratively down
E.........7...............K.<189>53: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/19, changed state to administratively down
E.........7...............S.<189>54: [syslog@9 s_id ="sw1:666"]: *Jan 2 00:14:37: %LINK-5-CHANGED: Interface GigabitEthernet0/20, changed state to administratively down
reading from file ./logging-message-counters-syslog.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E....C....7..........M....h.<189>149: [syslog@9 s_sn="68" s_id ="sw1:666"]: 000145: *Jan 2 00:20:28: %SYS-5-CONFIG_I: Configured from console by console
E....D....7..........M....f.<189>150: [syslog@9 s_sn="69" s_id ="sw1:666"]: 000146: *Jan 2 00:20:39: %SYS-5-CONFIG_I: Configured from console by console
E....E....7..........M....4.<187>151: [syslog@9 s_sn="70" s_id ="sw1:666"]: 000147: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/1, changed state to down
E....F....7..........M....4.<187>152: [syslog@9 s_sn="71" s_id ="sw1:666"]: 000148: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/2, changed state to down
E....G....7..........M....4.<187>153: [syslog@9 s_sn="72" s_id ="sw1:666"]: 000149: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/3, changed state to down
E....H....7..........M....3.<187>154: [syslog@9 s_sn="73" s_id ="sw1:666"]: 000150: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/4, changed state to down
E....I....7..........M....3.<187>155: [syslog@9 s_sn="74" s_id ="sw1:666"]: 000151: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/5, changed state to down
E....J....7..........M....3.<187>156: [syslog@9 s_sn="75" s_id ="sw1:666"]: 000152: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/6, changed state to down
E....K....7..........M....3.<187>157: [syslog@9 s_sn="76" s_id ="sw1:666"]: 000153: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/7, changed state to down
E....L....7..........M....3.<187>158: [syslog@9 s_sn="77" s_id ="sw1:666"]: 000154: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/8, changed state to down
E....M....7..........M....3.<187>159: [syslog@9 s_sn="78" s_id ="sw1:666"]: 000155: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/9, changed state to down
E....N....7..........M.....(<187>160: [syslog@9 s_sn="79" s_id ="sw1:666"]: 000156: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/10, changed state to down
E....O....7..........M...../<187>161: [syslog@9 s_sn="80" s_id ="sw1:666"]: 000157: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/11, changed state to down
E....P....7..........M.....,<187>162: [syslog@9 s_sn="81" s_id ="sw1:666"]: 000158: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/12, changed state to down
E....Q....7..........M.....)<187>163: [syslog@9 s_sn="82" s_id ="sw1:666"]: 000159: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/13, changed state to down
E....R....7..........M.....0<187>164: [syslog@9 s_sn="83" s_id ="sw1:666"]: 000160: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/14, changed state to down
E....S....7..........M.....-<187>165: [syslog@9 s_sn="84" s_id ="sw1:666"]: 000161: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/15, changed state to down
E....T....7..........M.....*<187>166: [syslog@9 s_sn="85" s_id ="sw1:666"]: 000162: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/16, changed state to down
E....U....7..........M.....'<187>167: [syslog@9 s_sn="86" s_id ="sw1:666"]: 000163: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/17, changed state to down
E....V....7..........M.....$<187>168: [syslog@9 s_sn="87" s_id ="sw1:666"]: 000164: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/18, changed state to down
E....W....7..........M.....!<187>169: [syslog@9 s_sn="88" s_id ="sw1:666"]: 000165: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/19, changed state to down
E....X....7..........M.....'<187>170: [syslog@9 s_sn="89" s_id ="sw1:666"]: 000166: *Jan 2 00:20:41: %LINK-3-UPDOWN: Interface GigabitEthernet0/20, changed state to down
reading from file ./no-options.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E..j......8+.............V.M<189>30: *Jan 2 00:10:53: %SYS-5-CONFIG_I: Configured from console by console
E..z......8..............f..<187>31: *Jan 2 00:11:18: %LINK-3-UPDOWN: Interface GigabitEthernet0/1, changed state to down
E..j......8).............V.O<189>32: *Jan 2 00:11:22: %SYS-5-CONFIG_I: Configured from console by console
reading from file ./sequence-num-sessions.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E.........7.................<190>56: [syslog@9 s_sn="31"]: *Jan 2 00:16:02: %SYS-6-LOGGINGHOST_STARTSTOP: Logging to host 192.168.1.1 port 666 restored CLI initiated
E.........7..............l..<189>57: [syslog@9 s_sn="32"]: *Jan 2 00:16:03: %SYS-5-CONFIG_I: Configured from console by console
E.... ....7..............l..<189>58: [syslog@9 s_sn="33"]: *Jan 2 00:16:16: %SYS-5-CONFIG_I: Configured from console by console
E....!....7..............|.:<187>59: [syslog@9 s_sn="34"]: *Jan 2 00:16:16: %LINK-3-UPDOWN: Interface GigabitEthernet0/1, changed state to down
E...."....7..............|.9<187>60: [syslog@9 s_sn="35"]: *Jan 2 00:16:16: %LINK-3-UPDOWN: Interface GigabitEthernet0/2, changed state to down
E....#....7..............|.9<187>61: [syslog@9 s_sn="36"]: *Jan 2 00:16:16: %LINK-3-UPDOWN: Interface GigabitEthernet0/3, changed state to down
E....$....7..............|.9<187>62: [syslog@9 s_sn="37"]: *Jan 2 00:16:16: %LINK-3-UPDOWN: Interface GigabitEthernet0/4, changed state to down
E....%....7..............|.9<187>63: [syslog@9 s_sn="38"]: *Jan 2 00:16:16: %LINK-3-UPDOWN: Interface GigabitEthernet0/5, changed state to down
E....&....7..............|.9<187>64: [syslog@9 s_sn="39"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/6, changed state to down
E....'....7..............|.8<187>65: [syslog@9 s_sn="40"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/7, changed state to down
E....(....7..............|.8<187>66: [syslog@9 s_sn="41"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/8, changed state to down
E....)....7..............|.8<187>67: [syslog@9 s_sn="42"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/9, changed state to down
E....*....7..............} .<187>68: [syslog@9 s_sn="43"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/10, changed state to down
E....+....7..............}..<187>69: [syslog@9 s_sn="44"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/11, changed state to down
E....,....7..............}..<187>70: [syslog@9 s_sn="45"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/12, changed state to down
E....-....7..............}..<187>71: [syslog@9 s_sn="46"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/13, changed state to down
E.........7..............}..<187>72: [syslog@9 s_sn="47"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/14, changed state to down
E..../....7..............} .<187>73: [syslog@9 s_sn="48"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/15, changed state to down
E....0....7..............}..<187>74: [syslog@9 s_sn="49"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/16, changed state to down
E....1....7..............}..<187>75: [syslog@9 s_sn="50"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/17, changed state to down
E....2....7..............}..<187>76: [syslog@9 s_sn="51"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/18, changed state to down
E....3....7..............}..<187>77: [syslog@9 s_sn="52"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/19, changed state to down
E....4....7..............}..<187>78: [syslog@9 s_sn="53"]: *Jan 2 00:16:17: %LINK-3-UPDOWN: Interface GigabitEthernet0/20, changed state to down
reading from file ./service-sequence-numbers.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E.........7..........M....d.<189>128: [syslog@9 s_sn="47" s_id ="sw1:666"]: 000124: *Jan 2 00:18:45: %SYS-5-CONFIG_I: Configured from console by console
E..../....7..........M......<189>129: [syslog@9 s_sn="48" s_id ="sw1:666"]: 000125: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/1, changed state to administratively down
E....0....7..........M......<189>130: [syslog@9 s_sn="49" s_id ="sw1:666"]: 000126: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/2, changed state to administratively down
E....1....7..........M......<189>131: [syslog@9 s_sn="50" s_id ="sw1:666"]: 000127: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/3, changed state to administratively down
E....2....7..........M......<189>132: [syslog@9 s_sn="51" s_id ="sw1:666"]: 000128: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/4, changed state to administratively down
E....3....7..........M......<189>133: [syslog@9 s_sn="52" s_id ="sw1:666"]: 000129: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/5, changed state to administratively down
E....4....7..........M......<189>134: [syslog@9 s_sn="53" s_id ="sw1:666"]: 000130: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/6, changed state to administratively down
E....5....7..........M......<189>135: [syslog@9 s_sn="54" s_id ="sw1:666"]: 000131: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/7, changed state to administratively down
E....6....7..........M......<189>136: [syslog@9 s_sn="55" s_id ="sw1:666"]: 000132: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/8, changed state to administratively down
E....7....7..........M......<189>137: [syslog@9 s_sn="56" s_id ="sw1:666"]: 000133: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/9, changed state to administratively down
E....8....7..........M....e.<189>138: [syslog@9 s_sn="57" s_id ="sw1:666"]: 000134: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/10, changed state to administratively down
E....9....7..........M....e*<189>139: [syslog@9 s_sn="58" s_id ="sw1:666"]: 000135: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/11, changed state to administratively down
E....:....7..........M....d0<189>140: [syslog@9 s_sn="59" s_id ="sw1:666"]: 000136: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/12, changed state to administratively down
E....;....7..........M....c6<189>141: [syslog@9 s_sn="60" s_id ="sw1:666"]: 000137: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/13, changed state to administratively down
E....<....7..........M....c2<189>142: [syslog@9 s_sn="61" s_id ="sw1:666"]: 000138: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/14, changed state to administratively down
E....=....7..........M....c.<189>143: [syslog@9 s_sn="62" s_id ="sw1:666"]: 000139: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/15, changed state to administratively down
E....>....7..........M....b4<189>144: [syslog@9 s_sn="63" s_id ="sw1:666"]: 000140: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/16, changed state to administratively down
E....?....7..........M....b0<189>145: [syslog@9 s_sn="64" s_id ="sw1:666"]: 000141: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/17, changed state to administratively down
[email protected],<189>146: [syslog@9 s_sn="65" s_id ="sw1:666"]: 000142: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/18, changed state to administratively down
E....A....7..........M....b(<189>147: [syslog@9 s_sn="66" s_id ="sw1:666"]: 000143: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/19, changed state to administratively down
E....B....7..........M....a.<189>148: [syslog@9 s_sn="67" s_id ="sw1:666"]: 000144: *Jan 2 00:18:47: %LINK-5-CHANGED: Interface GigabitEthernet0/20, changed state to administratively down
reading from file ./datetime-localtime-msec-year.pcap, link-type EN10MB (Ethernet), snapshot length 262144
E....o....7..........M....6.<189>193: [syslog@9 s_sn="112" s_id ="sw1:666"]: 000189: *Jan 1 2006 23:24:48.524: %SYS-5-CONFIG_I: Configured from console by console
E....p....7..........M....@.<189>194: [syslog@9 s_sn="113" s_id ="sw1:666"]: 000190: *Jan 1 2006 23:25:09.739: %SYS-5-CONFIG_I: Configured from console by console
E....q....7u.........M......<187>195: [syslog@9 s_sn="114" s_id ="sw1:666"]: 000191: *Jan 1 2006 23:25:10.888: %LINK-3-UPDOWN: Interface GigabitEthernet0/1, changed state to down
E....r....7t.........M......<187>196: [syslog@9 s_sn="115" s_id ="sw1:666"]: 000192: *Jan 1 2006 23:25:10.897: %LINK-3-UPDOWN: Interface GigabitEthernet0/2, changed state to down
E....s....7s.........M......<187>197: [syslog@9 s_sn="116" s_id ="sw1:666"]: 000193: *Jan 1 2006 23:25:10.905: %LINK-3-UPDOWN: Interface GigabitEthernet0/3, changed state to down
E....t....7r.........M....
E....u....7q.........M......<187>199: [syslog@9 s_sn="118" s_id ="sw1:666"]: 000195: *Jan 1 2006 23:25:10.914: %LINK-3-UPDOWN: Interface GigabitEthernet0/5, changed state to down
E....v....7p.........M......<187>200: [syslog@9 s_sn="119" s_id ="sw1:666"]: 000196: *Jan 1 2006 23:25:10.922: %LINK-3-UPDOWN: Interface GigabitEthernet0/6, changed state to down
E....w....7o.........M......<187>201: [syslog@9 s_sn="120" s_id ="sw1:666"]: 000197: *Jan 1 2006 23:25:10.930: %LINK-3-UPDOWN: Interface GigabitEthernet0/7, changed state to down
E....x....7n.........M......<187>202: [syslog@9 s_sn="121" s_id ="sw1:666"]: 000198: *Jan 1 2006 23:25:10.947: %LINK-3-UPDOWN: Interface GigabitEthernet0/8, changed state to down
E....y....7m.........M......<187>203: [syslog@9 s_sn="122" s_id ="sw1:666"]: 000199: *Jan 1 2006 23:25:10.947: %LINK-3-UPDOWN: Interface GigabitEthernet0/9, changed state to down
E....z....7k.........M....}U<187>204: [syslog@9 s_sn="123" s_id ="sw1:666"]: 000200: *Jan 1 2006 23:25:10.956: %LINK-3-UPDOWN: Interface GigabitEthernet0/10, changed state to down
E....{....7j.........M....yV<187>205: [syslog@9 s_sn="124" s_id ="sw1:666"]: 000201: *Jan 1 2006 23:25:10.964: %LINK-3-UPDOWN: Interface GigabitEthernet0/11, changed state to down
E....|....7i.........M....uW<187>206: [syslog@9 s_sn="125" s_id ="sw1:666"]: 000202: *Jan 1 2006 23:25:10.972: %LINK-3-UPDOWN: Interface GigabitEthernet0/12, changed state to down
E....}....7h.........M....qW<187>207: [syslog@9 s_sn="126" s_id ="sw1:666"]: 000203: *Jan 1 2006 23:25:10.981: %LINK-3-UPDOWN: Interface GigabitEthernet0/13, changed state to down
E....~....7g.........M....nN<187>208: [syslog@9 s_sn="127" s_id ="sw1:666"]: 000204: *Jan 1 2006 23:25:10.989: %LINK-3-UPDOWN: Interface GigabitEthernet0/14, changed state to down
E.........7f.........M....jO<187>209: [syslog@9 s_sn="128" s_id ="sw1:666"]: 000205: *Jan 1 2006 23:25:10.997: %LINK-3-UPDOWN: Interface GigabitEthernet0/15, changed state to down
E.........7e.........M....oa<187>210: [syslog@9 s_sn="129" s_id ="sw1:666"]: 000206: *Jan 1 2006 23:25:11.006: %LINK-3-UPDOWN: Interface GigabitEthernet0/16, changed state to down
E.........7d.........M....ua<187>211: [syslog@9 s_sn="130" s_id ="sw1:666"]: 000207: *Jan 1 2006 23:25:11.014: %LINK-3-UPDOWN: Interface GigabitEthernet0/17, changed state to down
E.........7c.........M....qa<187>212: [syslog@9 s_sn="131" s_id ="sw1:666"]: 000208: *Jan 1 2006 23:25:11.023: %LINK-3-UPDOWN: Interface GigabitEthernet0/18, changed state to down
E.........7b.........M....mb<187>213: [syslog@9 s_sn="132" s_id ="sw1:666"]: 000209: *Jan 1 2006 23:25:11.031: %LINK-3-UPDOWN: Interface GigabitEthernet0/19, changed state to down
E.........7a.........M....~_<187>214: [syslog@9 s_sn="133" s_id ="sw1:666"]: 000210: *Jan 1 2006 23:25:11.031: %LINK-3-UPDOWN: Interface GigabitEthernet0/20, changed state to down
these are straight pcaps, i also have the raw files lying around.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
i realized that these don't actually include a sample without the sequence number with just the colon, but i wont have access to a physical device for another month and don't want to rely on unofficial, outdated simulator logs. I'm really sorry I'll provide this as soon as i have on again
|
Ok @leodido I think I've addressed your comments. Let me know if the tests are ok and/or if you have any ideas about making the parser better at detecting specific errors (as I noted in the comment). |
leodido
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
|
|
||
| # Cisco IOS devices sometimes include a "message counter" before the timestamp | ||
| # "<189>237: *Jan 8 19:46:03.295..." | ||
| msgcountval = (digit*) >mark %set_msgcount @err(err_msgcount); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why do we have digit* here while for the sequence number we do have digit+?
Asking because it would parse <PRI>: as valid, but what would be the message counter value? Zero?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, that's what happens if you disable the message counter: https://github.com/leodido/go-syslog/pull/22/files#diff-7c1da6249183aa35b9f43da53d4df1d7bfa91d32bc29e63267436cf45b7686cdR298-R299
See also this comment #22 (comment)
Signed-off-by: Leonardo Di Donato <[email protected]>
| # and optionally put a hostname before the timestamp | ||
| ciscoHostname = (hostname ':' sp*)? when { m.ciscoHostname }; | ||
| # and then they prepend a '*' to the timestamp if there is no NTP sync | ||
| ciscostar = ('*'?) when { m.msgcount || m.sequence || m.ciscoHostname }; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not top priority, but we may want to capture the presence of the asterisk in a machine field (withoutNTPSync = true, by default false).
|
Is this PR still active? I've seen a few requests for Cisco support in Grafana Alloy which utilizes go-syslog and was sent this open PR, just checking if it's moving towards merge. |
|
I am sorry, i forgot about this, our workaround is working :D (cisco logs -> rsyslog(normalizes to rfc) -> alloy) The following zip file contains a pcap where I reproduced the single leading colon. this second zip file has all kinds of configurations, not sure which are supported, but the leading colon is a bug I think. The following is a script file recording of my terminal with the cisco config commands when i created these captures for reference. The last ~30 lines correspond to dump2 (the first file with the colon) and the start of the script is all the rest (less interesting, but for reference) ty for poking @dehaansa :D |
|
@go3ranh, thanks for the pcap dumps. @alistairking, I have a commit with some more test cases (coming from the pcap dumps) but for some reason I can't push anymore to the PR branch: Was the fork moved? Please give me back access so that I can refine this PR. |
|
After carefully reviewing this PR, I've decided not to treat the ordering issue as a bug, at least until I have more clarity on it. Reflecting on the topic, it appears to be more of a configuration issue to me. We cannot auto-detect whether either the message counter or the sequence number is present because they both follow the pattern So, I've decided to document this limitation and move on: when the Cisco device configuration does not match the parser flags, parsing will fail or produce incorrect results. When we have more clarity on the correct behavior in case of configuration mismatch, we'll act accordingly with another PR. Since I can't push on this PR, I'll merge it to the default branch. I'll send a follow-up PR for documentation and tests. I'll ask you folks @go3ranh, @dehaansa, @alistairking, @v-zhuravlev to please take a look at that PR. |
leodido
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM
|
On a side note, to be 100% sure of the placement of the Cisco hostname component, I'd need a log that contains the message counter, the sequence number, and the hostname components. In the logs, I've found evidence only for these cases:
The combination with all three (plus timestamp) doesn't appear in any dump @go3ranh would love if you could provide a dump for that too 🙇 |
ill do some more logging - and I think its absolutely fine not to support all those cisco options I'd be happy to document what you have to configure to make them play nice. Thanks a lot to both of you for your work and your patience! |
|
@go3ranh I've written some docs here https://github.com/leodido/go-syslog/tree/develop/rfc3164#cisco-device-configuration I'd love if you could double-check them 🙏 |
Ah sorry, yeah the fork was moved to a private repo. |
|
yep @alistairking please try https://github.com/leodido/go-syslog/releases/tag/v4.3.0 and lmk what works or not 🤞 |
These devices seem to send non-standard logs that include a sequence number, and a couple of extra characters (for good luck, I assume).
For example:
Note the
485: *here. This is the sequence number (and a*-- no idea).It also includes a ms-precision timestamp.
This is the first time I've ever written ragel code (first time I've even heard of it), so there's a pretty good chance that I got something wrong, or sub-optimal. I'm happy to make changes as you see fit.