bro loggers

Greetings

I am integrating bro into a larger system so that I can use it to keep track of connections (which seems easier than trying to write a method from scratch with pcap). I thought it would be straightforward to grep for print or email or alarm statements to figure out where to put the hooks for an IPC message but so far it eludes me. Is there a principal module for outputting the notifications?

Thanks

Mike

Hi Mike,

Greetings

I am integrating bro into a larger system so that I can use it to keep track
of connections (which seems easier than trying to write a method from
scratch with pcap). I thought it would be straightforward to grep for print
or email or alarm statements to figure out where to put the hooks for an IPC
message but so far it eludes me. Is there a principal module for outputting
the notifications?

where in Bro such code is located depends on the semantics of the
notification system. For example, there's syslogging in Logger.cc, while
email notification is implemented in notice.bro.

I'm not familiar with your requirements, but since you're mentioning IPC
you should probably be introduced to the power of Broccoli! :slight_smile: Using
this library you can integrate external applications into your Bro
network by exchanging full-blown Bro events -- assuming there exist
connection events in Bro suitable to your needs, you could have these
events forwarded to your application for further processing.

  Broccoli — The Bro client communications library

If this looks like it does what it needs, then please do get in touch so
we could discuss this further.

Cheers,
Christian.

Howdy

I have added 'broping.bro' to local.site.bro in $BROHOME/etc. I tried running the broping in the broccoli test directory on 0.0.0.0:47757 and get a 'Could not handshake'. The comm.log shows that bro is listening on 0.0.0.0:47758 which are apparently the defaults between listen-clear.bro and broping.bro. My bro is listening on eth0 which has an internal IP from the DNS/firewall. I can see entries in the comm.log for that IP and port 32831. I am running broping on the same machine as bro. broping reports 'Could not connect' on 127.0.0.1. Can anybody suggest any places to look for problems? I'm at a loss to proceed.

Thanks

Mike

Hi Mike,

Howdy

I have added 'broping.bro' to local.site.bro in $BROHOME/etc. I tried
running the broping in the broccoli test directory on 0.0.0.0:47757 and get
a 'Could not handshake'.

You mean "Could not complete handshake successfully"? Don't pass it
0.0.0.0:47757, but rather "broping -p <port> host", so typically just
"broping localhost" or even just "broping". 127.0.0.1 and 47758 are the
default IP/port settings.

The comm.log shows that bro is listening on
0.0.0.0:47758 which are apparently the defaults between listen-clear.bro
and broping.bro. My bro is listening on eth0 which has an internal IP from
the DNS/firewall. I can see entries in the comm.log for that IP and port
32831. I am running broping on the same machine as bro. broping reports
'Could not connect' on 127.0.0.1. Can anybody suggest any places to look for
problems? I'm at a loss to proceed.

mhmm okay what versions of Bro and Broccoli are you using? It might be
that since I'm typically using the latest CVS code for Bro, Broccoli
actually doesn't work correctly with the latest Bro release.

If you've built Broccoli with --enable-debug, can you send me the output
of your broping invocation with a "-d -d" for debugging messages + call
stack tracing?

I just noticed there may be issues with connections that *don't* require
synchronized access because all my latest experiments required this
feature. Anyone up for writing regression tests for Broccoli? :slight_smile:

Cheers,
Christian.

Christian

I have added 'broping.bro' to local.site.bro in $BROHOME/etc. I tried
running the broping in the broccoli test directory on 0.0.0.0:47757 and get
a 'Could not handshake'.

You mean "Could not complete handshake successfully"? Don't pass it
0.0.0.0:47757, but rather "broping -p <port> host", so typically just
"broping localhost" or even just "broping". 127.0.0.1 and 47758 are the
default IP/port settings.

Yes, that was the message. broping -p 47757 localhost will generate the same error. Anything else generates a "Could not connect to Bro..."

The comm.log shows that bro is listening on
0.0.0.0:47758 which are apparently the defaults between listen-clear.bro
and broping.bro. My bro is listening on eth0 which has an internal IP from
the DNS/firewall. I can see entries in the comm.log for that IP and port
32831. I am running broping on the same machine as bro. broping reports
'Could not connect' on 127.0.0.1. Can anybody suggest any places to look for
problems? I'm at a loss to proceed.

