[netsa-tools-discuss] incorrect flow times in silk 3.16

[Mark Thomas]

Tim-

Thank you for enabling the timestamp information and providing that
to me.

This is what SiLK is doing:

According to the log messages, the flowStartSysUpTime values are
larger than the flowEndSysUpTime values:

  flowStartSysUpTime  3881082770 
  flowEndSysUpTime    3881082647

Since SiLK expects the start time to be less than the end time, it
assumes that the end time has exceeded the 32 bit capacity of the
flowEndSysUpTime field and rolled over.  SiLK adds 2^32 to the end
time and subtracts the start time.  The result is a duration of
approximately 49 days.

Next, because the sysUpTime (11001000) is so much less than the
timestamps on the flow record, SiLK assumes it has also rolled over.
In an attempt to correct that, SiLK subtracts 2^32 from the start
time and adds that negative value to the
systemInitTimeMilliseconds.  The result is the start time being
about 10 days in the past.


I would be curious to see the timestamp fields that wireshark is
capturing and producing so I can double-check the code in SiLK.  If
you could capture the timestamp data in SiLK at the same time, that
would be even better.


I am sorry you did not receive my reply.  I sent it to you and to
the list.  I am sending this message separately to you and the list.

-Mark


On Tue, 15 Aug 2017 18:22:36 -0700, Tim Stevenson wrote:

> Hi Mark,
>
> Thank you for the reply & sorry for the delay, I am not subscribed to 
> the list so had to remember to come back & check for a response. If 
> you wouldn't mind cc'ing me directly on any response I'd appreciate it...
>
> This is what I see in the logs with record-timestamps enabled for an 
> NXOS v9 exporter:
>
> Aug 15 12:17:54 tstevens-silk-sandbox rwflowpack[2071]: 
> 'tstevens-93180yc-fx-1': Set sTime=2017/08/10T21:16:28.474Z, 
> dur=4294967.173s from incoming record flowStartSysUpTime=3881082770, 
> flowEndSysUpTime=3881082647, 
> systemInitTimeMilliseconds=1502813673000, 
> exportTimeSeconds=1502824674, calculated sysUpTime=11001000, assume 
> sysUpTime rollover, assume flowEndSysUpTime rollover
> Aug 15 12:18:04 tstevens-silk-sandbox rwflowpack[2071]: 
> 'tstevens-93180yc-fx-1': Set sTime=2017/08/10T21:16:34.368Z, 
> dur=4294967.173s from incoming record flowStartSysUpTime=3881088664, 
> flowEndSysUpTime=3881088541, 
> systemInitTimeMilliseconds=1502813673000, 
> exportTimeSeconds=1502824684, calculated sysUpTime=11011000, assume 
> sysUpTime rollover, assume flowEndSysUpTime rollover
> Aug 15 12:18:04 tstevens-silk-sandbox rwflowpack[2071]: 
> 'tstevens-93180yc-fx-1': Set sTime=2017/08/10T21:16:35.848Z, 
> dur=4294967.173s from incoming record flowStartSysUpTime=3881090144, 
> flowEndSysUpTime=3881090021, 
> systemInitTimeMilliseconds=1502813673000, 
> exportTimeSeconds=1502824684, calculated sysUpTime=11011000, assume 
> sysUpTime rollover, assume flowEndSysUpTime rollover
>
>
> I guess this is the problem: "assume sysUpTime rollover, assume 
> flowEndSysUpTime rollover"... Looks like flowStartSysUpTime 
> (3881090144) is bigger than  flowEndSysUpTime (3881090021).
>
> But when I capture these NDE packets in wireshark and decode with the 
> CFLOW dissector, it's interpreting them in the opposite way - ie, 
> start time is always smaller than end time, ie as expected. So 
> wireshark is parsing them correctly.
>
> I did find an IOS box (6500 sup720) and enabled v9 export there and 
> all the timestamps are handled correctly by rwflowpack, the date/time 
> is correct for that. I did notice that the actual order of fields in 
> the templates/packets are different between NXOS & IOS packet 
> captures when viewed in wireshark. I can provide the two pcap files 
> (as well as switch configs) if you like.
>
> Let me know, thanks,
> Tim
>
>
>>Tim-
>>
>>To debug the issue, I suggest modifying the sensor.conf file used by
>>rwflowpack to add 'record-timestamps' to the 'log-flags' setting for
>>the probe(s) that collect the NetFlow v9 data from from Cisco NX-OS:
>>
>>   probe P1 netflow-v9
>>     log-flags default record-timestamps
>>     ...
>>   end probe
>>
>>After you restart rwflowpack, for every NetFlow v9 record,
>>rwflowpack writes to the log file the values it read from the
>>incoming NetFlow v9 data.  Knowing those values will help in
>>debugging the issue.
>>
>>That log-flags setting generates a lot of output.  Once you have
>>collected some timestamp information I suggest you disable the flag.
>>
>>I can assist in debugging in the issue further once I know which
>>information elements SiLK is using and the values of those elements.
>>
>>Cheers,
>>
>>-Mark
>
>
>
>
>
> Tim Stevenson, tstevens at cisco.com
> Routing & Switching CCIE #5561
> Distinguished Engineer, Technical Marketing
> Data Center Switching
> Cisco - http://www.cisco.com
> +1(408)526-6759