Radium netflow collection: many records in the future?
Jesse Bowling
jessebowling at gmail.com
Tue Jul 23 12:53:31 EDT 2013
Hi Carter,
I do get records written to the file (that I can subsequently read with
ra); it just seems that the process exits after 16 seconds...
Running the ra in the foreground seems to not make a difference (changed
path; user can and does write here):
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.480472 ArgusWriteNewLogfile
(/usr/local/logs/netflow.troubleshoot.ra.argus, 0x6e30c0) returning 0
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.480490 RaScheduleRecord
(0x7f0a1dc3b010, 0x7f0a1df70620) scheduled
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.480508 ArgusHandleDatum
(0x7f0a1d62c010, 0x7f0a1dcbc790) returning 112
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.481495 ArgusReadStreamSocket
(0x7f0a1df70010) read 100 bytes
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.481523 ArgusGenerateRecord
(0x7f0a1df70620, 0) len 100
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.481536 ArgusWriteNewLogfile
(/usr/local/logs/netflow.troubleshoot.ra.argus, 0x6e30c0) returning 0
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.481545 RaScheduleRecord
(0x7f0a1dc3b010, 0x7f0a1df70620) scheduled
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.481553 ArgusHandleDatum
(0x7f0a1d62c010, 0x7f0a1dcbc790) returning 100
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932316 ArgusClientTimeout()
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932375 ArgusShutDown (0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932386 ArgusShutDown (0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932395 RaParseComplete(caught
signal 0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932406 ArgusFree (0xbfc190)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932483 ArgusDeleteQueue
(0xbfc190) returning
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932493
ArgusCloseInput(0x1df70010) closing
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932501 ArgusWriteConnection:
write(3, 0x48b418, 6)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932573
ArgusWriteConnection(0x1df70010, 0x48b418, 6) returning 6
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932678 ArgusFree
(0x7f0a1d62c010)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932707 ArgusFree
(0x7f0a1d5eb010)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932720
ArgusCloseInput(0x1df70010) done
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932744 ArgusFree
(0x7f0a1df70010)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932757 ArgusFree (0xbfc1e0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932765 ArgusDeleteQueue
(0xbfc1e0) returning
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932773 ArgusWindowClose ()
returning
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932787 RaParseComplete(caught
signal 0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932797
ArgusReadStream(0x7f0a1dc3b010, 0xbfc1e0) returning
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932806 RaParseComplete(caught
signal 0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932814 ArgusShutDown (0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932825 ArgusFree (0xbfc050)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932833 ArgusDeleteList
(0xbfc050, 4) returning
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932841 ArgusFree (0xbfc0f0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932849 ArgusDeleteList
(0xbfc0f0, 4) returning
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932857 ArgusFree (0xbfe4e0)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932865 ArgusFree (0xbfe400)
ra[24576.0007ce1d0a7f0000]: 07/23/13 12:49:56.932872 ArgusDeleteList
(0xbfe400, 2) returning
Turning on debug on radium (to 6):
Jul 23 12:49:29 merrimac.american.edu radium[24547]: 07/23/13
12:49:29.150799 started
Jul 23 12:49:29 merrimac.american.edu radium[24547]: 07/23/13
12:49:29.156953 Binding AF_ANY:9996 Expecting Netflow records
Jul 23 12:49:29 merrimac.american.edu radium[24547]: 07/23/13
12:49:29.675195 connect from localhost[127.0.0.1]
Jul 23 12:49:40 merrimac.american.edu radium[24547]: 07/23/13
12:49:40.702835 connect from localhost[127.0.0.1]
Jul 23 12:49:56 merrimac.american.edu radium[24547]: 07/23/13
12:49:56.945840 ArgusCheckClientMessage: client localhost[127.0.0.1] sent
DONE
# racount -r netflow.troubleshoot.ra.argus
racount records total_pkts src_pkts dst_pkts
total_bytes src_bytes dst_bytes
sum 3931 790213 790213 0
1060409912 1060409912 0
I just got your message about a patch for an error message; I'll add that
and report the results, but I'm not hopeful as I don't believe file
creation is the issue...But I've been wrong before! :)
Cheers,
Jesse
On Tue, Jul 23, 2013 at 12:28 PM, Carter Bullard <carter at qosient.com> wrote:
> So, do something new, and you run into new things.
> Looks like your trying to create and write into the file:
>
> /netflow.troubleshoot.ra.argus
>
> May want to put a dot in front, or take out the '/' ?
> Carter
>
>
>
> On Jul 23, 2013, at 11:50 AM, Jesse Bowling <jessebowling at gmail.com>
> wrote:
>
> So it looks like duration is either 0 or 300 (the time limit of my file
> chunks) for the future records.
>
> I'm trying to start a troubleshooting this looking at an hour's traffic at
> a run using this simple script:
>
> #!/bin/bash
>
> if [ -f /netflow.troubleshoot.ra.pcap ]
> then
> rm /netflow.troubleshoot.ra.pcap
> fi
>
>
> if [ -f /netflow.troubleshoot.ra.argus ]
> then
> rm /netflow.troubleshoot.ra.argus
> fi
>
> /usr/sbin/tcpdump -i eth0 -nn -w /netflow.troubleshoot.ra.pcap -G 3600 -W
> 1 dst port 9996 &
> time /usr/local/bin/ra -S localhost -T 3600 -w
> /netflow.troubleshoot.ra.argus &
>
> However the ra process dies after 16 seconds (consistently). Logs indicate
> only:
>
> Jul 23 11:42:42 localhost radium[5579]: 07/23/13 11:42:42.332615 connect
> from localhost[127.0.0.1]
> Jul 23 11:42:58 localhost radium[5579]: 07/23/13 11:42:58.618391
> ArgusCheckClientMessage: client localhost[127.0.0.1] sent DONE
>
> turning debug up to 6 gets me this at the end:
>
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:27.821739 ArgusWriteNewLogfile
> (/netflow.troubleshoot.ra.argus, 0x6e30c0) returning 0
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:27.821748 RaScheduleRecord
> (0x7fd251e2f010, 0x7fd252164620) scheduled
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:27.821756 ArgusHandleDatum
> (0x7fd251820a50, 0x7fd251eb0790) returning 112
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730108 ArgusClientTimeout()
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730165 ArgusShutDown (0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730176 ArgusShutDown (0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730184 RaParseComplete(caught
> signal 0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730195 ArgusFree (0x1c47190)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730203 ArgusDeleteQueue
> (0x1c47190) returning
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730240
> ArgusCloseInput(0x52164010) closing
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730251 ArgusWriteConnection:
> write(3, 0x48b418, 6)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730321
> ArgusWriteConnection(0x52164010, 0x48b418, 6) returning 6
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730716 ArgusFree
> (0x7fd251820010)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730774 ArgusFree
> (0x7fd2517df010)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730794
> ArgusCloseInput(0x52164010) done
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730831 ArgusFree
> (0x7fd252164010)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730854 ArgusFree (0x1c471e0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730862 ArgusDeleteQueue
> (0x1c471e0) returning
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730870 ArgusWindowClose ()
> returning
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730885 RaParseComplete(caught
> signal 0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730894
> ArgusReadStream(0x7fd251e2f010, 0x1c471e0) returning
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730904 RaParseComplete(caught
> signal 0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730912 ArgusShutDown (0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730922 ArgusFree (0x1c47050)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730930 ArgusDeleteList
> (0x1c47050, 4) returning
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730938 ArgusFree (0x1c470f0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730946 ArgusDeleteList
> (0x1c470f0, 4) returning
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730954 ArgusFree (0x1c494e0)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730961 ArgusFree (0x1c49400)
> ra[6491.0047ed51d27f0000]: 07/23/13 11:45:28.730969 ArgusDeleteList
> (0x1c49400, 2) returning
>
>
> Oh the rabbit holes!
>
> Cheers,
>
> Jesse
>
>
>
> On Tue, Jul 23, 2013 at 10:36 AM, Carter Bullard <carter at qosient.com>wrote:
>
>> Hey Jesse,
>> Each netflow packet contains multiple netflow records, and the time for
>> all the flows in the packet is relative to a timestamp at the beginning
>> of the packet.
>> If chunks of netflow records are wrong, I'd want to say that we're not
>> getting
>> a good timestamp and its affecting blocks of data. Of course, we could
>> be not parsing the timestamp correctly, as well, but that is less
>> attractive ;O)
>>
>> What are the durations of these flows? "-s +1dur ". We have to parse
>> both
>> a starting time and an ending time.
>>
>> It maybe useful to capture the netflow packet stream, with tcpdump, and
>> double check that argus and wireshark agree.
>>
>> Also, do you get some records that look good, and then a chunk of flows
>> that are off, then it goes back to being good?
>>
>> If you just attach to the radium with ra(), writing that to a file, we'll
>> see what
>> the actual netflow data stream, which may show this type of behavior ?
>>
>> Carter
>>
>> On Jul 23, 2013, at 9:36 AM, Jesse Bowling <jessebowling at gmail.com>
>> wrote:
>>
>> Hi,
>>
>> I'm collecting neflow records with radium, using argus-clients 3.0.7.9.
>> I've found that I have quite a few records that list start times in the
>> future; sometimes two months in the future! I notice that almost all the
>> records with future dates list a 5 minute boundary as the start time, i.e.:
>>
>> # ra -r argus.2013.09.10.00.00.00 -N 10 -w - - | ranonymize -r -
>> StartTime Flgs Proto SrcAddr
>> Sport Dir DstAddr Dport TotPkts TotBytes State
>> 09/10/13 00:00:00.000000 Ne 17
>> 1.0.2.1.54076 -> 1.0.3.1.63008 43 60370 REQ
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.1.1.52469 ?> 1.0.4.1.53624 2 2551 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.1.1.52469 ?> 1.0.4.2.53359 2 2545 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.1.1.52469 ?> 1.0.4.3.53572 1 1275 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.1.1.52469 ?> 1.0.4.4.54880 2 2553 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.2.1.39995 ?> 1.0.5.1.59243 1 45 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 1.0.5.1.59243 ?> 100.0.2.1.39995 3 2700 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.3.1.54214 ?> 100.0.4.1.80 17 782 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 1.0.6.1.80 ?> 100.0.5.1.42526 36 51113 INT
>> 09/10/13 00:00:00.000000 Ne 6
>> 100.0.5.1.42526 ?> 1.0.6.1.80 6 349 INT
>>
>> Can anyone suggest a strategy for determining whether the fault lies
>> within the argus processing, or the netflow generation?
>>
>> Thanks,
>>
>> Jesse
>>
>> $ grep -Ev '^#|^[ \t]*$' /etc/radium.conf
>> RADIUM_DAEMON=yes
>> RADIUM_MAR_STATUS_INTERVAL=60
>> RADIUM_CISCONETFLOW_PORT=9996
>> RADIUM_ACCESS_PORT=561
>>
>> $ grep -Ev '^#|^[ \t]*$' /etc/ra.conf
>> RA_SET_PID="no"
>> RA_PID_PATH="/var/run"
>> RA_RUN_TIME=0
>> RA_PRINT_MAN_RECORDS=no
>> RA_PRINT_EVENT_RECORDS=yes
>> RA_PRINT_LABELS=0
>> RA_FIELD_SPECIFIER="stime:24 flgs proto saddr sport dir daddr dport pkts
>> bytes state"
>> RA_PRINT_NAMES=none
>> RA_CIDR_ADDRESS_FORMAT="yes"
>> RA_PRINT_RESPONSE_DATA=no
>> RA_PRINT_UNIX_TIME=no
>> RA_TIME_FORMAT="%D %T.%f"
>> RA_USEC_PRECISION=6
>> RA_USERDATA_ENCODE=Ascii
>> RA_DELEGATED_IP="/usr/local/argus/delegated-ipv4-latest"
>>
>> Started with:
>>
>> /usr/local/bin/radium -f /etc/radium.conf
>> /usr/local/bin/rasplit -M time 5m -S 127.0.0.1:561 -w
>> /argus/netflow/%Y/%m/%d/argus.%Y.%m.%d.%H.%M.%S &
>>
>> Cheers,
>>
>> Jesse
>>
>> --
>> Jesse Bowling
>>
>>
>>
>
>
> --
> Jesse Bowling
>
>
>
--
Jesse Bowling
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://pairlist1.pair.net/pipermail/argus/attachments/20130723/7f1abbb2/attachment.html>
More information about the argus
mailing list