Annotate scheduled events with intended timestamp.

src/Event.cc

@@ -92,9 +92,9 @@ EventMgr::~EventMgr()
 	}
 
 void EventMgr::Enqueue(const EventHandlerPtr& h, Args vl, util::detail::SourceID src,
-                       analyzer::ID aid, Obj* obj)
+                       analyzer::ID aid, Obj* obj, double ts)
 	{
-	QueueEvent(new Event(h, std::move(vl), src, aid, obj));
+	QueueEvent(new Event(h, std::move(vl), src, aid, obj, ts));
 	}
 
 void EventMgr::QueueEvent(Event* event)

src/Event.h

@@ -73,10 +73,12 @@ public:
 	 * @param aid  identifies the protocol analyzer generating the event.
 	 * @param obj  an arbitrary object to use as a "cookie" or just hold a
 	 * reference to until dispatching the event.
+	 * @param ts  timestamp at which the event is intended to be executed
+	 * (defaults to current network time).
 	 */
 	void Enqueue(const EventHandlerPtr& h, zeek::Args vl,
 	             util::detail::SourceID src = util::detail::SOURCE_LOCAL, analyzer::ID aid = 0,
-	             Obj* obj = nullptr);
+	             Obj* obj = nullptr, double ts = run_state::network_time);
 
 	/**
 	 * A version of Enqueue() taking a variable number of arguments.
@@ -103,7 +105,8 @@ public:
 	analyzer::ID CurrentAnalyzer() const { return current_aid; }
 
 	// Returns the timestamp of the last raised event. The timestamp reflects the network time
-	// the event was created.
+	// the event was intended to be executed. For scheduled events, this is the time the event
+	// was scheduled to. For any other event, this is the time when the event was created.
 	double CurrentEventTime() const { return current_ts; }
 
 	int Size() const { return num_events_queued - num_events_dispatched; }

src/Expr.cc

@@ -4279,7 +4279,8 @@ ScheduleTimer::~ScheduleTimer() { }
 void ScheduleTimer::Dispatch(double /* t */, bool /* is_expire */)
 	{
 	if ( event )
-		event_mgr.Enqueue(event, std::move(args));
+		event_mgr.Enqueue(event, std::move(args), util::detail::SOURCE_LOCAL, 0, nullptr,
+		                  this->Time());
 	}
 
 ScheduleExpr::ScheduleExpr(ExprPtr arg_when, EventExprPtr arg_event)

src/zeek.bif

@@ -355,7 +355,9 @@ function set_network_time%(nt: time%): bool
 	%}
 
 ## Returns the timestamp of the last raised event. The timestamp reflects the
-## network time the event was created.
+## network time the event was intended to be executed. For scheduled events,
+## this is the time the event was scheduled for. For any other event, this is
+## the time when the event was created.
 ##
 ## Returns: The timestamp of the last raised event.
 ##

testing/btest/Baseline/language.event-ts-scheduled/out

@@ -0,0 +1,41 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
+>> Run 0 (1989-12-12-22:00:00)
+<< Run 0 (1989-12-12-22:00:00)
+[1989-12-12-23:00:00] Test was scheduled at 1989-12-12-22:00:00 for 1989-12-12-22:15:00
+[1989-12-12-23:00:00] Test was scheduled at 1989-12-12-22:00:00 for 1989-12-12-22:30:00
+>> Run 1 (1989-12-12-23:00:00)
+<< Run 1 (1989-12-12-23:00:00)
+[1989-12-13-00:00:00] Test was scheduled at 1989-12-12-23:00:00 for 1989-12-12-23:15:00
+[1989-12-13-00:00:00] Test was scheduled at 1989-12-12-23:00:00 for 1989-12-12-23:30:00
+>> Run 2 (1989-12-13-00:00:00)
+<< Run 2 (1989-12-13-00:00:00)
+[1989-12-13-01:00:00] Test was scheduled at 1989-12-13-00:00:00 for 1989-12-13-00:15:00
+[1989-12-13-01:00:00] Test was scheduled at 1989-12-13-00:00:00 for 1989-12-13-00:30:00
+>> Run 3 (1989-12-13-01:00:00)
+<< Run 3 (1989-12-13-01:00:00)
+[1989-12-13-02:00:00] Test was scheduled at 1989-12-13-01:00:00 for 1989-12-13-01:15:00
+[1989-12-13-02:00:00] Test was scheduled at 1989-12-13-01:00:00 for 1989-12-13-01:30:00
+>> Run 4 (1989-12-13-02:00:00)
+<< Run 4 (1989-12-13-02:00:00)
+[1989-12-13-03:00:00] Test was scheduled at 1989-12-13-02:00:00 for 1989-12-13-02:15:00
+[1989-12-13-03:00:00] Test was scheduled at 1989-12-13-02:00:00 for 1989-12-13-02:30:00
+>> Run 5 (1989-12-13-03:00:00)
+<< Run 5 (1989-12-13-03:00:00)
+[1989-12-13-04:00:00] Test was scheduled at 1989-12-13-03:00:00 for 1989-12-13-03:15:00
+[1989-12-13-04:00:00] Test was scheduled at 1989-12-13-03:00:00 for 1989-12-13-03:30:00
+>> Run 6 (1989-12-13-04:00:00)
+<< Run 6 (1989-12-13-04:00:00)
+[1989-12-13-05:00:00] Test was scheduled at 1989-12-13-04:00:00 for 1989-12-13-04:15:00
+[1989-12-13-05:00:00] Test was scheduled at 1989-12-13-04:00:00 for 1989-12-13-04:30:00
+>> Run 7 (1989-12-13-05:00:00)
+<< Run 7 (1989-12-13-05:00:00)
+[1989-12-13-06:00:00] Test was scheduled at 1989-12-13-05:00:00 for 1989-12-13-05:15:00
+[1989-12-13-06:00:00] Test was scheduled at 1989-12-13-05:00:00 for 1989-12-13-05:30:00
+>> Run 8 (1989-12-13-06:00:00)
+<< Run 8 (1989-12-13-06:00:00)
+[1989-12-13-07:00:00] Test was scheduled at 1989-12-13-06:00:00 for 1989-12-13-06:15:00
+[1989-12-13-07:00:00] Test was scheduled at 1989-12-13-06:00:00 for 1989-12-13-06:30:00
+>> Run 9 (1989-12-13-07:00:00)
+<< Run 9 (1989-12-13-07:00:00)
+[1989-12-13-07:00:00] Test was scheduled at 1989-12-13-07:00:00 for 1989-12-13-07:15:00
+[1989-12-13-07:00:00] Test was scheduled at 1989-12-13-07:00:00 for 1989-12-13-07:30:00

testing/btest/language/event-ts-scheduled.zeek

@@ -0,0 +1,20 @@
+# @TEST-EXEC: zeek -b -r $TRACES/ticks-dns-1hr.pcap %INPUT > out
+# @TEST-EXEC: btest-diff out
+
+global runs = 0;
+
+event test(schedule_time: time)
+	{
+	print fmt("[%D] Test was scheduled at %D for %D", network_time(),
+		schedule_time, current_event_time());
+	}
+
+event new_connection(c: connection)
+	{
+	local nt = network_time();
+	print fmt(">> Run %s (%D)", runs, nt);
+	schedule 30 mins { test(nt) };
+	schedule 15 mins { test(nt) };
+	print fmt("<< Run %s (%D)", runs, nt);
+	++runs;
+	}