Add timestamp to events.

src/Event.cc

@@ -7,7 +7,6 @@
 #include "zeek/Desc.h"
 #include "zeek/Func.h"
 #include "zeek/NetVar.h"
-#include "zeek/RunState.h"
 #include "zeek/Trigger.h"
 #include "zeek/Val.h"
 #include "zeek/iosource/Manager.h"
@@ -19,10 +18,11 @@ zeek::EventMgr zeek::event_mgr;
 namespace zeek
 	{
 
-Event::Event(EventHandlerPtr arg_handler, zeek::Args arg_args, util::detail::SourceID arg_src,
+Event::Event(const EventHandlerPtr& arg_handler, zeek::Args arg_args,
-             analyzer::ID arg_aid, Obj* arg_obj)
+             util::detail::SourceID arg_src, analyzer::ID arg_aid, Obj* arg_obj,
-	: handler(arg_handler), args(std::move(arg_args)), src(arg_src), aid(arg_aid), obj(arg_obj),
+             double arg_timestamp)
-	  next_event(nullptr)
+	: handler(arg_handler), args(std::move(arg_args)), src(arg_src), aid(arg_aid),
+	  timestamp(arg_timestamp), obj(arg_obj), next_event(nullptr)
 	{
 	if ( obj )
 		Ref(obj);
@@ -74,6 +74,7 @@ EventMgr::EventMgr()
 	head = tail = nullptr;
 	current_src = util::detail::SOURCE_LOCAL;
 	current_aid = 0;
+	current_ts = 0;
 	src_val = nullptr;
 	draining = false;
 	}
@@ -120,6 +121,8 @@ void EventMgr::QueueEvent(Event* event)
 void EventMgr::Dispatch(Event* event, bool no_remote)
 	{
 	current_src = event->Source();
+	current_aid = event->Analyzer();
+	current_ts = event->Time();
 	event->Dispatch(no_remote);
 	Unref(event);
 	}
@@ -154,6 +157,7 @@ void EventMgr::Drain()
 
 			current_src = current->Source();
 			current_aid = current->Analyzer();
+			current_ts = current->Time();
 			current->Dispatch();
 			Unref(current);
 

src/Event.h

@@ -15,14 +15,19 @@
 namespace zeek
 	{
 
+namespace run_state
+	{
+extern double network_time;
+	} // namespace run_state
+
 class EventMgr;
 
 class Event final : public Obj
 	{
 public:
-	Event(EventHandlerPtr handler, zeek::Args args,
+	Event(const EventHandlerPtr& handler, zeek::Args args,
 	      util::detail::SourceID src = util::detail::SOURCE_LOCAL, analyzer::ID aid = 0,
-	      Obj* obj = nullptr);
+	      Obj* obj = nullptr, double timestamp = run_state::network_time);
 
 	void SetNext(Event* n) { next_event = n; }
 	Event* NextEvent() const { return next_event; }
@@ -31,6 +36,7 @@ public:
 	analyzer::ID Analyzer() const { return aid; }
 	EventHandlerPtr Handler() const { return handler; }
 	const zeek::Args& Args() const { return args; }
+	double Time() const { return timestamp; }
 
 	void Describe(ODesc* d) const override;
 
@@ -45,6 +51,7 @@ protected:
 	zeek::Args args;
 	util::detail::SourceID src;
 	analyzer::ID aid;
+	double timestamp;
 	Obj* obj;
 	Event* next_event;
 	};
@@ -95,6 +102,10 @@ public:
 	// non-analyzer event.
 	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.
+	double CurrentEventTime() const { return current_ts; }
+
 	int Size() const { return num_events_queued - num_events_dispatched; }
 
 	void Describe(ODesc* d) const override;
@@ -114,6 +125,7 @@ protected:
 	Event* tail;
 	util::detail::SourceID current_src;
 	analyzer::ID current_aid;
+	double current_ts;
 	RecordVal* src_val;
 	bool draining;
 	detail::Flare queue_flare;

src/zeek.bif

@@ -354,6 +354,17 @@ function set_network_time%(nt: time%): bool
 	return zeek::val_mgr->True();
 	%}
 
+## Returns the timestamp of the last raised event. The timestamp reflects the
+## network time the event was created.
+##
+## Returns: The timestamp of the last raised event.
+##
+## .. zeek:see:: current_time set_network_time
+function current_event_time%(%): time
+	%{
+	return zeek::make_intrusive<zeek::TimeVal>(zeek::event_mgr.CurrentEventTime());
+	%}
+
 ## Returns a system environment variable.
 ##
 ## var: The name of the variable whose value to request.

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

@@ -0,0 +1,51 @@
+### 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):
+[1989-12-12-22:00:00] Test 4 was scheduled at 1989-12-12-22:00:00
+[1989-12-12-22:00:00] Test 3 was scheduled at 1989-12-12-22:00:00
+[1989-12-12-22:00:00] Test 2 was scheduled at 1989-12-12-22:00:00
+[1989-12-12-22:00:01] Test 1 was scheduled at 1989-12-12-22:00:00
+>> Run 1 (1989-12-12-22:00:01):
+[1989-12-12-22:00:01] Test 4 was scheduled at 1989-12-12-22:00:01
+[1989-12-12-22:00:01] Test 3 was scheduled at 1989-12-12-22:00:01
+[1989-12-12-22:00:01] Test 2 was scheduled at 1989-12-12-22:00:01
+[1989-12-12-22:00:02] Test 1 was scheduled at 1989-12-12-22:00:01
+>> Run 2 (1989-12-12-22:00:02):
+[1989-12-12-22:00:02] Test 4 was scheduled at 1989-12-12-22:00:02
+[1989-12-12-22:00:02] Test 3 was scheduled at 1989-12-12-22:00:02
+[1989-12-12-22:00:02] Test 2 was scheduled at 1989-12-12-22:00:02
+[1989-12-12-22:00:03] Test 1 was scheduled at 1989-12-12-22:00:02
+>> Run 3 (1989-12-12-22:00:03):
+[1989-12-12-22:00:03] Test 4 was scheduled at 1989-12-12-22:00:03
+[1989-12-12-22:00:03] Test 3 was scheduled at 1989-12-12-22:00:03
+[1989-12-12-22:00:03] Test 2 was scheduled at 1989-12-12-22:00:03
+[1989-12-12-22:00:04] Test 1 was scheduled at 1989-12-12-22:00:03
+>> Run 4 (1989-12-12-22:00:04):
+[1989-12-12-22:00:04] Test 4 was scheduled at 1989-12-12-22:00:04
+[1989-12-12-22:00:04] Test 3 was scheduled at 1989-12-12-22:00:04
+[1989-12-12-22:00:04] Test 2 was scheduled at 1989-12-12-22:00:04
+[1989-12-12-22:00:05] Test 1 was scheduled at 1989-12-12-22:00:04
+>> Run 5 (1989-12-12-22:00:05):
+[1989-12-12-22:00:05] Test 4 was scheduled at 1989-12-12-22:00:05
+[1989-12-12-22:00:05] Test 3 was scheduled at 1989-12-12-22:00:05
+[1989-12-12-22:00:05] Test 2 was scheduled at 1989-12-12-22:00:05
+[1989-12-12-22:00:06] Test 1 was scheduled at 1989-12-12-22:00:05
+>> Run 6 (1989-12-12-22:00:06):
+[1989-12-12-22:00:06] Test 4 was scheduled at 1989-12-12-22:00:06
+[1989-12-12-22:00:06] Test 3 was scheduled at 1989-12-12-22:00:06
+[1989-12-12-22:00:06] Test 2 was scheduled at 1989-12-12-22:00:06
+[1989-12-12-22:00:07] Test 1 was scheduled at 1989-12-12-22:00:06
+>> Run 7 (1989-12-12-22:00:07):
+[1989-12-12-22:00:07] Test 4 was scheduled at 1989-12-12-22:00:07
+[1989-12-12-22:00:07] Test 3 was scheduled at 1989-12-12-22:00:07
+[1989-12-12-22:00:07] Test 2 was scheduled at 1989-12-12-22:00:07
+[1989-12-12-22:00:08] Test 1 was scheduled at 1989-12-12-22:00:07
+>> Run 8 (1989-12-12-22:00:08):
+[1989-12-12-22:00:08] Test 4 was scheduled at 1989-12-12-22:00:08
+[1989-12-12-22:00:08] Test 3 was scheduled at 1989-12-12-22:00:08
+[1989-12-12-22:00:08] Test 2 was scheduled at 1989-12-12-22:00:08
+[1989-12-12-22:00:09] Test 1 was scheduled at 1989-12-12-22:00:08
+>> Run 9 (1989-12-12-22:00:09):
+[1989-12-12-22:00:09] Test 4 was scheduled at 1989-12-12-22:00:09
+[1989-12-12-22:00:09] Test 3 was scheduled at 1989-12-12-22:00:09
+[1989-12-12-22:00:09] Test 2 was scheduled at 1989-12-12-22:00:09
+[1989-12-12-22:00:09] Test 1 was scheduled at 1989-12-12-22:00:09

testing/btest/language/event-ts.zeek

@@ -0,0 +1,28 @@
+# @TEST-EXEC: zeek -b -r $TRACES/ticks-dns.pcap %INPUT > out
+# @TEST-EXEC: btest-diff out
+
+# Note: We use a PCAP with DNS queries only so that we have a single packet per
+# time step. Thus the run loop will be executed only once per time step.
+
+global runs = -1;
+
+event test(depth: count)
+	{
+	if ( depth == 0 )
+		return;
+
+	print fmt("[%D] Test %s was scheduled at %D", network_time(), depth, current_event_time());
+	event test(--depth);
+	}
+
+event new_connection(c: connection)
+	{
+	print fmt(">> Run %s (%D):", ++runs, network_time());
+	# Descend into recursion to enqueue events until we add an event that will
+	# be handled in the next run loop iteration, i.e. at a different timestamp
+	# than it was enqueued. Use four levels of recursion as every drain of the
+	# event queue handles two layers and the event queue is drained two times.
+	# First after processing a packet and second in the run loop. Finally, we
+	# expect an event so that network_time() > current_event_time().
+	event test(4);
+	}