[netsa-tools-discuss] rwflowpack bug?

Mon Nov 23 00:26:35 EST 2015

Vincent,

I haven’t run pfSense in quite some time.  What is the software package that is the flow generator on there at this point?  It will help us expand this bit of knowledge beyond just pfSense.

Also, is there an alternative to whichever flow generator you’re currently using?  I know that fairly recent versions of yaf are catalogued into FreeBSD’s ports system, but that doesn’t necessarily translate into having made it into pfSense.  Additionally, since pfSense uses pf as its firewall, I know there is at least one flow generator that links into the pf state table to generate flows.

Regards,
--
Chris Inacio
inacio at cert.org

> On Nov 20, 2015, at 4:05 PM, Mark Thomas <mthomas at cert.org> wrote:
> 
> Vincent-
> 
> Thank you very much for the log, and I understand what is happening.
> 
> Looking at the first message, we see:
> 
>  flowStartSysUpTime=72020125
>  flowEndSysUpTime=72015614
> 
> where
> 
>  flowStartSysUpTime is the start time of this flow record, given as
>  the number of milliseconds since the router booted.
> 
>  flowEndSysUpTime is the end time of this flow record, given as the
>  number of milliseconds since the router booted.
> 
> Since the start time is greater than the end time, SiLK makes the
> assumption that the end time has rolled over, which leads to SiLK
> setting the duration to
> 
>  flowEndSysUpTime + 2^32 - flowStartSysUpTime
> 
> milliseconds, or 4294962.785 seconds, or 49.7 days.
> 
> There should have been a sysUpTime value in the flow record's header
> that specified the number of seconds since the router booted.  The
> libfixbuf library presents that value to SiLK in the
> systemInitTimeMilliseconds information element, but the log message
> says that value is not available.  (This seems odd.)
> 
> SiLK therefore sets the end time of the flow record to the export
> time of the packet (1448047621, 2015-Nov-20 19:27:01 UTC) and
> computes the start time by subtracting 49.7 days from today, taking
> the start time back to Oct 1.
> 
> 
> I assume the issue is that the start and end times are reversed.
> 
> In our code for processing NetFlow v5 packets, we accounted for more
> irregularities in the various timestamps, and we made these changes
> based on example data we received.  Our IPFIX/NetFlow v9 code does
> not handle as many irregularities for a few reasons:
> 
> * The IPFIX/NetFlow v9 code in SiLK is already fairly complicated
>  since it has to handle many different IPFIX representations for
>  time.
> 
> * Since NetFlow v9 and especially IPFIX are more formally defined,
>  we did not expect to see flow records with the start and end times
>  reversed.
> 
> * We have not seen this before.
> 
> I suppose we need to make the NetFlow v9 code in SiLK has robust as
> the NetFlow v5 code when processing the timestamps.
> 
> In the short term, I am not certain what to suggest.
> 
> If you know your way around C code, you could try editing the code
> yourself.  The IPFIX/NetFlow v9 conversion code is in
> silk-3.11.0/src/libflowsource/skipfix.c.  You want to find the
> section of code that begins "Run the Gauntlet of Time".  The
> processing of flowStartSysUpTime and flowEndSysUpTime are the first
> checks in that long if/then/else block.
> 
> Good luck.
> 
> -Mark
> 
> 
> -----Original Message-----
> From: Vincent Ragosta <ragosta at plummerslade.com>
> Date: Fri, 20 Nov 2015 19:30:45 +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] rwflowpack bug?
> 
> 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
> 