From 43e54c7930a1286447d97a7f4696232b54d1491c Mon Sep 17 00:00:00 2001 From: Jon Siwek Date: Wed, 5 Feb 2020 13:03:21 -0800 Subject: [PATCH] GH-780: Prevent log batches from indefinite buffering Logs that got sent sparsely or burstily would get buffered for long periods of time since the logic to flush them only does so on the next log write. In the worst case, a subsequent log write could never happen and cause a log entry to be indefinitely buffered. This fix introduces a recurring event/timer to simply flush all pending logs at frequency of Broker::log_batch_interval. --- scripts/base/frameworks/broker/main.zeek | 11 ++ src/broker/Manager.cc | 9 +- src/broker/Manager.h | 2 - .../broker.remote_log_batch/recv.recv.out | 0 .../broker.remote_log_batch/recv.test.log | 11 ++ .../broker.remote_log_batch/send.send.out | 1 + .../broker.remote_log_batch/send.test.log | 11 ++ .../recv.recv.out | 1 - testing/btest/Baseline/plugins.hooks/output | 40 +++++-- .../all-events-no-args.log | 12 ++ .../all-events.log | 12 ++ testing/btest/broker/remote_event.zeek | 6 +- testing/btest/broker/remote_event_any.zeek | 6 +- .../btest/broker/remote_event_ssl_auth.zeek | 6 +- testing/btest/broker/remote_log_batch.zeek | 105 ++++++++++++++++++ testing/btest/broker/remote_log_types.zeek | 12 +- .../language/paraglob-serialization.zeek | 1 - 17 files changed, 224 insertions(+), 22 deletions(-) create mode 100644 testing/btest/Baseline/broker.remote_log_batch/recv.recv.out create mode 100644 testing/btest/Baseline/broker.remote_log_batch/recv.test.log create mode 100644 testing/btest/Baseline/broker.remote_log_batch/send.send.out create mode 100644 testing/btest/Baseline/broker.remote_log_batch/send.test.log create mode 100644 testing/btest/broker/remote_log_batch.zeek diff --git a/scripts/base/frameworks/broker/main.zeek b/scripts/base/frameworks/broker/main.zeek index d3fefd8939..b058a8a9bf 100644 --- a/scripts/base/frameworks/broker/main.zeek +++ b/scripts/base/frameworks/broker/main.zeek @@ -379,6 +379,17 @@ export { module Broker; +event Broker::log_flush() &priority=10 + { + Broker::flush_logs(); + schedule Broker::log_batch_interval { Broker::log_flush() }; + } + +event zeek_init() + { + schedule Broker::log_batch_interval { Broker::log_flush() }; + } + event retry_listen(a: string, p: port, retry: interval) { listen(a, p, retry); diff --git a/src/broker/Manager.cc b/src/broker/Manager.cc index 129f6ad525..29564a386f 100644 --- a/src/broker/Manager.cc +++ b/src/broker/Manager.cc @@ -131,7 +131,6 @@ Manager::Manager(bool arg_reading_pcaps) after_zeek_init = false; peer_count = 0; log_batch_size = 0; - log_batch_interval = 0; log_topic_func = nullptr; vector_of_data_type = nullptr; log_id_type = nullptr; @@ -147,7 +146,6 @@ void Manager::InitPostScript() DBG_LOG(DBG_BROKER, "Initializing"); log_batch_size = get_option("Broker::log_batch_size")->AsCount(); - log_batch_interval = get_option("Broker::log_batch_interval")->AsInterval(); default_log_topic_prefix = get_option("Broker::default_log_topic_prefix")->AsString()->CheckString(); log_topic_func = get_option("Broker::log_topic")->AsFunc(); @@ -580,8 +578,7 @@ bool Manager::PublishLogWrite(EnumVal* stream, EnumVal* writer, string path, int auto& pending_batch = lb.msgs[topic]; pending_batch.emplace_back(msg.move_data()); - if ( lb.message_count >= log_batch_size || - (network_time - lb.last_flush >= log_batch_interval ) ) + if ( lb.message_count >= log_batch_size ) statistics.num_logs_outgoing += lb.Flush(bstate->endpoint, log_batch_size); return true; @@ -608,7 +605,6 @@ size_t Manager::LogBuffer::Flush(broker::endpoint& endpoint, size_t log_batch_si } auto rval = message_count; - last_flush = network_time; message_count = 0; return rval; } @@ -619,8 +615,9 @@ size_t Manager::FlushLogBuffers() auto rval = 0u; for ( auto& lb : log_buffers ) - rval += lb.Flush(bstate->endpoint, log_batch_interval); + rval += lb.Flush(bstate->endpoint, log_batch_size); + statistics.num_logs_outgoing += rval; return rval; } diff --git a/src/broker/Manager.h b/src/broker/Manager.h index 5f98177a09..0cbde06090 100644 --- a/src/broker/Manager.h +++ b/src/broker/Manager.h @@ -354,7 +354,6 @@ private: struct LogBuffer { // Indexed by topic string. std::unordered_map msgs; - double last_flush; size_t message_count; size_t Flush(broker::endpoint& endpoint, size_t batch_size); @@ -389,7 +388,6 @@ private: int peer_count; size_t log_batch_size; - double log_batch_interval; Func* log_topic_func; VectorType* vector_of_data_type; EnumType* log_id_type; diff --git a/testing/btest/Baseline/broker.remote_log_batch/recv.recv.out b/testing/btest/Baseline/broker.remote_log_batch/recv.recv.out new file mode 100644 index 0000000000..e69de29bb2 diff --git a/testing/btest/Baseline/broker.remote_log_batch/recv.test.log b/testing/btest/Baseline/broker.remote_log_batch/recv.test.log new file mode 100644 index 0000000000..c2196df246 --- /dev/null +++ b/testing/btest/Baseline/broker.remote_log_batch/recv.test.log @@ -0,0 +1,11 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-02-05-20-53-15 +#fields msg num +#types string count +ping 0 +ping 1 +#close 2020-02-05-20-53-16 diff --git a/testing/btest/Baseline/broker.remote_log_batch/send.send.out b/testing/btest/Baseline/broker.remote_log_batch/send.send.out new file mode 100644 index 0000000000..c2520da821 --- /dev/null +++ b/testing/btest/Baseline/broker.remote_log_batch/send.send.out @@ -0,0 +1 @@ +Broker::peer_added, 127.0.0.1 diff --git a/testing/btest/Baseline/broker.remote_log_batch/send.test.log b/testing/btest/Baseline/broker.remote_log_batch/send.test.log new file mode 100644 index 0000000000..c2196df246 --- /dev/null +++ b/testing/btest/Baseline/broker.remote_log_batch/send.test.log @@ -0,0 +1,11 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open 2020-02-05-20-53-15 +#fields msg num +#types string count +ping 0 +ping 1 +#close 2020-02-05-20-53-16 diff --git a/testing/btest/Baseline/language.paraglob-serialization/recv.recv.out b/testing/btest/Baseline/language.paraglob-serialization/recv.recv.out index bd6ae96cfa..4d6b544da5 100644 --- a/testing/btest/Baseline/language.paraglob-serialization/recv.recv.out +++ b/testing/btest/Baseline/language.paraglob-serialization/recv.recv.out @@ -9,4 +9,3 @@ is_remote should be T, and is, T receiver got ping number: 3 [*, *ello, hello] is_remote should be T, and is, T -[num_peers=1, num_stores=0, num_pending_queries=0, num_events_incoming=4, num_events_outgoing=3, num_logs_incoming=0, num_logs_outgoing=1, num_ids_incoming=0, num_ids_outgoing=0] diff --git a/testing/btest/Baseline/plugins.hooks/output b/testing/btest/Baseline/plugins.hooks/output index dde704c5af..8fc63394a8 100644 --- a/testing/btest/Baseline/plugins.hooks/output +++ b/testing/btest/Baseline/plugins.hooks/output @@ -276,7 +276,7 @@ 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> -0.000000 MetaHookPost CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T])) -> +0.000000 MetaHookPost CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T])) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Broker::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Cluster::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Config::LOG)) -> @@ -457,7 +457,7 @@ 0.000000 MetaHookPost CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> 0.000000 MetaHookPost CallFunction(Log::create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> 0.000000 MetaHookPost CallFunction(Log::create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> -0.000000 MetaHookPost CallFunction(Log::write, , (PacketFilter::LOG, [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T])) -> +0.000000 MetaHookPost CallFunction(Log::write, , (PacketFilter::LOG, [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T])) -> 0.000000 MetaHookPost CallFunction(NetControl::check_plugins, , ()) -> 0.000000 MetaHookPost CallFunction(NetControl::init, , ()) -> 0.000000 MetaHookPost CallFunction(Notice::want_pp, , ()) -> @@ -1180,7 +1180,7 @@ 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -0.000000 MetaHookPre CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T])) +0.000000 MetaHookPre CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T])) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Broker::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Cluster::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Config::LOG)) @@ -1361,7 +1361,7 @@ 0.000000 MetaHookPre CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) 0.000000 MetaHookPre CallFunction(Log::create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) 0.000000 MetaHookPre CallFunction(Log::create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -0.000000 MetaHookPre CallFunction(Log::write, , (PacketFilter::LOG, [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T])) +0.000000 MetaHookPre CallFunction(Log::write, , (PacketFilter::LOG, [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T])) 0.000000 MetaHookPre CallFunction(NetControl::check_plugins, , ()) 0.000000 MetaHookPre CallFunction(NetControl::init, , ()) 0.000000 MetaHookPre CallFunction(Notice::want_pp, , ()) @@ -2083,7 +2083,7 @@ 0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]) 0.000000 | HookCallFunction Log::__create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]) 0.000000 | HookCallFunction Log::__create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]) -0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T]) +0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T]) 0.000000 | HookCallFunction Log::add_default_filter(Broker::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Cluster::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Config::LOG) @@ -2264,7 +2264,7 @@ 0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]) 0.000000 | HookCallFunction Log::create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]) 0.000000 | HookCallFunction Log::create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]) -0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T]) +0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T]) 0.000000 | HookCallFunction NetControl::check_plugins() 0.000000 | HookCallFunction NetControl::init() 0.000000 | HookCallFunction Notice::want_pp() @@ -2705,27 +2705,35 @@ 0.000000 | HookLoadFile base<...>/xmpp 0.000000 | HookLoadFile base<...>/zeek.bif.zeek 0.000000 | HookLogInit packet_filter 1/1 {ts (time), node (string), filter (string), init (bool), success (bool)} -0.000000 | HookLogWrite packet_filter [ts=1579727603.636084, node=zeek, filter=ip or not ip, init=T, success=T] +0.000000 | HookLogWrite packet_filter [ts=1580932537.132762, node=zeek, filter=ip or not ip, init=T, success=T] 0.000000 | HookQueueEvent NetControl::init() 0.000000 | HookQueueEvent filter_change_tracking() 0.000000 | HookQueueEvent zeek_init() 1362692526.869344 MetaHookPost BroObjDtor() -> +1362692526.869344 MetaHookPost CallFunction(Broker::__flush_logs, , ()) -> +1362692526.869344 MetaHookPost CallFunction(Broker::flush_logs, , ()) -> +1362692526.869344 MetaHookPost CallFunction(Broker::log_flush, , ()) -> 1362692526.869344 MetaHookPost CallFunction(ChecksumOffloading::check, , ()) -> 1362692526.869344 MetaHookPost CallFunction(filter_change_tracking, , ()) -> 1362692526.869344 MetaHookPost CallFunction(get_net_stats, , ()) -> 1362692526.869344 MetaHookPost CallFunction(new_connection, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.0, service={}, history=, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> 1362692526.869344 MetaHookPost DrainEvents() -> +1362692526.869344 MetaHookPost QueueEvent(Broker::log_flush()) -> false 1362692526.869344 MetaHookPost QueueEvent(ChecksumOffloading::check()) -> false 1362692526.869344 MetaHookPost QueueEvent(filter_change_tracking()) -> false 1362692526.869344 MetaHookPost QueueEvent(new_connection([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.0, service={}, history=, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> false 1362692526.869344 MetaHookPost SetupAnalyzerTree(1362692526.869344(1362692526.869344) TCP 141.142.228.5:59856 -> 192.150.187.43:80) -> 1362692526.869344 MetaHookPost UpdateNetworkTime(1362692526.869344) -> 1362692526.869344 MetaHookPre BroObjDtor() +1362692526.869344 MetaHookPre CallFunction(Broker::__flush_logs, , ()) +1362692526.869344 MetaHookPre CallFunction(Broker::flush_logs, , ()) +1362692526.869344 MetaHookPre CallFunction(Broker::log_flush, , ()) 1362692526.869344 MetaHookPre CallFunction(ChecksumOffloading::check, , ()) 1362692526.869344 MetaHookPre CallFunction(filter_change_tracking, , ()) 1362692526.869344 MetaHookPre CallFunction(get_net_stats, , ()) 1362692526.869344 MetaHookPre CallFunction(new_connection, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.0, service={}, history=, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) 1362692526.869344 MetaHookPre DrainEvents() +1362692526.869344 MetaHookPre QueueEvent(Broker::log_flush()) 1362692526.869344 MetaHookPre QueueEvent(ChecksumOffloading::check()) 1362692526.869344 MetaHookPre QueueEvent(filter_change_tracking()) 1362692526.869344 MetaHookPre QueueEvent(new_connection([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.0, service={}, history=, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) @@ -2733,16 +2741,20 @@ 1362692526.869344 MetaHookPre UpdateNetworkTime(1362692526.869344) 1362692526.869344 | HookBroObjDtor 1362692526.869344 | HookUpdateNetworkTime 1362692526.869344 +1362692526.869344 | HookCallFunction Broker::__flush_logs() +1362692526.869344 | HookCallFunction Broker::flush_logs() +1362692526.869344 | HookCallFunction Broker::log_flush() 1362692526.869344 | HookCallFunction ChecksumOffloading::check() 1362692526.869344 | HookCallFunction filter_change_tracking() 1362692526.869344 | HookCallFunction get_net_stats() 1362692526.869344 | HookCallFunction new_connection([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.0, service={}, history=, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=]) 1362692526.869344 | HookDrainEvents +1362692526.869344 | HookQueueEvent Broker::log_flush() 1362692526.869344 | HookQueueEvent ChecksumOffloading::check() 1362692526.869344 | HookQueueEvent filter_change_tracking() 1362692526.869344 | HookQueueEvent new_connection([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.0, service={}, history=, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=]) 1362692526.869344 | HookSetupAnalyzerTree 1362692526.869344(1362692526.869344) TCP 141.142.228.5:59856 -> 192.150.187.43:80 -1362692526.869344 | RequestObjDtor ChecksumOffloading::check() +1362692526.869344 | RequestObjDtor Broker::log_flush() 1362692526.939084 MetaHookPost CallFunction(connection_established, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=4, num_pkts=1, num_bytes_ip=64, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=4, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.06974, service={}, history=Sh, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> 1362692526.939084 MetaHookPost DrainEvents() -> 1362692526.939084 MetaHookPost QueueEvent(connection_established([id=[orig_h=141.142.228.5, orig_p=59856<...>/tcp], orig=[size=0, state=4, num_pkts=1, num_bytes_ip=64, flow_label=0, l2_addr=c8:bc:c8:96:d2:a0], resp=[size=0, state=4, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:10:db:88:d2:ef], start_time=1362692526.869344, duration=0.06974, service={}, history=Sh, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> false @@ -3139,6 +3151,9 @@ 1362692527.080828 MetaHookPre UpdateNetworkTime(1362692527.080828) 1362692527.080828 | HookUpdateNetworkTime 1362692527.080828 1362692527.080828 | HookDrainEvents +1362692527.080972 MetaHookPost CallFunction(Broker::__flush_logs, , ()) -> +1362692527.080972 MetaHookPost CallFunction(Broker::flush_logs, , ()) -> +1362692527.080972 MetaHookPost CallFunction(Broker::log_flush, , ()) -> 1362692527.080972 MetaHookPost CallFunction(ChecksumOffloading::check, , ()) -> 1362692527.080972 MetaHookPost CallFunction(Conn::conn_state, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=], tcp)) -> 1362692527.080972 MetaHookPost CallFunction(Conn::determine_service, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> @@ -3167,6 +3182,7 @@ 1362692527.080972 MetaHookPost DrainEvents() -> 1362692527.080972 MetaHookPost LogInit(Log::WRITER_ASCII, default, true, true, conn(1362692527.080972,0.0,0.0), 21, {ts (time), uid (string), id.orig_h (addr), id.orig_p (port), id.resp_h (addr), id.resp_p (port), proto (enum), service (string), duration (interval), orig_bytes (count), resp_bytes (count), conn_state (string), local_orig (bool), local_resp (bool), missed_bytes (count), history (string), orig_pkts (count), orig_ip_bytes (count), resp_pkts (count), resp_ip_bytes (count), tunnel_parents (set[string])}) -> 1362692527.080972 MetaHookPost LogWrite(Log::WRITER_ASCII, default, conn(1362692527.080972,0.0,0.0), 21, {ts (time), uid (string), id.orig_h (addr), id.orig_p (port), id.resp_h (addr), id.resp_p (port), proto (enum), service (string), duration (interval), orig_bytes (count), resp_bytes (count), conn_state (string), local_orig (bool), local_resp (bool), missed_bytes (count), history (string), orig_pkts (count), orig_ip_bytes (count), resp_pkts (count), resp_ip_bytes (count), tunnel_parents (set[string])}, ) -> true +1362692527.080972 MetaHookPost QueueEvent(Broker::log_flush()) -> false 1362692527.080972 MetaHookPost QueueEvent(ChecksumOffloading::check()) -> false 1362692527.080972 MetaHookPost QueueEvent(connection_state_remove([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> false 1362692527.080972 MetaHookPost QueueEvent(filter_change_tracking()) -> false @@ -3174,6 +3190,9 @@ 1362692527.080972 MetaHookPost QueueEvent(successful_connection_remove([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) -> false 1362692527.080972 MetaHookPost QueueEvent(zeek_done()) -> false 1362692527.080972 MetaHookPost UpdateNetworkTime(1362692527.080972) -> +1362692527.080972 MetaHookPre CallFunction(Broker::__flush_logs, , ()) +1362692527.080972 MetaHookPre CallFunction(Broker::flush_logs, , ()) +1362692527.080972 MetaHookPre CallFunction(Broker::log_flush, , ()) 1362692527.080972 MetaHookPre CallFunction(ChecksumOffloading::check, , ()) 1362692527.080972 MetaHookPre CallFunction(Conn::conn_state, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=], tcp)) 1362692527.080972 MetaHookPre CallFunction(Conn::determine_service, , ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) @@ -3202,6 +3221,7 @@ 1362692527.080972 MetaHookPre DrainEvents() 1362692527.080972 MetaHookPre LogInit(Log::WRITER_ASCII, default, true, true, conn(1362692527.080972,0.0,0.0), 21, {ts (time), uid (string), id.orig_h (addr), id.orig_p (port), id.resp_h (addr), id.resp_p (port), proto (enum), service (string), duration (interval), orig_bytes (count), resp_bytes (count), conn_state (string), local_orig (bool), local_resp (bool), missed_bytes (count), history (string), orig_pkts (count), orig_ip_bytes (count), resp_pkts (count), resp_ip_bytes (count), tunnel_parents (set[string])}) 1362692527.080972 MetaHookPre LogWrite(Log::WRITER_ASCII, default, conn(1362692527.080972,0.0,0.0), 21, {ts (time), uid (string), id.orig_h (addr), id.orig_p (port), id.resp_h (addr), id.resp_p (port), proto (enum), service (string), duration (interval), orig_bytes (count), resp_bytes (count), conn_state (string), local_orig (bool), local_resp (bool), missed_bytes (count), history (string), orig_pkts (count), orig_ip_bytes (count), resp_pkts (count), resp_ip_bytes (count), tunnel_parents (set[string])}, ) +1362692527.080972 MetaHookPre QueueEvent(Broker::log_flush()) 1362692527.080972 MetaHookPre QueueEvent(ChecksumOffloading::check()) 1362692527.080972 MetaHookPre QueueEvent(connection_state_remove([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=])) 1362692527.080972 MetaHookPre QueueEvent(filter_change_tracking()) @@ -3210,6 +3230,9 @@ 1362692527.080972 MetaHookPre QueueEvent(zeek_done()) 1362692527.080972 MetaHookPre UpdateNetworkTime(1362692527.080972) 1362692527.080972 | HookUpdateNetworkTime 1362692527.080972 +1362692527.080972 | HookCallFunction Broker::__flush_logs() +1362692527.080972 | HookCallFunction Broker::flush_logs() +1362692527.080972 | HookCallFunction Broker::log_flush() 1362692527.080972 | HookCallFunction ChecksumOffloading::check() 1362692527.080972 | HookCallFunction Conn::conn_state([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=], tcp) 1362692527.080972 | HookCallFunction Conn::determine_service([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=]) @@ -3238,6 +3261,7 @@ 1362692527.080972 | HookDrainEvents 1362692527.080972 | HookLogInit conn 1/1 {ts (time), uid (string), id.orig_h (addr), id.orig_p (port), id.resp_h (addr), id.resp_p (port), proto (enum), service (string), duration (interval), orig_bytes (count), resp_bytes (count), conn_state (string), local_orig (bool), local_resp (bool), missed_bytes (count), history (string), orig_pkts (count), orig_ip_bytes (count), resp_pkts (count), resp_ip_bytes (count), tunnel_parents (set[string])} 1362692527.080972 | HookLogWrite conn [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id.orig_h=141.142.228.5, id.orig_p=59856, id.resp_h=192.150.187.43, id.resp_p=80, proto=tcp, service=http, duration=0.211484, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=, local_resp=, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents=] +1362692527.080972 | HookQueueEvent Broker::log_flush() 1362692527.080972 | HookQueueEvent ChecksumOffloading::check() 1362692527.080972 | HookQueueEvent connection_state_remove([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=, orig_mime_depth=1, resp_mime_depth=1], http_state=[pending={}, current_request=1, current_response=1, trans_depth=1], irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=]) 1362692527.080972 | HookQueueEvent filter_change_tracking() diff --git a/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events-no-args.log b/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events-no-args.log index fef3381aa3..be3c589795 100644 --- a/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events-no-args.log +++ b/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events-no-args.log @@ -1,6 +1,7 @@ 0.000000 zeek_init 0.000000 filter_change_tracking 0.000000 NetControl::init +1254722767.492060 Broker::log_flush 1254722767.492060 ChecksumOffloading::check 1254722767.492060 filter_change_tracking 1254722767.492060 new_connection @@ -19,6 +20,7 @@ 1254722768.219663 smtp_reply 1254722768.224809 protocol_confirmation 1254722768.224809 smtp_request +1254722768.565386 Broker::log_flush 1254722768.566183 smtp_reply 1254722768.566183 smtp_reply 1254722768.566183 smtp_reply @@ -30,6 +32,7 @@ 1254722768.911655 smtp_request 1254722769.253544 smtp_reply 1254722769.254118 smtp_request +1254722769.613798 Broker::log_flush 1254722769.613798 smtp_reply 1254722769.614414 smtp_request 1254722769.956765 smtp_reply @@ -37,6 +40,7 @@ 1254722770.319708 smtp_reply 1254722770.320203 smtp_request 1254722770.320203 mime_begin_entity +1254722770.661679 Broker::log_flush 1254722770.661679 smtp_reply 1254722770.692743 mime_one_header 1254722770.692743 mime_one_header @@ -86,6 +90,7 @@ 1254722770.692804 file_over_new_connection 1254722770.695115 new_connection 1254722771.494181 file_sniff +1254722771.834595 Broker::log_flush 1254722771.858334 mime_end_entity 1254722771.858334 get_file_handle 1254722771.858334 file_state_remove @@ -97,12 +102,15 @@ 1254722771.858334 get_file_handle 1254722771.858334 smtp_request 1254722772.248789 smtp_reply +1254722774.763825 Broker::log_flush 1254722774.763825 smtp_request 1254722775.105467 smtp_reply +1254722776.690444 Broker::log_flush 1254722776.690444 new_connection 1437831776.764391 ChecksumOffloading::check 1437831776.764391 connection_state_remove 1437831776.764391 successful_connection_remove +1437831776.764391 Broker::log_flush 1437831776.764391 connection_state_remove 1437831776.764391 successful_connection_remove 1437831776.764391 connection_state_remove @@ -111,6 +119,7 @@ 1437831776.764391 successful_connection_remove 1437831776.764391 filter_change_tracking 1437831776.764391 new_connection +1437831787.856895 Broker::log_flush 1437831787.856895 new_connection 1437831787.861602 connection_established 1437831787.867142 smtp_reply @@ -155,9 +164,11 @@ 1437831787.905375 get_file_handle 1437831787.905375 smtp_request 1437831787.914113 smtp_reply +1437831798.533593 Broker::log_flush 1437831798.533593 new_connection 1437831799.262632 new_connection 1437831799.461152 new_connection +1437831799.610433 Broker::log_flush 1437831799.610433 connection_established 1437831799.611764 ssl_extension_server_name 1437831799.611764 ssl_extension @@ -216,6 +227,7 @@ 1437831800.045701 ssl_plaintext_data 1437831800.045701 ssl_established 1437831800.217854 net_done +1437831800.217854 Broker::log_flush 1437831800.217854 filter_change_tracking 1437831800.217854 connection_state_remove 1437831800.217854 successful_connection_remove diff --git a/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events.log b/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events.log index 8dfac88201..9fd035b9bd 100644 --- a/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events.log +++ b/testing/btest/Baseline/scripts.policy.misc.dump-events/all-events.log @@ -1,6 +1,7 @@ 0.000000 zeek_init 0.000000 filter_change_tracking 0.000000 NetControl::init +1254722767.492060 Broker::log_flush 1254722767.492060 ChecksumOffloading::check 1254722767.492060 filter_change_tracking 1254722767.492060 new_connection @@ -91,6 +92,7 @@ [2] command: string = EHLO [3] arg: string = GP +1254722768.565386 Broker::log_flush 1254722768.566183 smtp_reply [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=9, state=4, num_pkts=3, num_bytes_ip=137, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=318, state=4, num_pkts=3, num_bytes_ip=309, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=1.037137, service={\x0aSMTP\x0a}, history=ShAdDa, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722768.219663, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=1, helo=GP, mailfrom=, rcptto=, date=, from=, to=, cc=, reply_to=, msg_id=, in_reply_to=, subject=, x_originating_ip=, first_received=, second_received=, last_reply=220 and/or bulk e-mail., path=[74.53.140.153, 10.10.1.4], user_agent=, tls=F, process_received_from=T, has_client_activity=F, entity=, fuids=[]], smtp_state=[helo=GP, messages_transferred=0, pending_messages=, mime_depth=0], socks=, ssh=, syslog=] [1] is_orig: bool = F @@ -173,6 +175,7 @@ [2] command: string = ** [3] arg: string = cHVuamFiQDEyMw== +1254722769.613798 Broker::log_flush 1254722769.613798 smtp_reply [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=69, state=4, num_pkts=6, num_bytes_ip=317, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=384, state=4, num_pkts=6, num_bytes_ip=602, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=2.084752, service={\x0aSMTP\x0a}, history=ShAdDa, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722768.219663, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=1, helo=GP, mailfrom=, rcptto=, date=, from=, to=, cc=, reply_to=, msg_id=, in_reply_to=, subject=, x_originating_ip=, first_received=, second_received=, last_reply=334 UGFzc3dvcmQ6, path=[74.53.140.153, 10.10.1.4], user_agent=, tls=F, process_received_from=T, has_client_activity=F, entity=, fuids=[]], smtp_state=[helo=GP, messages_transferred=0, pending_messages=, mime_depth=0], socks=, ssh=, syslog=] [1] is_orig: bool = F @@ -218,6 +221,7 @@ 1254722770.320203 mime_begin_entity [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=150, state=4, num_pkts=8, num_bytes_ip=472, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=406, state=4, num_pkts=9, num_bytes_ip=774, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=2.791157, service={\x0aSMTP\x0a}, history=ShAdDa, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722768.219663, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=1, helo=GP, mailfrom=gurpartap@patriots.in, rcptto={\x0araj_deol2002in@yahoo.co.in\x0a}, date=, from=, to=, cc=, reply_to=, msg_id=, in_reply_to=, subject=, x_originating_ip=, first_received=, second_received=, last_reply=250 Accepted, path=[74.53.140.153, 10.10.1.4], user_agent=, tls=F, process_received_from=T, has_client_activity=T, entity=, fuids=[]], smtp_state=[helo=GP, messages_transferred=0, pending_messages=, mime_depth=0], socks=, ssh=, syslog=] +1254722770.661679 Broker::log_flush 1254722770.661679 smtp_reply [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=150, state=4, num_pkts=9, num_bytes_ip=518, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=462, state=4, num_pkts=9, num_bytes_ip=774, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=3.132633, service={\x0aSMTP\x0a}, history=ShAdDa, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722768.219663, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=1, helo=GP, mailfrom=gurpartap@patriots.in, rcptto={\x0araj_deol2002in@yahoo.co.in\x0a}, date=, from=, to=, cc=, reply_to=, msg_id=, in_reply_to=, subject=, x_originating_ip=, first_received=, second_received=, last_reply=250 Accepted, path=[74.53.140.153, 10.10.1.4], user_agent=, tls=F, process_received_from=T, has_client_activity=T, entity=[filename=], fuids=[]], smtp_state=[helo=GP, messages_transferred=0, pending_messages=, mime_depth=1], socks=, ssh=, syslog=] [1] is_orig: bool = F @@ -417,6 +421,7 @@ [0] f: fa_file = [id=FL9Y0d45OI4LpS6fmh, parent_id=, source=SMTP, is_orig=T, conns={\x0a\x09[[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp]] = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=4530, state=4, num_pkts=11, num_bytes_ip=3518, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=462, state=4, num_pkts=10, num_bytes_ip=870, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=3.163758, service={\x0aSMTP\x0a\x09}, history=ShAdDa, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722768.219663, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=1, helo=GP, mailfrom=gurpartap@patriots.in, rcptto={\x0araj_deol2002in@yahoo.co.in\x0a\x09}, date=Mon, 5 Oct 2009 11:36:07 +0530, from="Gurpartap Singh" , to={\x0a\x0a\x09}, cc=, reply_to=, msg_id=<000301ca4581$ef9e57f0$cedb07d0$@in>, in_reply_to=, subject=SMTP, x_originating_ip=, first_received=, second_received=, last_reply=354 Enter message, ending with "." on a line by itself, path=[74.53.140.153, 10.10.1.4], user_agent=Microsoft Office Outlook 12.0, tls=F, process_received_from=T, has_client_activity=T, entity=[filename=NEWS.txt], fuids=[Fel9gs4OtNEV6gUJZ5, Ft4M3f2yMvLlmwtbq9, FL9Y0d45OI4LpS6fmh]], smtp_state=[helo=GP, messages_transferred=0, pending_messages=, mime_depth=5], socks=, ssh=, syslog=]\x0a}, last_active=1254722771.494181, seen_bytes=4027, total_bytes=, missing_bytes=0, overflow_bytes=0, timeout_interval=2.0 mins, bof_buffer_size=4096, bof_buffer=Version 4.9.9.1\x0d\x0a* Many bug fixes\x0d\x0a* Improved editor\x0d\x0a\x0d\x0aVersion 4.9.9.0\x0d\x0a* Support for latest Mingw compiler system builds\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.8.9\x0d\x0a* New code tooltip display\x0d\x0a* Improved Indent/Unindent and Remove Comment\x0d\x0a* Improved automatic indent\x0d\x0a* Added support for the "interface" keyword\x0d\x0a* WebUpdate should now report installation problems from PackMan\x0d\x0a* New splash screen and association icons\x0d\x0a* Improved installer\x0d\x0a* Many bug fixes\x0d\x0a\x0d\x0aVersion 4.9.8.7\x0d\x0a* Added support for GCC > 3.2\x0d\x0a* Debug variables are now resent during next debug session\x0d\x0a* Watched Variables not in correct context are now kept and updated when it is needed\x0d\x0a* Added new compiler/linker options: \x0d\x0a - Strip executable\x0d\x0a - Generate instructions for a specific machine (i386, i486, i586, i686, pentium, pentium-mmx, pentiumpro, pentium2, pentium3, pentium4, \x0d\x0a k6, k6-2, k6-3, athlon, athlon-tbird, athlon-4, athlon-xp, athlon-mp, winchip-c6, winchip2, k8, c3 and c3-2)\x0d\x0a - Enable use of processor specific built-in functions (mmmx, sse, sse2, pni, 3dnow)\x0d\x0a* "Default" button in Compiler Options is back\x0d\x0a* Error messages parsing improved\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.8.5\x0d\x0a* Added the possibility to modify the value of a variable during debugging (right click on a watch variable and select "Modify value")\x0d\x0a* During Dev-C++ First Time COnfiguration window, users can now choose between using or not class browser and code completion features.\x0d\x0a* Many bug fixes\x0d\x0a\x0d\x0aVersion 4.9.8.4\x0d\x0a* Added the possibility to specify an include directory for the code completion cache to be created at Dev-C++ first startup\x0d\x0a* Improved code completion cache\x0d\x0a* WebUpdate will now backup downloaded DevPaks in Dev-C++\Packages directory, and Dev-C++ executable in devcpp.exe.BACKUP\x0d\x0a* Big speed up in function parameters listing while editing\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.8.3\x0d\x0a* On Dev-C++ first time configuration dialog, a code completion cache of all the standard \x0d\x0a include files can now be generated.\x0d\x0a* Improved WebUpdate module\x0d\x0a* Many bug fixes\x0d\x0a\x0d\x0aVersion 4.9.8.2\x0d\x0a* New debug feature for DLLs: attach to a running process\x0d\x0a* New project option: Use custom Makefile. \x0d\x0a* New WebUpdater module.\x0d\x0a* Allow user to specify an alternate configuration file in Environment Options \x0d\x0a (still can be overriden by using "-c" command line parameter).\x0d\x0a* Lots of bug fixes.\x0d\x0a\x0d\x0aVersion 4.9.8.1\x0d\x0a* When creating a DLL, the created static lib respects now the project-defined output directory\x0d\x0a\x0d\x0aVersion 4.9.8.0\x0d\x0a* Changed position of compiler/linker parameters in Project Options.\x0d\x0a* Improved help file\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.9\x0d\x0a* Resource errors are now reported in the Resource sheet\x0d\x0a* Many bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.8\x0d\x0a* Made whole bottom report control floating instead of only debug output.\x0d\x0a* Many bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.7\x0d\x0a* Printing settings are now saved\x0d\x0a* New environment options : "watch variable under mouse" and "Report watch errors"\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.6\x0d\x0a* Debug variable browser\x0d\x0a* Added possibility to include in a Template the Project's directories (include, libs and ressources)\x0d\x0a* Changed tint of Class browser pictures colors to match the New Look style\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.5\x0d\x0a* Bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.4\x0d\x0a* When compiling with debugging symbols, an extra definition is passed to the\x0d\x0a compiler: -D__DEBUG__\x0d\x0a* Each project creates a _private.h file containing version\x0d\x0a information definitions\x0d\x0a* When compiling the current file only, no dependency checks are performed\x0d\x0a* ~300% Speed-up in class parser\x0d\x0a* Added "External programs" in Tools/Environment Options (for units "Open with")\x0d\x0a* Added "Open with" in project units context menu\x0d\x0a* Added "Classes" toolbar\x0d\x0a* Fixed pre-compilation dependency checks to work correctly\x0d\x0a* Added new file menu entry: Save Project As\x0d\x0a* Bug-fix for double quotes in devcpp.cfg file read by vUpdate\x0d\x0a* Other bug fixes\x0d\x0a\x0d\x0aVersion 4.9.7.3\x0d\x0a* When adding debugging symbols on request, remove "-s" option from linker\x0d\x0a* Compiling progress window\x0d\x0a* Environment options : "Show progress window" and "Auto-close progress , info=[ts=1254722770.692804, fuid=FL9Y0d45OI4LpS6fmh, tx_hosts={\x0a\x0910.10.1.4\x0a}, rx_hosts={\x0a\x0974.53.140.153\x0a}, conn_uids={\x0aClEkJM2Vm5giqnMf4h\x0a}, source=SMTP, depth=5, analyzers={\x0a\x0a}, mime_type=, filename=NEWS.txt, duration=0 secs, local_orig=, is_orig=T, seen_bytes=0, total_bytes=, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=, md5=, sha1=, sha256=, x509=, extracted=, extracted_cutoff=, extracted_size=], ftp=, http=, irc=, pe=] [1] meta: fa_metadata = [mime_type=text/plain, mime_types=[[strength=-20, mime=text/plain]], inferred=T] +1254722771.834595 Broker::log_flush 1254722771.858334 mime_end_entity [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=14699, state=4, num_pkts=23, num_bytes_ip=21438, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=462, state=4, num_pkts=15, num_bytes_ip=1070, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=4.329288, service={\x0aSMTP\x0a}, history=ShAdDaT, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722768.219663, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=1, helo=GP, mailfrom=gurpartap@patriots.in, rcptto={\x0araj_deol2002in@yahoo.co.in\x0a}, date=Mon, 5 Oct 2009 11:36:07 +0530, from="Gurpartap Singh" , to={\x0a\x0a}, cc=, reply_to=, msg_id=<000301ca4581$ef9e57f0$cedb07d0$@in>, in_reply_to=, subject=SMTP, x_originating_ip=, first_received=, second_received=, last_reply=354 Enter message, ending with "." on a line by itself, path=[74.53.140.153, 10.10.1.4], user_agent=Microsoft Office Outlook 12.0, tls=F, process_received_from=T, has_client_activity=T, entity=[filename=NEWS.txt], fuids=[Fel9gs4OtNEV6gUJZ5, Ft4M3f2yMvLlmwtbq9, FL9Y0d45OI4LpS6fmh]], smtp_state=[helo=GP, messages_transferred=0, pending_messages=, mime_depth=5], socks=, ssh=, syslog=] @@ -470,6 +475,7 @@ [4] msg: string = OK id=1Mugho-0003Dg-Un [5] cont_resp: bool = F +1254722774.763825 Broker::log_flush 1254722774.763825 smtp_request [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=14705, state=4, num_pkts=25, num_bytes_ip=21547, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=490, state=4, num_pkts=22, num_bytes_ip=1378, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=7.234779, service={\x0aSMTP\x0a}, history=ShAdDaT, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722772.248789, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=2, helo=GP, mailfrom=, rcptto=, date=, from=, to=, cc=, reply_to=, msg_id=, in_reply_to=, subject=, x_originating_ip=, first_received=, second_received=, last_reply=, path=[74.53.140.153, 10.10.1.4], user_agent=, tls=F, process_received_from=T, has_client_activity=F, entity=, fuids=[]], smtp_state=[helo=GP, messages_transferred=1, pending_messages=, mime_depth=5], socks=, ssh=, syslog=] [1] is_orig: bool = T @@ -484,6 +490,7 @@ [4] msg: string = xc90.websitewelcome.com closing connection [5] cont_resp: bool = F +1254722776.690444 Broker::log_flush 1254722776.690444 new_connection [0] c: connection = [id=[orig_h=10.10.1.20, orig_p=138/udp, resp_h=10.10.1.255, resp_p=138/udp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:02:3f:ec:61:11], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=ff:ff:ff:ff:ff:ff], start_time=1254722776.690444, duration=0.0, service={\x0a\x0a}, history=, uid=CtPZjS20MLrsMUOJi2, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] @@ -494,6 +501,7 @@ 1437831776.764391 successful_connection_remove [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=56166/udp, resp_h=10.10.1.1, resp_p=53/udp], orig=[size=34, state=1, num_pkts=1, num_bytes_ip=62, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=100, state=1, num_pkts=1, num_bytes_ip=128, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.49206, duration=0.034025, service={\x0aDNS\x0a}, history=Dd, uid=CHhAvVGS1DHFjwGM9, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=[ts=1254722767.49206, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=10.10.1.4, orig_p=56166/udp, resp_h=10.10.1.1, resp_p=53/udp], proto=udp, service=dns, duration=0.034025, orig_bytes=34, resp_bytes=100, conn_state=SF, local_orig=, local_resp=, missed_bytes=0, history=Dd, orig_pkts=1, orig_ip_bytes=62, resp_pkts=1, resp_ip_bytes=128, tunnel_parents=], extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=[pending_query=, pending_queries=, pending_replies=], ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] +1437831776.764391 Broker::log_flush 1437831776.764391 connection_state_remove [0] c: connection = [id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], orig=[size=14705, state=5, num_pkts=28, num_bytes_ip=21673, flow_label=0, l2_addr=00:e0:1c:3c:17:c2], resp=[size=538, state=5, num_pkts=25, num_bytes_ip=1546, flow_label=0, l2_addr=00:1f:33:d9:81:60], start_time=1254722767.529046, duration=7.576953, service={\x0aSMTP\x0a}, history=ShAdDaTFf, uid=ClEkJM2Vm5giqnMf4h, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=[ts=1254722772.248789, uid=ClEkJM2Vm5giqnMf4h, id=[orig_h=10.10.1.4, orig_p=1470/tcp, resp_h=74.53.140.153, resp_p=25/tcp], trans_depth=2, helo=GP, mailfrom=, rcptto=, date=, from=, to=, cc=, reply_to=, msg_id=, in_reply_to=, subject=, x_originating_ip=, first_received=, second_received=, last_reply=221 xc90.websitewelcome.com closing connection, path=[74.53.140.153, 10.10.1.4], user_agent=, tls=F, process_received_from=T, has_client_activity=F, entity=, fuids=[]], smtp_state=[helo=GP, messages_transferred=1, pending_messages=, mime_depth=5], socks=, ssh=, syslog=] @@ -516,6 +524,7 @@ 1437831776.764391 new_connection [0] c: connection = [id=[orig_h=192.168.133.100, orig_p=49285/tcp, resp_h=66.196.121.26, resp_p=5050/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=58:b0:35:86:54:8d], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=cc:b2:55:f4:62:92], start_time=1437831776.764391, duration=0.0, service={\x0a\x0a}, history=, uid=CUM0KZ3MLUfNB0cl11, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] +1437831787.856895 Broker::log_flush 1437831787.856895 new_connection [0] c: connection = [id=[orig_h=192.168.133.100, orig_p=49648/tcp, resp_h=192.168.133.102, resp_p=25/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=58:b0:35:86:54:8d], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=00:08:ca:cc:ad:4c], start_time=1437831787.856895, duration=0.0, service={\x0a\x0a}, history=, uid=CmES5u32sYpV7JYN, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] @@ -751,6 +760,7 @@ [4] msg: string = Ok [5] cont_resp: bool = F +1437831798.533593 Broker::log_flush 1437831798.533593 new_connection [0] c: connection = [id=[orig_h=192.168.133.100, orig_p=49336/tcp, resp_h=74.125.71.189, resp_p=443/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=58:b0:35:86:54:8d], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=cc:b2:55:f4:62:92], start_time=1437831798.533593, duration=0.0, service={\x0a\x0a}, history=^, uid=CP5puj4I8PtEU4qzYg, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] @@ -760,6 +770,7 @@ 1437831799.461152 new_connection [0] c: connection = [id=[orig_h=192.168.133.100, orig_p=49655/tcp, resp_h=17.167.150.73, resp_p=443/tcp], orig=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=58:b0:35:86:54:8d], resp=[size=0, state=0, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=cc:b2:55:f4:62:92], start_time=1437831799.461152, duration=0.0, service={\x0a\x0a}, history=, uid=C3eiCBGOLw3VtHfOj, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] +1437831799.610433 Broker::log_flush 1437831799.610433 connection_established [0] c: connection = [id=[orig_h=192.168.133.100, orig_p=49655/tcp, resp_h=17.167.150.73, resp_p=443/tcp], orig=[size=0, state=4, num_pkts=1, num_bytes_ip=64, flow_label=0, l2_addr=58:b0:35:86:54:8d], resp=[size=0, state=4, num_pkts=0, num_bytes_ip=0, flow_label=0, l2_addr=cc:b2:55:f4:62:92], start_time=1437831799.461152, duration=0.149281, service={\x0a\x0a}, history=Sh, uid=C3eiCBGOLw3VtHfOj, tunnel=, vlan=, inner_vlan=, successful=F, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=, http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] @@ -1044,6 +1055,7 @@ 1437831800.217854 net_done [0] t: time = 1437831800.217854 +1437831800.217854 Broker::log_flush 1437831800.217854 filter_change_tracking 1437831800.217854 connection_state_remove [0] c: connection = [id=[orig_h=192.168.133.100, orig_p=49655/tcp, resp_h=17.167.150.73, resp_p=443/tcp], orig=[size=2249, state=4, num_pkts=15, num_bytes_ip=2873, flow_label=0, l2_addr=58:b0:35:86:54:8d], resp=[size=3653, state=4, num_pkts=13, num_bytes_ip=4185, flow_label=0, l2_addr=cc:b2:55:f4:62:92], start_time=1437831799.461152, duration=0.756702, service={\x0aSSL\x0a}, history=ShADda, uid=C3eiCBGOLw3VtHfOj, tunnel=, vlan=, inner_vlan=, successful=T, dpd=, dpd_state=, conn=, extract_orig=F, extract_resp=F, thresholds=, dce_rpc=, dce_rpc_state=, dce_rpc_backing=, dhcp=, dnp3=, dns=, dns_state=, ftp=, ftp_data_reuse=F, ssl=[ts=1437831799.611764, uid=C3eiCBGOLw3VtHfOj, id=[orig_h=192.168.133.100, orig_p=49655/tcp, resp_h=17.167.150.73, resp_p=443/tcp], version_num=771, version=TLSv12, cipher=TLS_RSA_WITH_RC4_128_MD5, curve=, server_name=p31-keyvalueservice.icloud.com, session_id=, resumed=F, client_ticket_empty_session_seen=F, client_key_exchange_seen=T, server_appdata=0, client_appdata=F, last_alert=, next_protocol=, analyzer_id=, established=T, logged=T, delay_tokens=, cert_chain=[[ts=1437831799.764576, fuid=F1vce92FT1oRjKI328, tx_hosts={\x0a\x0917.167.150.73\x0a}, rx_hosts={\x0a\x09192.168.133.100\x0a}, conn_uids={\x0aC3eiCBGOLw3VtHfOj\x0a}, source=SSL, depth=0, analyzers={\x0aMD5,\x0aSHA1,\x0aX509\x0a}, mime_type=application/x-x509-user-cert, filename=, duration=0 secs, local_orig=, is_orig=F, seen_bytes=1406, total_bytes=, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=, md5=1bf9696d9f337805383427e88781d001, sha1=f5ccb1a724133607548b00d8eb402efca3076d58, sha256=, x509=[ts=1437831799.764576, id=F1vce92FT1oRjKI328, certificate=[version=3, serial=053FCE9BA6805B00, subject=C=US,ST=California,O=Apple Inc.,OU=management:idms.group.506364,CN=*.icloud.com, issuer=C=US,O=Apple Inc.,OU=Certification Authority,CN=Apple IST CA 2 - G1, cn=*.icloud.com, not_valid_before=1424184331.0, not_valid_after=1489848331.0, key_alg=rsaEncryption, sig_alg=sha256WithRSAEncryption, key_type=rsa, key_length=2048, exponent=65537, curve=], handle=, extensions=[[name=Authority Information Access, short_name=authorityInfoAccess, oid=1.3.6.1.5.5.7.1.1, critical=F, value=OCSP - URI:http://ocsp.apple.com/ocsp04-appleistca2g101\x0a], [name=X509v3 Subject Key Identifier, short_name=subjectKeyIdentifier, oid=2.5.29.14, critical=F, value=8E:51:A1:0E:0A:9B:1C:04:F7:59:D3:69:2E:23:16:91:0E:AD:06:FB], [name=X509v3 Basic Constraints, short_name=basicConstraints, oid=2.5.29.19, critical=T, value=CA:FALSE], [name=X509v3 Authority Key Identifier, short_name=authorityKeyIdentifier, oid=2.5.29.35, critical=F, value=keyid:D8:7A:94:44:7C:90:70:90:16:9E:DD:17:9C:01:44:03:86:D6:2A:29\x0a], [name=X509v3 Certificate Policies, short_name=certificatePolicies, oid=2.5.29.32, critical=F, value=Policy: 1.2.840.113635.100.5.11.4\x0a User Notice:\x0a Explicit Text: Reliance on this certificate by any party assumes acceptance of any applicable terms and conditions of use and/or certification practice statements.\x0a CPS: http://www.apple.com/certificateauthority/rpa\x0a], [name=X509v3 CRL Distribution Points, short_name=crlDistributionPoints, oid=2.5.29.31, critical=F, value=\x0aFull Name:\x0a URI:http://crl.apple.com/appleistca2g1.crl\x0a], [name=X509v3 Key Usage, short_name=keyUsage, oid=2.5.29.15, critical=T, value=Digital Signature, Key Encipherment], [name=X509v3 Extended Key Usage, short_name=extendedKeyUsage, oid=2.5.29.37, critical=F, value=TLS Web Server Authentication, TLS Web Client Authentication], [name=X509v3 Subject Alternative Name, short_name=subjectAltName, oid=2.5.29.17, critical=F, value=DNS:*.icloud.com]], san=[dns=[*.icloud.com], uri=, email=, ip=, other_fields=F], basic_constraints=[ca=F, path_len=]], extracted=, extracted_cutoff=, extracted_size=], [ts=1437831799.764576, fuid=Fxp53s3wA5G3zdEJg8, tx_hosts={\x0a\x0917.167.150.73\x0a}, rx_hosts={\x0a\x09192.168.133.100\x0a}, conn_uids={\x0aC3eiCBGOLw3VtHfOj\x0a}, source=SSL, depth=0, analyzers={\x0aMD5,\x0aSHA1,\x0aX509\x0a}, mime_type=application/x-x509-ca-cert, filename=, duration=0 secs, local_orig=, is_orig=F, seen_bytes=1092, total_bytes=, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=, md5=48f0e38385112eeca5fc9ffd402eaecd, sha1=8e8321ca08b08e3726fe1d82996884eeb5f0d655, sha256=, x509=[ts=1437831799.764576, id=Fxp53s3wA5G3zdEJg8, certificate=[version=3, serial=023A74, subject=C=US,O=Apple Inc.,OU=Certification Authority,CN=Apple IST CA 2 - G1, issuer=CN=GeoTrust Global CA,O=GeoTrust Inc.,C=US, cn=Apple IST CA 2 - G1, not_valid_before=1402933322.0, not_valid_after=1653061322.0, key_alg=rsaEncryption, sig_alg=sha256WithRSAEncryption, key_type=rsa, key_length=2048, exponent=65537, curve=], handle=, extensions=[[name=X509v3 Authority Key Identifier, short_name=authorityKeyIdentifier, oid=2.5.29.35, critical=F, value=keyid:C0:7A:98:68:8D:89:FB:AB:05:64:0C:11:7D:AA:7D:65:B8:CA:CC:4E\x0a], [name=X509v3 Subject Key Identifier, short_name=subjectKeyIdentifier, oid=2.5.29.14, critical=F, value=D8:7A:94:44:7C:90:70:90:16:9E:DD:17:9C:01:44:03:86:D6:2A:29], [name=X509v3 Basic Constraints, short_name=basicConstraints, oid=2.5.29.19, critical=T, value=CA:TRUE, pathlen:0], [name=X509v3 Key Usage, short_name=keyUsage, oid=2.5.29.15, critical=T, value=Certificate Sign, CRL Sign], [name=X509v3 CRL Distribution Points, short_name=crlDistributionPoints, oid=2.5.29.31, critical=F, value=\x0aFull Name:\x0a URI:http://g.symcb.com/crls/gtglobal.crl\x0a], [name=Authority Information Access, short_name=authorityInfoAccess, oid=1.3.6.1.5.5.7.1.1, critical=F, value=OCSP - URI:http://g.symcd.com\x0a], [name=X509v3 Certificate Policies, short_name=certificatePolicies, oid=2.5.29.32, critical=F, value=Policy: 2.16.840.1.113733.1.7.54\x0a CPS: http://www.geotrust.com/resources/cps\x0a]], san=, basic_constraints=[ca=T, path_len=0]], extracted=, extracted_cutoff=, extracted_size=]], cert_chain_fuids=[F1vce92FT1oRjKI328, Fxp53s3wA5G3zdEJg8], client_cert_chain=[], client_cert_chain_fuids=[], subject=C=US,ST=California,O=Apple Inc.,OU=management:idms.group.506364,CN=*.icloud.com, issuer=C=US,O=Apple Inc.,OU=Certification Authority,CN=Apple IST CA 2 - G1, client_subject=, client_issuer=, server_depth=0, client_depth=0], http=, http_state=, irc=, krb=, modbus=, mysql=, ntlm=, ntp=, radius=, rdp=, rfb=, sip=, sip_state=, snmp=, smb_state=, smtp=, smtp_state=, socks=, ssh=, syslog=] diff --git a/testing/btest/broker/remote_event.zeek b/testing/btest/broker/remote_event.zeek index cdf74e15f3..bfe30be1b7 100644 --- a/testing/btest/broker/remote_event.zeek +++ b/testing/btest/broker/remote_event.zeek @@ -87,7 +87,6 @@ event ping(msg: string, n: count) if ( n == events_to_recv ) { - print get_broker_stats(); terminate(); return; } @@ -96,4 +95,9 @@ event ping(msg: string, n: count) Broker::publish("zeek/event/my_topic", e); } +event zeek_done() + { + print get_broker_stats(); + } + @TEST-END-FILE diff --git a/testing/btest/broker/remote_event_any.zeek b/testing/btest/broker/remote_event_any.zeek index ac6721335c..6a6492bb98 100644 --- a/testing/btest/broker/remote_event_any.zeek +++ b/testing/btest/broker/remote_event_any.zeek @@ -92,7 +92,6 @@ event ping(msg: string, n: any) if ( (n as count) == events_to_recv ) { - print get_broker_stats(); terminate(); return; } @@ -104,4 +103,9 @@ event ping(msg: string, n: any) Broker::publish("zeek/event/my_topic", pong, msg, n); } +event zeek_done() + { + print get_broker_stats(); + } + @TEST-END-FILE diff --git a/testing/btest/broker/remote_event_ssl_auth.zeek b/testing/btest/broker/remote_event_ssl_auth.zeek index 7ffdae0bda..49307ac081 100644 --- a/testing/btest/broker/remote_event_ssl_auth.zeek +++ b/testing/btest/broker/remote_event_ssl_auth.zeek @@ -247,7 +247,6 @@ event ping(msg: string, n: count) if ( n == events_to_recv ) { - print get_broker_stats(); terminate(); return; } @@ -256,4 +255,9 @@ event ping(msg: string, n: count) Broker::publish("zeek/event/my_topic", e); } +event zeek_done() + { + print get_broker_stats(); + } + @TEST-END-FILE diff --git a/testing/btest/broker/remote_log_batch.zeek b/testing/btest/broker/remote_log_batch.zeek new file mode 100644 index 0000000000..46accc3da4 --- /dev/null +++ b/testing/btest/broker/remote_log_batch.zeek @@ -0,0 +1,105 @@ +# @TEST-PORT: BROKER_PORT + +# @TEST-EXEC: btest-bg-run recv "zeek -B broker -b ../recv.zeek >recv.out" +# @TEST-EXEC: btest-bg-run send "zeek -B broker -b ../send.zeek >send.out" + +# @TEST-EXEC: btest-bg-wait 45 +# @TEST-EXEC: btest-diff recv/recv.out +# @TEST-EXEC: btest-diff recv/test.log +# @TEST-EXEC: btest-diff send/send.out +# @TEST-EXEC: btest-diff send/test.log + +@TEST-START-FILE common.zeek + +redef exit_only_after_terminate = T; + +module Test; + +export { + redef enum Log::ID += { LOG }; + + type Info: record { + msg: string &log; + nolog: string &default="no"; + num: count &log; + }; +} + +event zeek_init() &priority=5 + { + Log::create_stream(Test::LOG, [$columns=Test::Info]); + } + +event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) + { + terminate(); + } + +event quit() + { + terminate(); + } + +@TEST-END-FILE + +@TEST-START-FILE recv.zeek + + +@load ./common + +event zeek_init() + { + Broker::subscribe("zeek/"); + Broker::listen("127.0.0.1", to_port(getenv("BROKER_PORT"))); + } + +event Broker::peer_removed(endpoint: Broker::EndpointInfo, msg: string) + { + terminate(); + } + +@TEST-END-FILE + +@TEST-START-FILE send.zeek + +@load ./common + +event zeek_init() + { + Broker::peer("127.0.0.1", to_port(getenv("BROKER_PORT"))); + } + +global n = 0; +global done = F; + +event die() + { + terminate(); + } + +event do_write() + { + Log::write(Test::LOG, [$msg = "ping", $num = n]); + ++n; + + if ( n == 1 ) + schedule .1secs { do_write() }; + else + done = T; + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + print "Broker::peer_added", endpoint$network$address; + event do_write(); + } + +module Broker; + +event Broker::log_flush() + { + if ( done ) + Broker::publish("zeek/quit", quit); + } + +@TEST-END-FILE diff --git a/testing/btest/broker/remote_log_types.zeek b/testing/btest/broker/remote_log_types.zeek index 4ea384e5f6..a14a12586d 100644 --- a/testing/btest/broker/remote_log_types.zeek +++ b/testing/btest/broker/remote_log_types.zeek @@ -91,6 +91,8 @@ function foo(i : count) : string return "Bar"; } +global done = F; + event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) { print "Broker::peer_added", endpoint$network$address; @@ -118,7 +120,15 @@ event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) $f=foo ]); - Broker::publish("zeek/", quit_receiver); + done = T; + } + +module Broker; + +event Broker::log_flush() + { + if ( done ) + Broker::publish("zeek/", quit_receiver); } @TEST-END-FILE diff --git a/testing/btest/language/paraglob-serialization.zeek b/testing/btest/language/paraglob-serialization.zeek index c9ffe9df4c..c5d5d516dd 100644 --- a/testing/btest/language/paraglob-serialization.zeek +++ b/testing/btest/language/paraglob-serialization.zeek @@ -88,7 +88,6 @@ event ping(msg: opaque of paraglob, n: count) print "is_remote should be T, and is", is_remote_event(); if ( n > events_to_recv ) { - print get_broker_stats(); terminate(); return; }