[netflow-tools] Problems with flowd logging from a Cisco ASR router

[Russell Sutherland]

I am running flowd, built from the ports tree,  on an intel based OpenBSD
5.1 machine:

# which flowd
/usr/local/sbin/flowd


# pkg_info | grep flow
flow-tools-0.68.5.1p2 cisco NetFlow utilities
flowd-0.9.1         NetFlow collector


# uname -rps
OpenBSD 5.1 i386


The problem seems to be that the data does not get logged, either at all
or consistently.

Here is my flowd.conf file:

#  cat /etc/flowd.conf  | grep -v '#' | grep -v '^$'
logfile "/var/log/flowd"
listen on 0.0.0.0:9559
flow source 127.0.0.1
flow source 205.211.94.0/24
store ALL
accept all


When flowd is run, the data seems to be arriving and being processed:

# flowd -d
read_config: entering
child_get_config: entering
drop_privs: dropping privs without chroot
send_config: entering fd = 4
recv_config: entering fd = 3
recv_config: ready to receive config
send_config: done
child_get_config: child config done
Listener for [0.0.0.0]:9559 fd = 3
Adjusted socket receive buffer from 41600 to 262144
Setting socket send buf to 1024
privsep_init: entering
drop_privs: dropping privs with chroot
init_pfd: entering (num_fds = 0)
init_pfd: done (num_fds = 2)
client_open_log: entering
answer_open_log: entering
Received max number of packets (512) on fd 3
netflow v.9 packet (len 196) 3 recs, source 0x00000801
netflow v.9 data flowset (len 176) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 1452) 25 recs, source 0x00000801
netflow v.9 data flowset (len 1432) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 768) 13 recs, source 0x00000801
netflow v.9 data flowset (len 748) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 1452) 25 recs, source 0x00000801
netflow v.9 data flowset (len 1432) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 1452) 25 recs, source 0x00000801
netflow v.9 data flowset (len 1432) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 1452) 25 recs, source 0x00000801
netflow v.9 data flowset (len 1432) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 1452) 25 recs, source 0x00000801
netflow v.9 data flowset (len 1432) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3


The problem is, that the log file: /var/log/flowd never or rarely gets
updated.
What I mean is that on some apparent random cases,  of starting and
stopping the daemon, the log file gets written to.

Sending USR1, HUP, or INFO signals to do not seem to initiate a flushing
of buffers to disk, though the events are recorded in the debug data:

# cat /var/run/flowd.pid
                   
11602
# kill -s INFO 11602
# kill -s TERM 11602


Š..
netflow v.9 packet (len 312) 5 recs, source 0x00000801
netflow v.9 data flowset (len 292) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
accept  # evaluations 0 matches 0 wins 0
Peer state: 1 of 128 in used, 0 forced deletions
peer 0 - 205.211.94.233: packets:0 flows:0 invalid:0 no_template:56
peer 0 - 205.211.94.233: first seen:2012-06-13T09:47:35.599
peer 0 - 205.211.94.233: last valid:1969-12-31T19:00:00.000 netflow v.0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 84) 1 recs, source 0x00000801
netflow v.9 data flowset (len 64) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 312) 5 recs, source 0x00000801
netflow v.9 data flowset (len 292) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
netflow v.9 packet (len 140) 2 recs, source 0x00000801
netflow v.9 data flowset (len 120) source 0x00000801
netflow v.9 data flowset without template 205.211.94.233/0x00000801/0x0104
output_flow_flush: flushing output queue len 0
Received max number of packets (512) on fd 3
ŠŠ.
output_flow_flush: flushing output queue len 0
privsep_master: child exitedExiting on signal 15


The NetFlow source is a Cisco ASR Router. flowd works successfully from a
Cisco 650x router with version 9.


Any ideas?



-- 
Russell Sutherand  I+TS
e: russell.sutherland at utoronto.ca
t: +1.416.978.0470
f: +1.416.978.6620
m: +1.416.803.0080