logging/Manager: Implement DelayTokenType as an actual opaque

With a bit of tweaking in the JavaScript plugin to support opaque types, this
will allow the delay functionality to work there, too.

Making the LogDelayToken an actual opaque seems reasonable, too. It's not
supposed to be user inspected.

scripts/base/frameworks/logging/main.zeek

@@ -636,7 +636,7 @@ export {
 	## Type of the opaque value returned by :zeek:see:`Log::delay`. These
 	## values can be passed to :zeek:see:`Log::delay_finish` to release a
 	## delayed write operation.
-	type DelayToken: any;
+	type DelayToken: opaque of LogDelayToken;
 
 	## Represents a post delay callback that simply returns T. This is used
 	## as a default value for :zeek:see:`Log::delay` and ignored internally.

src/logging/Manager.cc

@@ -13,6 +13,7 @@
 #include "zeek/Func.h"
 #include "zeek/IntrusivePtr.h"
 #include "zeek/NetVar.h"
+#include "zeek/OpaqueVal.h"
 #include "zeek/RunState.h"
 #include "zeek/Type.h"
 #include "zeek/broker/Manager.h"
@@ -28,6 +29,12 @@
 
 using namespace std;
 
+namespace zeek::detail {
+
+extern zeek::OpaqueTypePtr log_delay_token_type;
+
+};
+
 namespace zeek::logging {
 
 namespace detail {
@@ -37,10 +44,43 @@ class DelayInfo;
 
 using DelayInfoPtr = std::shared_ptr<DelayInfo>;
 
-constexpr zeek::TypeTag ZeekDelayTokenTypeTag = TYPE_COUNT;
+class LogDelayTokenVal : public OpaqueVal {
+public:
+    explicit LogDelayTokenVal(DelayTokenType token) : OpaqueVal(zeek::detail::log_delay_token_type), token(token) {}
+    virtual ~LogDelayTokenVal() = default;
+
+    ValPtr DoClone(CloneState* state) override;
+
+    DelayTokenType Token() { return token; }
+
+protected:
+    explicit LogDelayTokenVal() : LogDelayTokenVal(0) {}
+    DECLARE_OPAQUE_VALUE(LogDelayTokenVal)
+
+private:
+    DelayTokenType token;
+};
+
+ValPtr LogDelayTokenVal::DoClone(CloneState* state) {
+    return state->NewClone(this, make_intrusive<LogDelayTokenVal>(Token()));
+}
+
+// Delay tokens are only valid on the same worker.
+broker::expected<broker::data> LogDelayTokenVal::DoSerialize() const {
+    return broker::make_error(broker::ec::invalid_data, "cannot serialize delay tokens");
+}
+
+bool LogDelayTokenVal::DoUnserialize(const broker::data&) { return false; }
+
+IMPLEMENT_OPAQUE_VALUE(LogDelayTokenVal)
+
 DelayTokenType to_internal_delay_token(const ValPtr& val) {
-    assert(val->GetType()->Tag() == ZeekDelayTokenTypeTag);
-    return val->AsCount();
+    assert(val->GetType()->Tag() == TYPE_OPAQUE);
+    if ( auto* optr = dynamic_cast<LogDelayTokenVal*>(val.get()) )
+        return optr->Token();
+
+    zeek::reporter->Error("dynamic_cast of LogDelayToken failed: wrong opaque type provided?");
+    return 0;
 }
 
 using DelayWriteMap = std::map<WriteContext, DelayInfoPtr>;
@@ -1151,12 +1191,12 @@ bool Manager::WriteToFilters(const Manager::Stream* stream, zeek::RecordValPtr c
 ValPtr Manager::Delay(const EnumValPtr& id, const RecordValPtr record, FuncPtr post_delay_cb) {
     if ( active_writes.size() == 0 ) {
         reporter->Error("invalid Log::delay() call: no active write context available");
-        return zeek::val_mgr->Count(0);
+        return make_intrusive<detail::LogDelayTokenVal>();
     }
     const auto& active_write_ctx = active_writes.back();
     if ( active_write_ctx.id != id || active_write_ctx.record != record ) {
         reporter->Error("invalid Log::delay() call: active write mismatch");
-        return zeek::val_mgr->Count(0);
+        return make_intrusive<detail::LogDelayTokenVal>();
     }
 
     DBG_LOG(DBG_LOGGING, "Delay() for %p RefCnt=%d", record.get(), record->RefCnt());
@@ -1175,7 +1215,7 @@ ValPtr Manager::Delay(const EnumValPtr& id, const RecordValPtr record, FuncPtr p
         // This is the first time this Log::write() is delayed, allocate a
         // new token an return it to script land.
         detail::DelayTokenType token = ++last_delay_token;
-        token_val = zeek::val_mgr->Count(token);
+        token_val = zeek::make_intrusive<detail::LogDelayTokenVal>(token);
         double expire_time = run_state::network_time + stream->max_delay_interval;
         auto new_delay_info = std::make_shared<detail::DelayInfo>(active_write_ctx, token_val, expire_time);
         if ( post_delay_cb )
@@ -1201,12 +1241,22 @@ bool Manager::DelayFinish(const EnumValPtr& id, const RecordValPtr& record, cons
     if ( ! stream )
         return false;
 
-    if ( token_val->GetType()->Tag() != detail::ZeekDelayTokenTypeTag ) {
+    if ( token_val->GetType()->Tag() != TYPE_OPAQUE ) {
         reporter->Error("invalid delay token type %s", zeek::type_name(token_val->GetType()->Tag()));
         return false;
     }
 
+    const auto& token_type_name = token_val->GetType<zeek::OpaqueType>()->Name();
+    if ( token_type_name != std::string_view{"LogDelayToken"} ) {
+        reporter->Error("invalid Log::delay_finish() call: wrong opaque token type: %s", token_type_name.c_str());
+        return false;
+    }
+
     detail::DelayTokenType token = detail::to_internal_delay_token(token_val);
+    if ( token == 0 ) {
+        reporter->Error("invalid Log::delay_finish() call: invalid token provided");
+        return false;
+    }
 
     DBG_LOG(DBG_LOGGING, "DelayFinish() for %p RefCnt=%d token=%ld", record.get(), record->RefCnt(), token);
     const auto& it = stream->delay_tokens.find(token);

src/zeek-setup.cc

@@ -244,6 +244,8 @@ const char* zeek_version() {
 
 namespace detail {
 
+zeek::OpaqueTypePtr log_delay_token_type;
+
 static std::vector<const char*> to_cargs(const std::vector<std::string>& args) {
     std::vector<const char*> rval;
     rval.reserve(args.size());
@@ -719,6 +721,7 @@ SetupResult setup(int argc, char** argv, Options* zopts) {
     int_histogram_metric_family_type = make_intrusive<OpaqueType>("int_histogram_metric_family");
     dbl_histogram_metric_type = make_intrusive<OpaqueType>("dbl_histogram_metric");
     dbl_histogram_metric_family_type = make_intrusive<OpaqueType>("dbl_histogram_metric_family");
+    log_delay_token_type = make_intrusive<OpaqueType>("LogDelayToken");
 
     // After spinning up Broker, we have background threads running now. If
     // we exit early, we need to shut down at least Broker to get a clean

testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stderr

@@ -1,2 +1 @@
 ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
-1362692527.080972 error: invalid delay token type string

testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stdout

@@ -0,0 +1,21 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
+1362692526.869344, new_connection, CHhAvVGS1DHFjwGM9
+1362692526.869344, log_stream_policy, LOG, CHhAvVGS1DHFjwGM9
+token, <opaque of LogDelayTokenVal>
+to_json(token), {"opaque_type":"LogDelayTokenVal"}
+1362692526.869344, new_packet, 1
+1362692526.939084, new_packet, 2
+1362692526.939378, new_packet, 3
+1362692526.939527, new_packet, 4
+1362692527.008509, new_packet, 5
+1362692527.009512, new_packet, 6
+1362692527.009721, new_packet, 7
+1362692527.009765, new_packet, 8
+1362692527.009775, new_packet, 9
+1362692527.009855, new_packet, 10
+1362692527.009887, new_packet, 11
+1362692527.011846, new_packet, 12
+1362692527.080828, log_policy, CHhAvVGS1DHFjwGM9
+1362692527.080828, new_packet, 13
+1362692527.080972, new_packet, 14
+1362692527.080972, Pcap::file_done

testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/test.cut

@@ -1,2 +1,3 @@
 ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
-1362692527.080972 error: delay reference underflow for token=1
+ts|write_ts|uid|msg
+1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value

testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-4/.stderr

@@ -1,2 +1,2 @@
 ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
-1362692527.080972 error: non-existing log record for token=42 0x<...>
+1362692527.080972 error: record mismatch token=1 0x<...> and 0x<...>

testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr

@@ -1,2 +1,2 @@
 ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
-1362692527.080972 error: record mismatch token=1 0x<...> and 0x<...>
+1362692527.080972 error: delay reference underflow for token=1

testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-3/.stderr

@@ -0,0 +1,4 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
+error in <...>/main.zeek, line 639 and <...>/static-errors.zeek, line 8: type clash (Log::DelayToken and 42)
+error in <...>/static-errors.zeek, line 8 and <...>/main.zeek, line 639: type mismatch (42 and Log::DelayToken)
+error in <...>/static-errors.zeek, line 8: argument type mismatch in function call (Log::delay_finish(id, to_any_coercerec, 42))

testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-4/.stderr

@@ -0,0 +1,4 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
+error in <...>/main.zeek, line 639 and <...>/static-errors.zeek, line 8: arithmetic mixed with non-arithmetic (Log::DelayToken and 42)
+error in <...>/static-errors.zeek, line 8 and <...>/main.zeek, line 639: type mismatch (42 and Log::DelayToken)
+error in <...>/static-errors.zeek, line 8: argument type mismatch in function call (Log::delay_finish(id, to_any_coercerec, 42))

testing/btest/scripts/base/frameworks/logging/delay/basic.zeek

@@ -106,3 +106,17 @@ hook Log::log_stream_policy(rec: Info, id: Log::ID)
 	Log::delay(id, rec);
 	Log::delay(id, rec);
 	}
+
+@TEST-START-NEXT
+# Delay twice, never release, print the token value and its JSON representation.
+hook Log::log_stream_policy(rec: Info, id: Log::ID)
+	{
+	if ( id != LOG )
+		return;
+
+	print network_time(), "log_stream_policy", id, rec$uid;
+
+	local token = Log::delay(id, rec);
+	print "token", token;
+	print "to_json(token)", to_json(token);
+	}

testing/btest/scripts/base/frameworks/logging/delay/errors.zeek

@@ -33,16 +33,6 @@ hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
 @TEST-START-NEXT
 @load base/protocols/conn
 
-hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
-	{
-	# Wrong token for delay_finish()
-	local token = Log::delay(id, rec);
-	Log::delay_finish(id, rec, 42);
-	}
-
-@TEST-START-NEXT
-@load base/protocols/conn
-
 hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
 	{
 	# Wrong record for delay_finish()
@@ -53,16 +43,6 @@ hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
 @TEST-START-NEXT
 @load base/protocols/conn
 
-hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
-	{
-	# Wrong token type for delay_finish()
-	local token = Log::delay(id, rec);
-	Log::delay_finish(id, rec, "42");
-	}
-
-@TEST-START-NEXT
-@load base/protocols/conn
-
 hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
 	{
 	# Delay underflow.

testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek

@@ -31,3 +31,25 @@ hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
 	{
 	Log::delay(id, rec, post_delay_cb);
 	}
+
+@TEST-START-NEXT
+# Bad token type 1
+@load base/protocols/conn
+
+hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
+	{
+	# Wrong token type for delay_finish()
+	local token = Log::delay(id, rec);
+	Log::delay_finish(id, rec, "42");
+	}
+
+@TEST-START-NEXT
+# Bad token type 2
+@load base/protocols/conn
+
+hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID)
+	{
+	# Wrong token type for delay_finish()
+	local token = Log::delay(id, rec);
+	Log::delay_finish(id, rec, 42);
+	}