[netsa-tools-discuss] rwflowpack bug?

Mark Thomas mthomas at cert.org
Fri Nov 20 16:05:54 EST 2015


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


More information about the netsa-tools-discuss mailing list