diff --git a/NEWS b/NEWS index c4b4e7dc00..f985ea09d3 100644 --- a/NEWS +++ b/NEWS @@ -103,6 +103,11 @@ Changed Functionality of a node are scraped via the Prometheus HTTP endpoint, or one of the collect methods is invoked from Zeek script. +* Calling ``Broker::publish()`` now uses the event time of the currently + executing event as network time metadata attached to the remote event. + Previously, ``network_time()`` was used. This matters if ``Broker::publish()`` + is called within scheduled events or called within remote events. + Removed Functionality --------------------- diff --git a/src/broker/Manager.cc b/src/broker/Manager.cc index 270f57c4c1..7b6178187b 100644 --- a/src/broker/Manager.cc +++ b/src/broker/Manager.cc @@ -12,6 +12,7 @@ #include "zeek/DebugLogger.h" #include "zeek/Desc.h" +#include "zeek/Event.h" #include "zeek/Func.h" #include "zeek/IntrusivePtr.h" #include "zeek/Reporter.h" @@ -580,9 +581,10 @@ bool Manager::PublishEvent(string topic, RecordVal* args) { } // At this point we come from script-land. This means that publishing of the event was - // explicitly triggered. Hence, the timestamp is set to the current network time. This also - // means that timestamping cannot be manipulated from script-land for now. - return PublishEvent(std::move(topic), event_name, std::move(xs), run_state::network_time); + // explicitly triggered. Hence, the timestamp is set to the current event's time. This + // also means that timestamping cannot be manipulated from script-land for now. + auto ts = event_mgr.CurrentEventTime(); + return PublishEvent(std::move(topic), event_name, std::move(xs), ts); } bool Manager::PublishIdentifier(std::string topic, std::string id) { diff --git a/testing/btest/Baseline/broker.remote_event_schedule_ts/recv.recv.out b/testing/btest/Baseline/broker.remote_event_schedule_ts/recv.recv.out new file mode 100644 index 0000000000..60cebba91f --- /dev/null +++ b/testing/btest/Baseline/broker.remote_event_schedule_ts/recv.recv.out @@ -0,0 +1,11 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +receiver added peer: endpoint=127.0.0.1 msg=handshake successful +receiver got ping: my-message-a intended for 1989-12-12-22:00:00 published at 1989-12-12-22:00:00 stamped to 1989-12-12-22:00:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-b intended for 1989-12-12-22:15:00 published at 1989-12-12-23:00:00 stamped to 1989-12-12-22:15:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-c intended for 1989-12-12-22:30:00 published at 1989-12-12-23:00:00 stamped to 1989-12-12-22:30:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-a intended for 1989-12-12-23:00:00 published at 1989-12-12-23:00:00 stamped to 1989-12-12-23:00:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-b intended for 1989-12-12-23:15:00 published at 1989-12-13-00:00:00 stamped to 1989-12-12-23:15:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-c intended for 1989-12-12-23:30:00 published at 1989-12-13-00:00:00 stamped to 1989-12-12-23:30:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-a intended for 1989-12-13-00:00:00 published at 1989-12-13-00:00:00 stamped to 1989-12-13-00:00:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-b intended for 1989-12-13-00:15:00 published at 1989-12-13-01:00:00 stamped to 1989-12-13-00:15:00 (is_remote = T, intended_equals_stamped=T) +receiver got ping: my-message-c intended for 1989-12-13-00:30:00 published at 1989-12-13-01:00:00 stamped to 1989-12-13-00:30:00 (is_remote = T, intended_equals_stamped=T) diff --git a/testing/btest/Baseline/broker.remote_event_schedule_ts/send.send.out b/testing/btest/Baseline/broker.remote_event_schedule_ts/send.send.out new file mode 100644 index 0000000000..68fdce6f5b --- /dev/null +++ b/testing/btest/Baseline/broker.remote_event_schedule_ts/send.send.out @@ -0,0 +1,43 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +sender added peer: endpoint=127.0.0.1 msg=handshake successful +>> Run 1 (1989-12-12-22:00:00) +>>> Publish my-message-a intended for 1989-12-12-22:00:00 (current_event_time=1989-12-12-22:00:00, network_time=1989-12-12-22:00:00) +>>> Publish my-message-b intended for 1989-12-12-22:15:00 (current_event_time=1989-12-12-22:15:00, network_time=1989-12-12-23:00:00) +>>> Publish my-message-c intended for 1989-12-12-22:30:00 (current_event_time=1989-12-12-22:30:00, network_time=1989-12-12-23:00:00) +>> Run 2 (1989-12-12-23:00:00) +>>> Publish my-message-a intended for 1989-12-12-23:00:00 (current_event_time=1989-12-12-23:00:00, network_time=1989-12-12-23:00:00) +>>> Publish my-message-b intended for 1989-12-12-23:15:00 (current_event_time=1989-12-12-23:15:00, network_time=1989-12-13-00:00:00) +>>> Publish my-message-c intended for 1989-12-12-23:30:00 (current_event_time=1989-12-12-23:30:00, network_time=1989-12-13-00:00:00) +>> Run 3 (1989-12-13-00:00:00) +>>> Publish my-message-a intended for 1989-12-13-00:00:00 (current_event_time=1989-12-13-00:00:00, network_time=1989-12-13-00:00:00) +>>> Publish my-message-b intended for 1989-12-13-00:15:00 (current_event_time=1989-12-13-00:15:00, network_time=1989-12-13-01:00:00) +>>> Publish my-message-c intended for 1989-12-13-00:30:00 (current_event_time=1989-12-13-00:30:00, network_time=1989-12-13-01:00:00) +>> Run 4 (1989-12-13-01:00:00) +>>> Publish my-message-a intended for 1989-12-13-01:00:00 (current_event_time=1989-12-13-01:00:00, network_time=1989-12-13-01:00:00) +>>> Publish my-message-b intended for 1989-12-13-01:15:00 (current_event_time=1989-12-13-01:15:00, network_time=1989-12-13-02:00:00) +>>> Publish my-message-c intended for 1989-12-13-01:30:00 (current_event_time=1989-12-13-01:30:00, network_time=1989-12-13-02:00:00) +>> Run 5 (1989-12-13-02:00:00) +>>> Publish my-message-a intended for 1989-12-13-02:00:00 (current_event_time=1989-12-13-02:00:00, network_time=1989-12-13-02:00:00) +>>> Publish my-message-b intended for 1989-12-13-02:15:00 (current_event_time=1989-12-13-02:15:00, network_time=1989-12-13-03:00:00) +>>> Publish my-message-c intended for 1989-12-13-02:30:00 (current_event_time=1989-12-13-02:30:00, network_time=1989-12-13-03:00:00) +>> Run 6 (1989-12-13-03:00:00) +>>> Publish my-message-a intended for 1989-12-13-03:00:00 (current_event_time=1989-12-13-03:00:00, network_time=1989-12-13-03:00:00) +>>> Publish my-message-b intended for 1989-12-13-03:15:00 (current_event_time=1989-12-13-03:15:00, network_time=1989-12-13-04:00:00) +>>> Publish my-message-c intended for 1989-12-13-03:30:00 (current_event_time=1989-12-13-03:30:00, network_time=1989-12-13-04:00:00) +>> Run 7 (1989-12-13-04:00:00) +>>> Publish my-message-a intended for 1989-12-13-04:00:00 (current_event_time=1989-12-13-04:00:00, network_time=1989-12-13-04:00:00) +>>> Publish my-message-b intended for 1989-12-13-04:15:00 (current_event_time=1989-12-13-04:15:00, network_time=1989-12-13-05:00:00) +>>> Publish my-message-c intended for 1989-12-13-04:30:00 (current_event_time=1989-12-13-04:30:00, network_time=1989-12-13-05:00:00) +>> Run 8 (1989-12-13-05:00:00) +>>> Publish my-message-a intended for 1989-12-13-05:00:00 (current_event_time=1989-12-13-05:00:00, network_time=1989-12-13-05:00:00) +>>> Publish my-message-b intended for 1989-12-13-05:15:00 (current_event_time=1989-12-13-05:15:00, network_time=1989-12-13-06:00:00) +>>> Publish my-message-c intended for 1989-12-13-05:30:00 (current_event_time=1989-12-13-05:30:00, network_time=1989-12-13-06:00:00) +>> Run 9 (1989-12-13-06:00:00) +>>> Publish my-message-a intended for 1989-12-13-06:00:00 (current_event_time=1989-12-13-06:00:00, network_time=1989-12-13-06:00:00) +>>> Publish my-message-b intended for 1989-12-13-06:15:00 (current_event_time=1989-12-13-06:15:00, network_time=1989-12-13-07:00:00) +>>> Publish my-message-c intended for 1989-12-13-06:30:00 (current_event_time=1989-12-13-06:30:00, network_time=1989-12-13-07:00:00) +>> Run 10 (1989-12-13-07:00:00) +>>> Publish my-message-a intended for 1989-12-13-07:00:00 (current_event_time=1989-12-13-07:00:00, network_time=1989-12-13-07:00:00) +sender lost peer: endpoint=127.0.0.1 msg=lost connection to remote peer +>>> Publish my-message-b intended for 1989-12-13-07:15:00 (current_event_time=1989-12-13-07:15:00, network_time=1989-12-13-07:00:00) +>>> Publish my-message-c intended for 1989-12-13-07:30:00 (current_event_time=1989-12-13-07:30:00, network_time=1989-12-13-07:00:00) diff --git a/testing/btest/broker/remote_event_schedule_ts.zeek b/testing/btest/broker/remote_event_schedule_ts.zeek new file mode 100644 index 0000000000..fe90f2b0cb --- /dev/null +++ b/testing/btest/broker/remote_event_schedule_ts.zeek @@ -0,0 +1,92 @@ +# @TEST-DOC: Broker::publish() within a schedule event uses the intended timestamp, not the current network_time() +# +# Not compatible with -O C++ testing since includes two distinct scripts. +# @TEST-REQUIRES: test "${ZEEK_USE_CPP}" != "1" +# +# @TEST-GROUP: broker +# +# @TEST-PORT: BROKER_PORT +# +# @TEST-EXEC: btest-bg-run recv "zeek -b ../recv.zeek >recv.out" +# @TEST-EXEC: btest-bg-run send "zeek -b -r $TRACES/ticks-dns-1hr.pcap ../send.zeek >send.out" +# +# @TEST-EXEC: btest-bg-wait 5 +# @TEST-EXEC: btest-diff recv/recv.out +# @TEST-EXEC: btest-diff send/send.out + +# @TEST-START-FILE send.zeek + +redef exit_only_after_terminate = T; + +global runs = 0; +global ping: event(msg: string, intended_ts: time, publish_ts: time); + +event zeek_init() + { + suspend_processing(); + Broker::subscribe("zeek/event/my_topic"); + Broker::peer("127.0.0.1", to_port(getenv("BROKER_PORT"))); + } + +event send_ping(msg: string, intended_ts: time) + { + print fmt(">>> Publish %s intended for %D (current_event_time=%D, network_time=%D)", + msg, intended_ts, current_event_time(), network_time()); + Broker::publish("zeek/event/my_topic", ping, msg, intended_ts, network_time()); + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + print fmt("sender added peer: endpoint=%s msg=%s", + endpoint$network$address, msg); + continue_processing(); + } + +event new_connection(c: connection) + { + print fmt(">> Run %s (%D)", ++runs, network_time()); + + event send_ping("my-message-a", network_time()); + schedule 30 mins { send_ping("my-message-c", network_time() + 30 mins) }; + schedule 15 mins { send_ping("my-message-b", network_time() + 15 mins) }; + } + +event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) + { + print fmt("sender lost peer: endpoint=%s msg=%s", + endpoint$network$address, msg); + terminate(); + } + +# @TEST-END-FILE + + +# @TEST-START-FILE recv.zeek + +redef exit_only_after_terminate = T; + +global msg_count = 0; + +event zeek_init() + { + Broker::subscribe("zeek/event/my_topic"); + Broker::listen("127.0.0.1", to_port(getenv("BROKER_PORT"))); + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + print fmt("receiver added peer: endpoint=%s msg=%s", endpoint$network$address, msg); + } + +event ping(msg: string, intended_ts: time, publish_ts: time) &is_used + { + if ( ++msg_count >= 10 ) + { + terminate(); + return; + } + + print fmt("receiver got ping: %s intended for %D published at %D stamped to %D (is_remote = %s, intended_equals_stamped=%s)", + msg, intended_ts, publish_ts, current_event_time(), is_remote_event(), intended_ts == current_event_time()); + } +# @TEST-END-FILE diff --git a/testing/btest/broker/web-socket-events-metadata.zeek b/testing/btest/broker/web-socket-events-metadata.zeek index 52b1c8ab3b..33477b4e7e 100644 --- a/testing/btest/broker/web-socket-events-metadata.zeek +++ b/testing/btest/broker/web-socket-events-metadata.zeek @@ -29,7 +29,7 @@ event zeek_init() Broker::listen_websocket("127.0.0.1", to_port(getenv("BROKER_PORT"))); } -function send_event() +event send_event() { ++event_count; local e = Broker::make_event(ping, "my-message", event_count); @@ -39,7 +39,7 @@ function send_event() event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) { print fmt("sender added peer: endpoint=%s msg=%s", endpoint$network$address, msg); - send_event(); + event send_event(); } event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) @@ -53,7 +53,11 @@ event pong(msg: string, n: count) &is_used print fmt("sender got pong: %s, %s network_time=%s current_event_time=%s", msg, n, network_time(), current_event_time()); set_network_time(network_time() + 10sec); - send_event(); + + # pong is a remote event and a Broker::publish() would take + # current_event_time() as the network time for Broker::publish(), + # prevent this by queuing a new send_event(). + event send_event(); }