argus 3.0 bloating on OpenBSD 4.3

[Michael Sanderson]

I'm seeing similar things to what Martijn van Oosterhout had with his
Linux machine, though on OpenBSD 4.3.

I'm running argus 3.0 on a 32-bit OpenBSD 4.3 machine, with an ra
collecting data on a 32-bit OpenSuSE box.  Neither is running a
customized kernel.  Argus does not appear to be built with threads on
the OpenBSD box.  Upon occassion, the argus will output error lines like

 ArgusInterface timestamps wayyy out of order: now -732332471 then
1233017300
 ArgusInterface timestamps wayyy out of order: now -1504018871 then
1233017510

and shortly after that it begins to bloat, while the data collector
begins to receive less data.  The collector's rotated files are smaller
and traffic that I would expect to see in the files may not be present,
though there is some traffic.  All expected protocols are present, but
definitely not all of the traffic.  Intriguingly, if the argus daemon is
'kill'ed before the box runs out of memory, it will happily send all of
the flows to the collector before exiting.  Typically there is a
seriously wacky date on one of the flows that is sent.

As an example, the two entries above took place 26 Jan 09
16:48:20.937511 and 26 Jan 09 16:51:50.396118 (incidently, the first
time I have see two close together like that).  I rotate every 15
minutes and my file sizes look like:

-rw-r--r-- 1 root root 11760560 2009-01-26 16:00
data.2009.01.26-16:00:01
-rw-r--r-- 1 root root 10244648 2009-01-26 16:15
data.2009.01.26-16:15:01
-rw-r--r-- 1 root root 10110680 2009-01-26 16:30
data.2009.01.26-16:30:01
-rw-r--r-- 1 root root 11347580 2009-01-26 16:45
data.2009.01.26-16:45:02
-rw-r--r-- 1 root root  4338192 2009-01-26 17:00
data.2009.01.26-17:00:01
-rw-r--r-- 1 root root  2136652 2009-01-26 17:15
data.2009.01.26-17:15:01
-rw-r--r-- 1 root root  2043564 2009-01-26 17:30
data.2009.01.26-17:30:01
-rw-r--r-- 1 root root  2082432 2009-01-26 17:45
data.2009.01.26-17:45:01

The kill took place between 21:45 and 22:00:

-rw-r--r-- 1 root root  2191072 2009-01-26 21:45
data.2009.01.26-21:45:01
-rw-r--r-- 1 root root 94159604 2009-01-26 22:00
data.2009.01.26-22:00:01

Here is a segment of the output from an ra on data.2009.01.26-22:00:01
(sorry for line wrapping).  Note the 46/10/17 date on the fourth output
line.

09/01/26 21:01:27  e         udp      77.85.162.112.27371    <->    
142.103.17.161.19164         2        463   CON

09/01/26 21:47:06  e         tcp       86.96.229.89.14410     ->       
142.103.6.5.80            2        114   FIN

09/01/26 21:46:58  e         udp      137.82.37.253.32770    <->     
198.162.63.42.161           6       2133   CON

09/01/26 20:17:50  e         tcp      142.103.9.193.37207     ->     
75.126.170.58.443          16       3299   RST

46/10/17 14:18:49  e         tcp      142.103.17.80.59990     ->     
212.187.172.5.23456        11        820   FIN

09/01/26 16:48:20  e         udp        142.103.6.6.51948    <->     
204.13.250.26.53            2        266   CON

09/01/26 16:48:20  e         tcp     142.103.15.108.3004      ->   
128.121.146.100.443          14       3660   RST

09/01/26 16:48:20  e         udp      200.63.155.21.43823    <->      
198.162.35.1.53            2        214   CON

09/01/26 16:48:20  e         tcp       60.173.11.39.14400     ->     
142.103.23.48.1234          1         58   ACC

Another note of interest in the output is that the timestamps jump all
over the place prior to the wacky date, with lines from as early as
09/01/26 16:55:43 (shortly after the error message) through to current
time.  After the wacky date is output, the dates appear to
chronologically increase.  It MAY be that the wacky date corresponds to
when the kill was issued.  I'll have to try watching a data stream the
next time I do a kill.

Is anyone aware of an OpenBSD 4.3 time error along the lines of the
Linux kernel bug that affected Martijn's configuration?  Carter, there
had been a bit of discussion on the list about mitigating these
effects.  Is this something that you have looked at?

    Michael Sanderson