[Bro] log streams in a bro cluster
Luis Martin Liras
martin.liras at gmail.com
Thu Jun 9 07:48:16 PDT 2016
Hi Justin, thank you for your help.
I reply inline in your email. Sorry for the capital letters, they are
just to make a difference between your comments and mine:
On 09/06/16 15:01, Azoff, Justin S wrote:
>> On Jun 9, 2016, at 7:16 AM, Luis Martin Liras <martin.liras at gmail.com> wrote:
>>
>> Hi all,
>>
>> A little bit of investigation and I found (with a tcpdump) that the logs arrive to the manager process BUT they are not stored to disk. Then I found the following entry at the beginning of the communication.log file :
>>
>> 1465472892.006482 manager parent - - - error [#10002/192.168.1.10:57322] unserializing event/function Notice::cluster_notice: write error for creating writer
>>
>>
>> followed by a lot of errors like:
>>
>> 1465473767.549373 manager parent - - - error [#10001/192.168.1.10:57322] unserializing event/function Notice::cluster_notice: write error for log entry
>>
> Ah.. the "write error for creating writer" message is a bit misleading, it outputs that for any error in the process.
>
> Those messages also point to an issue with notices, not with your log file. Are you also calling NOTICE somewhere?
YES I AM. PROBABLY YOU ARE RIGHT AND THAT ERROR IS RELATED TO THE NOTICE
FRAMEWORK. BUT NOTICES AS BEING LOGGED FINE.
> Your problem could be that there is a discrepancy between how you defined warn_info and what you are passing Log::write.
I DON'T THINK SO BECAUSE WHEN RUNNING STANDALONE, THE LOGS ARE WRITTEN FINE.
> Non clustered bro doesn't need to serialize/deserialize the messages so you can get away with certain mistakes that break once you use a cluster.
...BUT I'M WORKING IN A CLUSTER CONFIGURATION. HENCE THE DESERIALIZE
ERROR. WHEN I MENTION STANDALONE I BECAUSE I CAN CHECK ALSO IN A SINGLE
NODE BRO CONFIGURATION, BUT MY OBJECTIVE IS TO MAKE IT WORK IN A CLUSTER.
> The standard log files all use the same mechanism, so if you are getting an http.log then your remote communication is working and there should be nothing preventing your log file from being written.
YEAP, I'M GETTING DNS or CONN LOGS, SO THE LOGGING FRAMEWORK SEEMS TO BE
LOGGING FINE BUT STILL MY OWN LOG FILES ARE NOT WRITTEN TO DISK IN THE
MANAGER NODE.
HAVE A LOOK TO THIS. THIS IS THE LOG DIRECTORY IN ONE OF THE WORKERS:
root at Worker1:/home/bro/bro/spool/worker-1# ls -l
total 2340
-rw-r--r-- 1 root root 6005 Jun 9 16:35 communication.log
-rw-r--r-- 1 root root 8709 Jun 9 16:35 conn.log
-rw-r--r-- 1 root root 20596 Jun 9 16:35 dns.log
-rw-r--r-- 1 root root 292 Jun 9 16:32 known_services.log
-rw-r--r-- 1 root root 23596 Jun 9 16:32 loaded_scripts.log
-rw-r--r-- 1 root root 1425948 Jun 9 16:35 my-prot.log
-rw-r--r-- 1 root root 231 Jun 9 16:32 packet_filter.log
-rw-r--r-- 1 root root 290 Jun 9 16:32 reporter.log
-rw-r--r-- 1 root root 79 Jun 9 16:32 stderr.log
-rw-r--r-- 1 root root 188 Jun 9 16:32 stdout.log
-rw-r--r-- 1 root root 898 Jun 9 16:34 weird.log
...AND THIS IS THE LOG DIRECTORY IN THE MANAGER:
root at Manager:/home/bro/logs# ls -l
total 160
-rw-r--r-- 1 root root 75440 Jun 9 16:36 communication.log
-rw-r--r-- 1 root root 485 Jun 9 16:33 conn.log
-rw-r--r-- 1 root root 429 Jun 9 16:33 dns.log
-rw-r--r-- 1 root root 199 Jun 9 16:32 known_services.log
-rw-r--r-- 1 root root 23113 Jun 9 16:32 loaded_scripts.log
-rw-r--r-- 1 root root 187 Jun 9 16:32 packet_filter.log
-rw-r--r-- 1 root root 237 Jun 9 16:32 reporter.log
-rw-r--r-- 1 root root 0 Jun 9 16:32 stderr.log
-rw-r--r-- 1 root root 188 Jun 9 16:32 stdout.log
-rw-r--r-- 1 root root 249 Jun 9 16:32 weird.log
MY_PROT.LOG IS NOT THERE BUT THE OTHERS LOGS ARE. THERE'S SOMETHING I'M
DOING WRONG AND DON'T KNOW WHAT IT IS..
IT'S STRANGE BECAUSE I CAN SEE WITH TCPDUMP NETWORK TRAFFIC WITH THE
PROPIETARY LOGS SENT TO THE MANAGER:
0x0190: 0008 0100 0000 1243 517a 7a36 5733 5567 .......CQzz6W3Ug
0x01a0: 6d66 4e34 4c59 3372 6600 0000 0d01 040a mfN4LY3rf.......
0x01b0: 0100 0c00 0000 0d01 040a 0100 6500 0000 ............e...
0x01c0: 0201 ffff ffff ffff ffff 0000 0008 0100 ................
0x01d0: 0000 1f30 7835 3020 2d20 5641 5249 4142 ...0x50.-.VARIAB
0x01e0: 4c45 5f4d 4f4e 4954 4f52 5f52 4551 5545 LE_MONITOR_REQUE
0x01f0: 5354 0000 0008 0100 0000 0000 0000 1c00 ST..............
0x0200: 0000 0100 0000 066d 6f64 6275 7300 0000 ................
0x0210: 0800 0000 0601 41d5 d65d ab02 e200 0000 ......A..]......
0x0220: 0008 0100 0000 1243 517a 7a36 5733 5567 .......CQzz6W3Ug
0x0230: 6d66 4e34 4c59 3372 6600 0000 0d01 040a mfN4LY3rf.......
0x0240: 0100 0c00 0000 0c01 0000 0000 0000 d472 ...............r
0x0250: 0000 0001 0000 000d 0104 0a01 0065 0000 .............e..
0x0260: 000c 0100 0000 0000 0001 f600 0000 0100 ................
THIS IS AN EXTRACT FROM A COMMUNICATION BETWEEN WORKER AND MANAGER AND
THAT'S WHAT MY-PROT.LOG SHOULD LOOK LIKE...
> It would help if you could post your scripts somewhere or try to come up with a minimal example that shows the problem.
OK, I will try to summarize what my scripts do:
Workers
=====
1.- I have developed an analyzer for a proprietary protocol. It seems to
work fine.
2.- local-worker.bro:
event bro_init() &priority=5
{
#############
# ANALYZERS #
#############
Analyzer::enable_analyzer(Analyzer::ANALYZER_MY-PROT);
Analyzer::register_for_ports(Analyzer::ANALYZER_MY-PROT, My-ports);
###########
# LOGGING #
###########
Log::create_stream(myprot::MY-PROT_LOG, [$columns=myprot_info,
$path="myprot"]);
Log::create_stream(myprot::MY-PROT_WARN,
[$columns=myprot_info,$path="warnings"]);
...
}
Both proprietary protocol messages and warnings are written to
MY-PROT_LOG or MY-PROT_WARN streams with a command like:
Log::write(log, [$ts=network_time(), $uid=c$uid, $origin=host,
$destination=dest, $warn_level=warning_level, $message=texto,
$options=options]);
At the same time there are other situations (FTP traffic warnings, etc,
that are generated as notices) with a command like:
NOTICE([$note=tipo, $msg=texto, $conn=c, $sub=options,
$n=int_to_count(warning_level)]);
So Yes, I think it's what you are saying, I'm mixing logs and notices...
but, Shouldn't do I?.
If I run my scripts locally (standalone), they all seem to work fine,
both logs and notice files are generated , but of course, with this
configuration, there's only one Bro process and just a single node. The
problem comes with the manager node.
3.- local-manager.bro
The manager policy script simply manages the Notices through a call to:
hook Notice::policy(not:Notice::Info)
{
...
}
...and depending if the notices are related to some allowed or forbidden
IPs, and depending on the warning_level of the notice, it generates or
not, an alarm or an email:
...
if (warning_level>email_warning_threshold)
{
add not$actions[Notice::ACTION_EMAIL];
}
else
{
add not$actions[Notice::ACTION_ALARM];
}
...
The notices are logged fine in the manager, this is notice.log:
(...)
1465481767.026893 CqZikc1SK1fLN2cvb2 192.168.0.12 54386
192.168.0.101 502 - - - tcp (empty) NOT_SEEN_CONN
SLAVE=0 192.168.0.12 192.168.0.101 502 2 worker-2
Notice::ACTION_LOG 3600.000000 F - - - - -
(...)
but I have just realized that they are all logged as
NOTICE::ACTION_LOG and not as ACTION_EMAIL or ACTION_ALARM.
It's important to note that I'm not trying to manage my-prot logs in the
manager policy script. Maybe there's something I need to add in the
manager policy script to get those logs?
Thank you for your help!.
More information about the Bro
mailing list