mhmm okay what versions of Bro and Broccoli are you using? It might be
that since I'm typically using the latest CVS code for Bro, Broccoli
actually doesn't work correctly with the latest Bro release.

bro.rc status reports the version is 0.9a9. My brocolli is 0.7.1

If you've built Broccoli with --enable-debug, can you send me the output
of your broping invocation with a "-d -d" for debugging messages + call
stack tracing?

I'll have to rebuild it, but that's not a big deal.

I just noticed there may be issues with connections that *don't* require
synchronized access because all my latest experiments required this
feature. Anyone up for writing regression tests for Broccoli? :slight_smile:

Maybe.

Cheers

Mike

I've just fixed these problems in CVS and bundled up a snapshot tarball:

http://www.cl.cam.ac.uk/~cpk25/broccoli/snapshots/broccoli-0.8.060305.tar.gz

Please use this one until 0.8 is out. I've verified that broping really
should work out of the box with this tarball and Bro 0.9a9. Just run bro
directly with broping.bro, and don't pass any arguments to broping.
Output from the two shells:

$ ./bro ~/devel/Broccoli/test/broping.bro
1117837283.819435 warning: event handlers never invoked:
1117837283.819435 warning: ping

$ broping
pong event from 127.0.0.1: seq=0, time=0.010662/1.010452 s
pong event from 127.0.0.1: seq=1, time=0.008867/1.008964 s
pong event from 127.0.0.1: seq=2, time=0.038239/1.009833 s
pong event from 127.0.0.1: seq=3, time=0.009923/1.009428 s
pong event from 127.0.0.1: seq=4, time=0.038738/1.009980 s

Let me know if it still doesn't work for you.

Cheers,
Christian.

I'm still having trouble. Here's where I've looked for a solution:

I stopped bro and used nmap to scan 47757 and 47758 and they are both closed. I then restarted bro with load @broping as the last line in my local.site.bro and repeated the scan with the result that 47757 is now open. The latest iana.org list shows these ports are in an 'unassigned' range. I am starting bro logged in a root and the bro.cfg file defines root as the user.

The comm.log file says that bro is listening on 127.0.0.1:47757. It also complains on the line above this that "can't bind to port: address in use". I have no clue what this means, since the port scan shows those ports closed when bro is stopped.

I looked at broping.bro, which loads listen-clear.bro which loads remote.bro. remote.bro defines 'default_port_clear=47757.tcp'. listen-clear.bro uses this value to initialize listen_port_clear. broping.bro checks to see if listen_port_clear is defined and if so redefines it to 47758. If this were successful, would not the port scan show 47758 as open? Running broping -d -d I see in the output that the connection was refused to 127.0.0.1:47758.

Any suggestions how to troubleshoot the port?

Thanks

Mike

Here's another bit: when I broping -p 47757, the comm.log shows 'request for unknown event pong' errors. It acts like broping.bro is not getting loaded. Is bro prone to fail things silently?

Cheers

Mike

When I am not certain if communications are working (or more precisely
where they are failing) I run tcpdump on localhost and look at the payload.

Use flags like: tcpdump -n -i lo -s1500 -X port 47758

or something equivalent. You should see:

