argus crash problem

[Peter Van Epp]

On Wed, Jan 30, 2008 at 01:45:17PM -0500, Lei Wei wrote:
> Hello Peter and Carter,
> 
> I've been trying to repeat the crash problem again recently. I ran 
> argus with the debug option enabled from Sunday night until now. It 
> never crashed. The only debug information it outputed was several lines 
> when argus started to run and nothing more. The CPU usage right now is 
> till about 99% but the output data file grows well and now is about 
> 144G already. I'm not sure why I can't repeat the crash again and there 
> shouldn't be too much difference in the amount of traffic between this 
> and last week. By the way, the link I'm monitoring is the campus border 
> link to the ISP and the traffic load is more than 1G per second.  I 
> wonder if there's any difference running in debug mode that could 
> possibly play a role in it...  Anyway, I'll keep monitoring it and see 
> what happens.
> 
> Lei
> 

	Hmmm, thats too bad. Debug mode does slow argus down a bit, its 
possible that its slowing it down enough that the problem isn't happening.
What does memory usage look like? I'd be suspicious that what is happening
is that argus is running out of memory and stopping (although that should 
show up in syslog). That said I just noticed I'm not getting any syslog 
messages from argus (and I think I should be). I just restarted one of my
test ones with -D2:

# argus -J -P 560 -i eth2 -i eth3 -m -U700 -D2  -- host 142.58.101.100
argus[4637]: 30 Jan 08 12:32:05.555408 ArgusNewModeler() returning 0x10181010
argus[4637]: 30 Jan 08 12:32:05.555871 ArgusNewSource() returning 0x10201f70
argus[4637]: 30 Jan 08 12:32:05.555903 ArgusNewOutput() returning retn 0x102016b0
argus[4637]: 30 Jan 08 12:32:05.555985 setArgusPortNum(560) returning
argus[4637]: 30 Jan 08 12:32:05.556023 setArgusInterfaceStatus(1)
argus[4637]: 30 Jan 08 12:32:05.585055 ArgusInitSource() pcap_open_live(eth3) returned 0x10252d60
argus[4637]: 30 Jan 08 12:32:05.585119 ArgusOpenInterface(0x10201f70, 'eth3') returning
argus[4637]: 30 Jan 08 12:32:05.615008 ArgusInitSource() pcap_open_live(eth2) returned 0x10253370
argus[4637]: 30 Jan 08 12:32:05.615071 ArgusOpenInterface(0x10201f70, 'eth2') returning
argus[4637]: 30 Jan 08 12:32:05.615119 ArgusCopyArgv(0xff8811f8) returning 0x10253980
argus[4637]: 30 Jan 08 12:32:05.615298 ArgusInitSource() returning
argus[4637]: 30 Jan 08 12:32:05.615357 ArgusEstablishListen(560, (null), 0xff880a18)
argus[4637]: 30 Jan 08 12:32:05.615526 ArgusEstablishListen(560, 0xff880a18) binding: any:560
argus[4637]: 30 Jan 08 12:32:05.615607 ArgusEstablishListen(560, 0xff880a18) returning 5
argus[4637]: 30 Jan 08 12:32:05.615633 ArgusInitOutput() done
  ArgusWarning: argus[4637]: 30 Jan 08 12:32:05.615670 started
argus[4637]: 30 Jan 08 12:32:05.615711 ArgusInitModeler() done
argus[4637]: 30 Jan 08 12:32:05.615974 setArgusInterfaceStatus(1)
  ArgusWarning: argus[4637]: 30 Jan 08 12:32:05.616010 ArgusGetInterfaceStatus: interface eth3 is up
argus[4637]: 30 Jan 08 12:32:05.616046 setArgusInterfaceStatus(1)
  ArgusWarning: argus[4637]: 30 Jan 08 12:32:05.616102 ArgusGetInterfaceStatus: interface eth2 is up
argus[4637]: 30 Jan 08 12:32:05.616133 setArgusInterfaceStatus(1)
argus[4637]: 30 Jan 08 12:32:05.616159 setArgusInterfaceStatus(1)
argus[4637]: 30 Jan 08 12:32:59.824738 ArgusScheduleShutDown(2)

argus[4637]: 30 Jan 08 12:32:59.824838 ArgusShutDown(Normal Shutdown)

argus[4637]: 30 Jan 08 12:32:59.824856 ArgusCloseSource(0x10201f70) starting
argus[4637]: 30 Jan 08 12:32:59.824874 ArgusCloseSource(0x10201f70) deleting source
argus[4637]: 30 Jan 08 12:32:59.825600 ArgusCloseModeler(0x10181010) pushing close record 0x1028f2b0
argus[4637]: 30 Jan 08 12:32:59.825625 ArgusCloseModeler(0x10181010)
argus[4637]: 30 Jan 08 12:32:59.825642 ArgusCloseOutput() scheduling closure after writing records
argus[4637]: 30 Jan 08 12:32:59.825698 ArgusOutputProcess() received stop record 0 records on the list
argus[4637]: 30 Jan 08 12:32:59.825716 ArgusCloseOutput(0x102016b0) done
argus[4637]: 30 Jan 08 12:32:59.825759 ArgusShutDown()

# tail /var/log/messages
...
Jan 30 12:32:05 sniffer1 kernel: RING: succesfully allocated 0 KB [tot_mem=12664896][order=12]
Jan 30 12:32:05 sniffer1 kernel: RING: allocated 10851 slots [slot_len=1546][tot_mem=16777216]
Jan 30 12:32:05 sniffer1 kernel: RING: succesfully allocated 0 KB [tot_mem=12664896][order=12]
Jan 30 12:32:05 sniffer1 kernel: RING: allocated 10851 slots [slot_len=1546][tot_mem=16777216]

	and all that shows in syslog is the ring buffer starting as the 
interfaces come up. I think argus used to syslog the interfaces opening to
syslog which may mean there is a bug in syslogging. 

Peter Van Epp / Operations and Technical Support 
Simon Fraser University, Burnaby, B.C. Canada