[netsa-tools-discuss] rwflowpack bug?

[Vincent Ragosta]

Mark,

Here is a snippet of the log file with record-timestamps logging enabled:

Nov 20 14:26:58 silk-01 rwflowpack[8095]: NetFlow V9 Record Count Discrepancy. Reported: 12. Found: 14.
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:18.215Z, dur=4294962.785s from incoming record flowStartSysUpTime=72020125, flowEndSysUpTime=72015614, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:18.215Z, dur=4294962.785s from incoming record flowStartSysUpTime=72020125, flowEndSysUpTime=72015614, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.721Z, dur=4294967.279s from incoming record flowStartSysUpTime=72065210, flowEndSysUpTime=72065193, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.721Z, dur=4294967.279s from incoming record flowStartSysUpTime=72065210, flowEndSysUpTime=72065193, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.748Z, dur=4294967.252s from incoming record flowStartSysUpTime=72065255, flowEndSysUpTime=72065211, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.748Z, dur=4294967.252s from incoming record flowStartSysUpTime=72065255, flowEndSysUpTime=72065211, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.721Z, dur=4294967.279s from incoming record flowStartSysUpTime=72065273, flowEndSysUpTime=72065256, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.721Z, dur=4294967.279s from incoming record flowStartSysUpTime=72065273, flowEndSysUpTime=72065256, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.718Z, dur=4294967.282s from incoming record flowStartSysUpTime=72065368, flowEndSysUpTime=72065354, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.718Z, dur=4294967.282s from incoming record flowStartSysUpTime=72065368, flowEndSysUpTime=72065354, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.721Z, dur=4294967.279s from incoming record flowStartSysUpTime=72065385, flowEndSysUpTime=72065368, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover
Nov 20 14:26:58 silk-01 rwflowpack[8095]: 'pfSense': Set sTime=2015/10/02T02:24:13.721Z, dur=4294967.279s from incoming record flowStartSysUpTime=72065385, flowEndSysUpTime=72065368, no systemInitTimeMilliseconds, set end to exportTimeSeconds=1448047621, assume flowEndSysUpTime rollover

> Since Oct 1 was about 49 days ago, I would not be surprised to find that there is an issue in the way that SiLK is interpreting the 32 bit values used to represent "the number of milliseconds since the router booted",

I rebooted the router yesterday to see if this would resolve the issue, but it continued to record an sTime from October.

Thanks,

- Vincent

-----Original Message-----
From: Mark Thomas [mailto:mthomas at cert.org] 
Sent: Friday, November 20, 2015 2:19 PM
To: Vincent Ragosta <ragosta at plummerslade.com>
Cc: netsa-tools-discuss at cert.org
Subject: Re: [netsa-tools-discuss] rwflowpack bug?

Vincent-

Short answer:

In the sensors.conf file, modify the probe block to contain "record-timestamps" in the log-flags statement as shown here:

    probe pfSense netflow-v9
        listen-on-port 9900
        protocol udp
        accept-from-host 192.168.10.250
        log-flags default record-timestamps
    end probe

Restart rwflowpack and you should see in the rwflowpack log file (or in syslog) statements that indicate how rwflowpack is setting the time.

Longer answer:

That thread from 2014 prompted us to add ability to for rwflowpack to log the values it is using to set the start time.  Since that can produce a lot of output, it is not enabled by default.  My "Short answer" above is asking you to enable this logging.

Since Oct 1 was about 49 days ago, I would not be surprised to find that there is an issue in the way that SiLK is interpreting the 32 bit values used to represent "the number of milliseconds since the router booted", since those values roll-over about every 49 days.

-Mark