broker/Publish: Use event time instead of network time

Discussed with @J-Gras, calling Broker::publish() within a scheduled
should use the "intended timestamp" implicitly.

This is subtle, but supposedly more expected when running
a pcap replay cluster.

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
 ---------------------
 

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
+    // explicitly triggered. Hence, the timestamp is set to the current event's time. This
-    // means that timestamping cannot be manipulated from script-land for now.
+    // 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);
+    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) {

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)

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)

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

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();
     }