[netsa-tools-discuss] Date on SILK/rwflowpack directory is in the future by a good bit.
Mark Thomas
mthomas at cert.org
Fri Feb 2 16:36:10 EST 2018
Jeff-
Thank you for the log messages.
There was a mistake in my message: I should have been using
"sysUpTime" where I was using "systemInitTimeMilliseconds".
In your data, SiLK assumes the sysUpTime has rolled over since the
sysUpTime differs so widely from the flowStartSysUpTime (details
below). This pushes the timestamps far into the past.
The sysUpTime value is not in seconds, however, and using the
nf9-sysuptime-seconds quirk moves the records into the future.
Your other collector may be producing correct timestamps by setting
the timestamp of the flow records to the export time of the message.
Perhaps I should support similar behavior in SiLK.
In the meantime, I do not have a good work-around for your data
short of editing the SiLK source code to ignore the sysUpTime value.
-Mark
Here are the details on how SiLK is computing the records'
timestamps:
The first log message shows that the router booted 14,509,307
milliseconds ago, the flow record started 2,466,682,730, milliseconds
after the router booted, and the flow ended 2,466,703,523
milliseconds after the router booted:
sysUpTime 14,509,307
flowStartSysUpTime 2,466,682,730
flowEndSysUpTime 2,466,703,523
Since the router boot time must be larger than times on the record,
SiLK assumes the sysUpTime exceeded a 32-bit number and rolled-over.
SiLK adds 2^32 to the sysUpTime to produce:
sysUpTime 4,309,476,603
flowStartSysUpTime 2,466,682,730
flowEndSysUpTime 2,466,703,523
Subtracting the flowStartSysUpTime from the sysUpTime shows the flow
started 1,842,793,873 milliseconds (or 21.32 days) prior to the
export time of the record.
Using the export time of 2018-02-01T02:13:19Z (1517451199 seconds
since the UNIX epoch), the record's start time becomes
2018-01-10T18:20:05.127Z.
-----Original Message-----
From: "Collyer, Jeffrey W. (jwc3f)" <jwc3f at virginia.edu>
Date: Thu, 1 Feb 2018 02:37:32 +0000
To: Mark Thomas <mthomas at cert.org>
Cc: "netsa-tools-discuss at cert.org" <netsa-tools-discuss at cert.org>
Subject: Re: [netsa-tools-discuss] Date on SILK/rwflowpack directory is in the
future by a good bit.
Mark,
Thanks for the help but something is still off. I logged timestamps and got loads of this
Jan 31 21:19:37 nf2 rwflowpack[60103]: 'GIGAMON-NF-1': Set sTime=2018/01/10T18:20:05.127Z, dur=20.793s from incoming record flowStartSysUpTime=2466682730, flowEndSysUpTime=2466703523, systemInitTimeMilliseconds=1517436689693, exportTimeSeconds=1517451199, calculated sysUpTime=14509307c, assume sysUpTime rollover
Jan 31 21:19:37 nf2 rwflowpack[60103]: 'GIGAMON-NF-1': Set sTime=2018/01/10T18:20:13.471Z, dur=12.662s from incoming record flowStartSysUpTime=2466691074, flowEndSysUpTime=2466703736, systemInitTimeMilliseconds=1517436689693, exportTimeSeconds=1517451199, calculated sysUpTime=14509307, assume sysUpTime rollover
Jan 31 21:19:37 nf2 rwflowpack[60103]: 'GIGAMON-NF-1': Set sTime=2018/01/10T18:20:15.038Z, dur=10.928s from incoming record flowStartSysUpTime=2466692641, flowEndSysUpTime=2466703569, systemInitTimeMilliseconds=1517436689693, exportTimeSeconds=1517451199, calculated sysUpTime=14509307, assume sysUpTime rollover
Which will there is a large discrepancy between systemInitTimeMilliseconds and flowStartSysUpTime=2466692641, it only looks like about 615x not 1000x
I added the quirks statement to my sensor.conf probe -
probe GIGAMON-NF-1 netflow-v9
listen-on-port 9901
protocol udp
accept-from-host 10.243.36.60
# log-flags default record-timestamps
quirks nf9-sysuptime-seconds
end probe
But now my rwflowpack seems to be writing data in the past
rwflowpac 60320 root 1w REG 7,1 677123489 1181300 /usr/local/var/lib/rwflowpack/log/rwflowpack-20180131.log
rwflowpac 60320 root 2w REG 7,1 677123489 1181300 /usr/local/var/lib/rwflowpack/log/rwflowpack-20180131.log
rwflowpac 60320 root 3w REG 7,1 677123489 1181300 /usr/local/var/lib/rwflowpack/log/rwflowpack-20180131.log
rwflowpac 60320 root 9uW REG 0,77 353192952 41263 /opt/silk/data/GIGAMON-NF-1/outweb/2017/10/24/ow-GIGAMON-NF-1_20171024.22 (10.243.36.90:/mnt/flowpool/silk)
rwflowpac 60320 root 10uW REG 0,77 207543542 41262 /opt/silk/data/GIGAMON-NF-1/in/2017/10/24/in-GIGAMON-NF-1_20171024.22 (10.243.36.90:/mnt/flowpool/silk)
rwflowpac 60320 root 11uW REG 0,77 22735 41265 /opt/silk/data/GIGAMON-NF-1/int2int/2017/10/24/int2int-GIGAMON-NF-1_20171024.22 (10.243.36.90:/mnt/flowpool/silk)
Something is still amiss. I will freely admit that I did a Gigamon firmware update around the time this started happening, but my other flow collector seems to no be affected, so I missed that Silk was having problem.
What other data can I provide to help you figure out what is happening and how to fix it?
Jeff
> On Jan 25, 2018, at 5:28 PM, Mark Thomas <mthomas at cert.org> wrote:
>
> Jeff-
>
> Thank you for using the NetSA tools. Thanks also for your question.
>
> In NetFlow v9, the starting and ending times for an individual
> record are given as offsets from a timestamp in the message header.
> (Details below.) Sometimes SiLK may misinterpret these offsets and
> produce odd timestamps.
>
> You can tell rwflowpack to write the incoming record timestamps in
> the log file. To do this, you must modify the sensor.conf file.
> Locate the probe block(s) in the file, and add the following
> statement:
>
> log-flags default record-timestamps
>
> (If you already have a log-flags statement for a probe, add the
> record-timestamps value to it.)
>
> Once you restart rwflowpack, it will print values it receives for
> each flow record and how it interprets those values to create an
> absolute timestamp. Note that this produces a lot of output in the
> log file.
>
> Having the timestamp data in the log file should help in debugging
> the issue.
>
> If you find that the systemInitTimeMilliseconds is about 1000 times
> less than the flowStartSysUpTime, the Gigamon may have the same
> issue as we recently discovered on SonicWall appliances. We added
> a quirk to work-around the problem, which you can enable by adding
>
> quirks nf9-sysuptime-seconds
>
> to the probe block(s) and restarting rwflowpack.
>
> I hope this helps, and if you have further questions or would like
> assistance in interpreting the log output, please let us know.
>
> Cheers,
>
> -Mark
>
> NetFlow timestamp details:
>
> The starting and ending times for an individual NetFlow v9 record
> are given as offsets from the device's initialization time (where
> the initialization time is often the router's boot time). The
> NetFlow message header contains the message's export time as both an
> offset from the initialization time and in the traditional form used
> by UNIX (seconds since January 1, 1970). The offsets have
> millisecond precision and are stored in 32-bit numbers; this causes
> the values to roll-over every 49.7 days.
>
> SiLK expects all the offsets to be fairly close to one another. If
> they are not, SiLK assumes a value has rolled over and attempts to
> compensate for that. This can cause SiLK to produce timestamps that
> occur about 50 days in the future or past.
>
> The record-timestamps log-flag causes rwflowpack to record the
> offsets on each record (flowStartSysUpTime, flowEndSysUpTime), the
> offset in the header (systemInitTimeMilliseconds), the current UNIX
> time (exportTimeSeconds), the start time it computes, and whether it
> assumed offsets had rolled-over.
>
>
> -----Original Message-----
> From: "Collyer, Jeffrey W. (jwc3f)" <jwc3f at virginia.edu>
> Date: Tue, 23 Jan 2018 20:57:33 +0000
> To: "netsa-tools-discuss at cert.org" <netsa-tools-discuss at cert.org>
> Subject: [netsa-tools-discuss] Date on SILK/rwflowpack directory is in the
> future by a good bit.
>
> So I have a Gigamon generating Netflow v9 and sending it to two collectors, one of which is Silk.
> The Silk collector is suddenly writing files with dates in the future.
> The second collector is seeing the same flow data and only sees time/date stamps for today, nothing in the future.
>
> Much as I would love to know the future I can’t figure out what is causing this.
>
> For example
>
> /opt/silk/data/GIGAMON-NF-1/in/2018/02/12# ls -al
> total 2998086
> drwxr-xr-x 2 root root 14 Jan 23 15:27 .
> drwxr-xr-x 5 root root 5 Jan 23 04:27 ..
> -rw-r--r-- 1 root root 221513566 Jan 23 05:29 in-GIGAMON-NF-1_20180212.00
> -rw-r--r-- 1 root root 220770422 Jan 23 06:29 in-GIGAMON-NF-1_20180212.01
> -rw-r--r-- 1 root root 238481114 Jan 23 07:29 in-GIGAMON-NF-1_20180212.02
> -rw-r--r-- 1 root root 248975819 Jan 23 08:29 in-GIGAMON-NF-1_20180212.03
> -rw-r--r-- 1 root root 278772583 Jan 23 09:29 in-GIGAMON-NF-1_20180212.04
> -rw-r--r-- 1 root root 288936702 Jan 23 10:29 in-GIGAMON-NF-1_20180212.05
> -rw-r--r-- 1 root root 297647756 Jan 23 11:29 in-GIGAMON-NF-1_20180212.06
> -rw-r--r-- 1 root root 301989843 Jan 23 12:29 in-GIGAMON-NF-1_20180212.07
> -rw-r--r-- 1 root root 296719238 Jan 23 13:29 in-GIGAMON-NF-1_20180212.08
> -rw-r--r-- 1 root root 300709672 Jan 23 14:29 in-GIGAMON-NF-1_20180212.09
> -rw-r--r-- 1 root root 298666055 Jan 23 15:29 in-GIGAMON-NF-1_20180212.10
> -rw-r--r-- 1 root root 77347926 Jan 23 2018 in-GIGAMON-NF-1_20180212.11
> /opt/silk/data/GIGAMON-NF-1/in/2018/02/12# date
> Tue Jan 23 15:43:12 EST 2018
>
> Ive checked the date on the Gigamon, the VM that Silk is running on, and the Hypervisor. All are correct and are NTP synced.
> I restarted rwflowpack, rebooted the VM, and even motioned it off and bounced the hypervisor.
> I was on silk-3.14.0, but I just upgraded to silk-3.16.0 in case that might help. It didn’t.
>
> My conf files are pretty stock, and previously it had been working fine.
>
> Any help/hints/idea about whats wrong and how I might fix this greatly appreciated.
>
> Jeff
>
> Jeffrey Collyer
> Information Security Engineer
> University of Virginia
Jeffrey Collyer
Information Security Engineer
University of Virginia
jwc3f at virginia.edu
434-297-6317
More information about the netsa-tools-discuss
mailing list