Snort alert log entry timestamp delta between GUI and syslog

[cyberzeus]

I have alerts logged to syslog and with one alert in particular, the GUI version has a timestamp about 5.5h earlier than the same alert in syslog.  The natural question is why would I think these are the same alerts - here's my reasoning:

• The alert is on the LAN side and I see very few alerts on the LAN side to begin with.

• Every other data field for this alert is the exact same with the only difference being the timestamp - even down to the destination port #.

• While it is definitely probable to see same non-well-known src\dst port # re-used, it is highly unlikely to see that re-use occur with 2 different sessions between the same 2 machines running the same L4 protocol AND the same L7 protocol\application within the span of just a few hours (basic prob is roughly > 1 in a few hundred thousand).

• To support this statement, captures taken of my machine communicating with a variety of hosts\services illustrate the rarity of seeing the same src\dst non-well-known port # re-use.  I definitely see it occur but it's always involving at least one element being different - i.e. the L4 protocol, the L7 protocol\application, etc.

One thought I had was a delta due to different timezones being used for the 2 log entries however this doesn't fit because (1) All other GUI\syslog entry timestamps match; (2) The time delta does not equal an integer of hours as you would expect with a timezone mis-match (time delta here is 5h:35m:5s).

Another interesting thing about this alert is that it did not trigger a block until exactly 5m after the alert BUT the relevant port # (in this direction, the src_port) is different than it's counterpart in the alert log entries (in that direction, the dst_port).

All log entries\captures are included herein.

ALERT syslog entry
Dec 11 12:06:10 IP_MASKED snort[35645]: [124:3:1] (smtp) Attempted response buffer overflow: 726 chars [Classification: Attempted User Privilege Gain] [Priority: 1] {TCP} 98.139.211.125:587 -> IP_MASKED:62123

FW BLOCK syslog entry
Dec 11 12:11:06 IP_MASKED filterlog: 18,,,1000000110,igb1,match,block,in,4,0x0,,64,37027,0,DF,6,tcp,64,IP_MASKED,98.139.211.125,54848,587,0,S,4159647144,,65535,,mss;nop;wscale;nop;nop;TS;sackOK;eol

[cyberzeus]

UPDATE

In reviewing more of the logs, I found that coincidentally - or possibly cause\effect…not sure - but Snort began updating the rulesets just prior to the 12:00-timestamped version of the alert.  I'm not sure if this update and subsequent Snort restart plays a role in this but I gotta believe it might.

Curious to hear feedback...

[bmeeks]

That is definitely weird and I don't have a good answer.  My first thought would be to see if clog plays a role.  The syslog on pfSense is a circular log file.  No clue from me on how that may impact things, but it is something to consider.  Snort just hands off the data to the syslog daemon.  Also, like you mentioned, I would first have jumped on a time zone thing, but with that odd half-hour difference in there that theory goes up in smoke.

Bill

[cyberzeus]

Hi Bill,

Yeah - really strange.  I considered the clog aspect as well but if that were part of this, then you would expect there to be skew consistent across the whole file which I do not see.

I do think the 5m delay for the block resulting from the 12:00 related syslog message is due to the rules updating - I figure maybe the BLOCK_THIS IPC message somehow got head-of-line blocked due to Snort grinding through rule updates.  I believe Snort is single-threaded and if so, then this might make even more sense.  Would be curious to hear your comments on that possibility…

In any event, still doesn't explain the different timestamps on the syslog messages... scratches head

[bmeeks]

@cyberzeus:

Hi Bill,

Yeah - really strange.  I considered the clog aspect as well but if that were part of this, then you would expect there to be skew consistent across the whole file which I do not see.

I do think the 5m delay for the block resulting from the 12:00 related syslog message is due to the rules updating - I figure maybe the BLOCK_THIS IPC message somehow got head-of-line blocked due to Snort grinding through rule updates.  I believe Snort is single-threaded and if so, then this might make even more sense.  Would be curious to hear your comments on that possibility…

In any event, still doesn't explain the different timestamps on the syslog messages... scratches head

Snort is indeed single-threaded … at least the 2.x and older versions.  The new 3.0-ALPHA is multi-threaded, but it's not released as stable yet and is not in the FreeBSD ports collection.

Bill