tcpdump: listening on lo
11:14:52.033801 127.0.0.1.32814 > 127.0.0.1.47758: P 3223603527:3223603715(188) ack 3222363924 win 32767 <nop,nop,timestamp 600132 598183> (DF)
0x0000 4500 00f0 58f9 4000 4006 e30c 7f00 0001 E...X.@.@.......
0x0010 7f00 0001 802e ba8e c024 4947 c011 5f14 .........IG\.\.\_\. 0x0020 8018 7fff fee4 0000 0101 080a 0009 2844 \.\.\.\.\.\.\.\.\.\.\.\.\.\.\(D 0x0030 0009 20a7 0000 0008 0200 0000 0000 0000 \.\.\.\.\.\.\.\.\.\.\.\.\.\.\.\. 0x0040 0000 00ac 6500 0000 0470 696e 6741 d0a9 \.\.\.\.e\.\.\.\.pingA\.\. 0x0050 24a7 0229 1300 0000 0101 0000 0000 880b ..)............
0x0060 0001 0000 0000 8a07 0013 0700 0000 0000 ................
0x0070 0000 0201 0000 0002 0001 0000 0000 8a01 ................
0x0080 0003 0200 0000 0000 0000 0373 6571 0001 ...........seq..
0x0090 0000 0000 8a01 0006 0300 0000 0000 0000 ................
0x00a0 0873 7263 5f74 696d 6500 0000 0000 0000 .src_time.......
0x00b0 0000 0002 0101 0000 0000 8801 0001 0000 ................
0x00c0 0000 8a01 0003 0200 0000 0000 0000 0001 ................
0x00d0 0101 0000 0000 8801 0001 0000 0000 8a01 ................
0x00e0 0006 0300 0000 0000 41d0 a924 a702 2774 ........A..$..'t
11:14:52.033837 127.0.0.1.47758 > 127.0.0.1.32814: . ack 188 win 32767 <nop,nop,timestamp 600132 600132> (DF)
0x0000 4500 0034 45c0 4000 4006 f701 7f00 0001 E..4E.@.@.......
0x0010 7f00 0001 ba8e 802e c011 5f14 c024 4a03 .........._..$J.
0x0020 8010 7fff 4416 0000 0101 080a 0009 2844 ....D.........(D
0x0030 0009 2844 ..(D
11:14:52.593017 127.0.0.1.47758 > 127.0.0.1.32814: P 1:144(143) ack 188 win 32767 <nop,nop,timestamp 600188 600132> (DF)
0x0000 4500 00c3 45c1 4000 4006 f671 7f00 0001 E...E.@.@..q....
0x0010 7f00 0001 ba8e 802e c011 5f14 c024 4a03 .........._..J\. 0x0020 8018 7fff feb7 0000 0101 080a 0009 287c \.\.\.\.\.\.\.\.\.\.\.\.\.\.\(| 0x0030 0009 2844 0000 0008 0279 8d09 0000 0000 \.\.\(D\.\.\.\.\.y\.\.\.\.\.\. 0x0040 0000 007f 6500 0000 0470 6f6e 6741 d0a9 \.\.\.\.e\.\.\.\.pongA\.\. 0x0050 24a7 0000 0000 0000 0101 0000 0016 880b ...............
0x0060 0000 0000 000b 0000 0000 0000 0000 0003 ................
0x0070 0101 0000 0017 8801 0001 0000 0018 8a01 ................
0x0080 0003 0200 0000 0000 0000 0001 0101 0000 ................
0x0090 0019 8801 0001 0000 001a 8a01 0006 0300 ................
0x00a0 0000 0000 41d0 a924 a702 2774 0101 0000 ....A..\.\.&#39;t\.\.\.\. 0x00b0 001b 8801 0000 0000 000f 0041 d0a9 24a7 \.\.\.\.\.\.\.\.\.\.\.A\.\..
0x00c0 02c2 a4 ...
11:14:52.593059 127.0.0.1.32814 > 127.0.0.1.47758: . ack 144 win 32767 <nop,nop,timestamp 600188 600188> (DF)
0x0000 4500 0034 58fa 4000 4006 e3c7 7f00 0001 E..4X.@.@.......
0x0010 7f00 0001 802e ba8e c024 4a03 c011 5fa3 .........$J..._.
0x0020 8010 7fff 4317 0000 0101 080a 0009 287c ....C.........(|
0x0030 0009 287c ..(|

You may also want to use the 'broping -r' option, since I recall a data
struct problem with the non-record based broping.

Let me know if you still have issues with this.

scott

Mike Muratet wrote:

Hello Again

Well, this is a lot like a scene in a Hitchcock movie where they do that thing with the lens that makes the hallway seem to get longer and longer.

I have tried a few more things. It appears to me that my local.site.bro is not getting called. I can use broping.bro or broping-record.bro as my starting policy in bro.cfg and I can verify that bro is listening on 47758 with nmap. I can capture the transactions with tcpdump per Scott's recommendation and I can see that there are 7 messages from 127.0.0.1:34102 to 127.0.0.1:47758 with replies. I forget how to interpret the payloads, but I'll go back and read the manual. In any event, all the combinations of broping.bro, broping-record.bro and broping -r return "Could not connect to bro at 127.0.0.1:47758".

So, I reconfigured bro with bro_config. It sets the start policy to localhost.localdomain.bro and I gave it an empty file. I'm not sure I'm entirely clear as to the purpose of this parameter, but that's OK--I don't think that's where the problem lies. With this configuration, the broping script is not getting called and it looks to me that local.site.bro is not getting called. I put print and log statements in it and I don't see anything on standard out or in the logs.

So, does local.site.bro get called automatically or do I have to coerce it with a load statement? If I can make sure bro is configured properly then maybe the rest will fall into place. I notice that bro_config writes some network information into local.site.bro. What happens to bro if this information is not available?

Thanks

Mike

Mike,

I usually just do this (my shell is bash):
cd /usr/local/bro
. etc/bro.cfg
./bro -i eth1 -i eth2 localhost.localdomain.bro

The '. etc/bro.cfg' should set your $BROHOME and $BROPATH
correctly to find all of the needed the files.

The order the files load is that bro is invoked with a start
file (in the above localhost.localdomain.bro). In that file (which is
in $BROHOME/site) there should be a couple of lines like this at
the top:

---------------- localhost.localdomain.bro ----------------------------
@prefixes = local
@load site # file generated by the network script for dynamic config
                    # of the local network subnets.

# Make any changes to policy starting here
....
-------------- end --------------------------------------

and the '@load site' will load the local.site.bro file from $BROHOME/site
if your making changes, you should be making it to the 'localhost.localdoamin.bro'
file (which really should be the name of your box (i.e. foo.example.com.bro).

If you don't have any network info in local.site.bro, bro will not be able to
tell which hosts are 'inside' the network, and which are 'outside' :wink:

Having said all this. If you see that bro is listening to 47758, i'm pretty sure
that it has loaded the broccoli stuff.

Cheers,
jason

Mike Muratet wrote:

Mike,

I'll just try to answer to your comments in the sequence they came
in. :slight_smile:

> \./bro \~/devel/Broccoli/test/broping\.bro &gt; 1117837283\.819435 warning: event handlers never invoked: &gt; 1117837283\.819435 warning: ping &gt; &gt; broping
> pong event from 127.0.0.1: seq=0, time=0.010662/1.010452 s
> pong event from 127.0.0.1: seq=1, time=0.008867/1.008964 s
> pong event from 127.0.0.1: seq=2, time=0.038239/1.009833 s
> pong event from 127.0.0.1: seq=3, time=0.009923/1.009428 s
> pong event from 127.0.0.1: seq=4, time=0.038738/1.009980 s

I stopped bro and used nmap to scan 47757 and 47758 and they are both
closed. I then restarted bro with load @broping as the last line in my
local.site.bro and repeated the scan with the result that 47757 is now open.

Sounds good. To be extra sure that no policy settings interfere with
broping.bro, just run broping.bro directly as shown above.

The latest iana.org list shows these ports are in an 'unassigned' range. I
am starting bro logged in a root and the bro.cfg file defines root as the
user.

Don't be root -- there's no need. The reason why we're using the high
ports in the unassigned range is precisely so you don't have to be root.

The comm.log file says that bro is listening on 127.0.0.1:47757. It also
complains on the line above this that "can't bind to port: address in use".
I have no clue what this means, since the port scan shows those ports closed
when bro is stopped.

I'm guessing that multiple attempts were made to bind to that port, and
while the first one didn't succeed the following one did. Looking at the
code I think that when Bro says it's listening, it definitely is.

I looked at broping.bro, which loads listen-clear.bro which loads
remote.bro. remote.bro defines 'default_port_clear=47757.tcp'.
listen-clear.bro uses this value to initialize listen_port_clear.
broping.bro checks to see if listen_port_clear is defined and if so
redefines it to 47758. If this were successful, would not the port scan show
47758 as open? Running broping -d -d I see in the output that the connection
was refused to 127.0.0.1:47758.

Does it say "connection refused", or "Could not connect to Bro"? This
difference is important -- the former would mean the TCP connection
couldn't be established, while the latter would mean something in the
Bro-internal protocol handshake may have gone wrong.

Make sure your high ports aren't firewalled.

Here's another bit: when I broping -p 47757, the comm.log shows 'request for
unknown event pong' errors. It acts like broping.bro is not getting loaded.

So now the connection definitely gets established; I'll assume the
connection refused problem above was a "Could not connect to Bro".

Just avoid any doubts regarding whether or not broping.bro is loaded
correctly by running Bro directly with it, per my example.

Is bro prone to fail things silently?

Not in general, no.

I have tried a few more things. It appears to me that my local.site.bro is
not getting called. I can use broping.bro or broping-record.bro as my
starting policy in bro.cfg and I can verify that bro is listening on 47758
with nmap. I can capture the transactions with tcpdump per Scott's
recommendation and I can see that there are 7 messages from 127.0.0.1:34102
to 127.0.0.1:47758 with replies.

That all sounds good.

I forget how to interpret the payloads, but
I'll go back and read the manual.

Don't bother, that's just the details of the serialization protocol.

In any event, all the combinations of
broping.bro, broping-record.bro and broping -r return "Could not connect to
bro at 127.0.0.1:47758".

Okay. Note that this is a Broccoli-level error message and not at TCP
one (I'll make sure that error message is more clear in that regard for
0.8). The underlying TCP connection does work, according to your
description above. Debugging output will likely allow me to answer
what's going on.

So, I reconfigured bro with bro_config. It sets the start policy to
localhost.localdomain.bro and I gave it an empty file. I'm not sure I'm
entirely clear as to the purpose of this parameter, but that's OK--I don't
think that's where the problem lies. With this configuration, the broping
script is not getting called and it looks to me that local.site.bro is not
getting called. I put print and log statements in it and I don't see
anything on standard out or in the logs.

So, does local.site.bro get called automatically or do I have to coerce it
with a load statement? If I can make sure bro is configured properly then
maybe the rest will fall into place. I notice that bro_config writes some
network information into local.site.bro. What happens to bro if this
information is not available?

Forget all this for now -- just run broping.bro directly. Once that
works, we can always add more stuff around it.

Cheers,
Christian.

Mike,

I usually just do this (my shell is bash):
cd /usr/local/bro
. etc/bro.cfg
./bro -i eth1 -i eth2 localhost.localdomain.bro

The '. etc/bro.cfg' should set your $BROHOME and $BROPATH
correctly to find all of the needed the files.

The order the files load is that bro is invoked with a start
file (in the above localhost.localdomain.bro). In that file (which is
in $BROHOME/site) there should be a couple of lines like this at
the top:

---------------- localhost.localdomain.bro ----------------------------
@prefixes = local
@load site # file generated by the network script for dynamic config
                   # of the local network subnets.

# Make any changes to policy starting here
....
-------------- end --------------------------------------

and the '@load site' will load the local.site.bro file from $BROHOME/site
if your making changes, you should be making it to the 'localhost.localdoamin.bro'
file (which really should be the name of your box (i.e. foo.example.com.bro).

I would cut the above out and paste it into the manual. I suspected it was supposed to work this way but it's not clear. Specifically, there's nothing in the manual that says how local files get called, and the bro_config script apparently doesn't write the necessary lines into localhost.localdomain.bro

The above procedure is failing with a 'can't open site' error. local.site.bro is in $BROPATH. But at least it's something that can be checked.

If you don't have any network info in local.site.bro, bro will not be able to
tell which hosts are 'inside' the network, and which are 'outside' :wink:

Yes, and all other things being equal I think my problem lies in there somewhere.

Having said all this. If you see that bro is listening to 47758, i'm pretty sure
that it has loaded the broccoli stuff.

Well, it did when I used broping.bro as my start policy. If I can figure out what's going on with bro and the file system such that it can't find local.site.bro, maybe I'll be on my way.

Cheers

Mike

Christian

I have been looking at brocolli debug output for broping and the related tcpdump files and bro logs. Using the timestamps I have followed the request to bro for 'ping' and I can see in the bro log that 'ping' was received. There's nothing in the logs about sending 'pong', and so far I haven't been able to locate that part of the bro code by grep'ing "ping". However, I can see in the tcpdump data that there is a response at the appropriate time (even if I don't understand the payload info). Looking at the broccoli output, it appears that it tries repeatedly to read a buffer in sets of 20 attempts, and finally gives up. If you (or anyone on the list) can point me to the write part of bro, I'll look there to see if it's sending 'pong'.

Thanks

Mike

Scott

As I said in my last post, I had tried all the combinations of broping, broping-record and broping, broping -r. I see in the broping.bro and broping-record.bro scripts that printing 'Received ping...' is part of the pong event.

But, the problem seems to have fixed itself and now broping and broping -r work with broping.bro. This bothers me, because outside of a stray gamma ray, computers are deterministic devices and I have done nothing except start and stop bro. The only thing that I can see that changed from trial to trial is the port on which broping attempts to connect to bro.

I have looked at the OpenSSL code in broccoli but I don't see how/where the port gets assigned or why it should be different everytime. Any ideas?

However, I at least have the ability to connect and I can now get back to my original problem.

Thanks

Mike

Hi Mike,

after looking at this debugging output I can say for sure that the TCP
connection between broping and Bro got established successfully. broping
is starting up and beginning its part of the Bro-level connection
handshake, but it never receives anything from Bro: it tries to read
data until the handshake timeout goes off in which case it returns the
failure.

So we need to figure out why your Bro does not send anything back -- I
currently have no idea why that would be the case. Can you please build
Bro in debugging mode (--enable-debug at configure time), and run it
with "-B serial,comm" and send me all of the resulting Bro logs? Thanks.

Note that it doesn't make sense to try all these combinations. Either
use broping and broping.bro, or broping -r and broping-record.bro. In
the former case, all parameters for the pong event are sent separately,
in the latter case, a Bro record type is used to bundle them up.

Cheers,
Christian.

Christian

I have been looking at brocolli debug output for broping and the related
tcpdump files and bro logs. Using the timestamps I have followed the request
to bro for 'ping' and I can see in the bro log that 'ping' was received.
There's nothing in the logs about sending 'pong', and so far I haven't been
able to locate that part of the bro code by grep'ing "ping".

Both the ping and pong events are exclusively defined and handled in
broping.bro:

event ping(src_time: time, seq: count)
        {
        event pong(src_time, current_time(), seq);
        }

event pong(src_time: time, dst_time: time, seq: count)
        {
        print ping_log, fmt("ping received, seq %d, %f at src, %f at dest, one-way: %f",
                            seq, src_time, dst_time, dst_time-src_time);
        }

broping-record.bro does the same thing, using record types.

However, I can
see in the tcpdump data that there is a response at the appropriate time
(even if I don't understand the payload info). Looking at the broccoli
output, it appears that it tries repeatedly to read a buffer in sets of 20
attempts, and finally gives up. If you (or anyone on the list) can point me
to the write part of bro, I'll look there to see if it's sending 'pong'.

Well ... after looking at the ASCII output of tcpdump you sent me, I can
say that the only thing that gets sent back to broping from Bro are TCP
acks, but no actual payload whatsoever. We'll need to look at the Bro
debugging output to figure out why it's not sending anything.

Cheers,
Christian.

Christian

I'll rebuild bro with debug enabled and try again and collect the output.

Mike

Hi Mike,

I discovered that there were multiple instances of bro running which may
explain the 'resource unavailable' errors. I discovered the instances which
I thought had failed to start with a casual 'ps -e -l'.

I can send you more debug files for broping if you need or want them.

I'll still gladly look at your debug output but I'm now a bit confused
about what is actually causing you problems -- in an earlier email you
were saying that