diff --git a/scripts/base/frameworks/logging/main.zeek b/scripts/base/frameworks/logging/main.zeek index 98f3c4b20a..9db95e4e6e 100644 --- a/scripts/base/frameworks/logging/main.zeek +++ b/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. diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index ee8830296b..66734f16ed 100644 --- a/src/logging/Manager.cc +++ b/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; -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(Token())); +} + +// Delay tokens are only valid on the same worker. +broker::expected 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(val.get()) ) + return optr->Token(); + + zeek::reporter->Error("dynamic_cast of LogDelayToken failed: wrong opaque type provided?"); + return 0; } using DelayWriteMap = std::map; @@ -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(); } 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(); } 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(token); double expire_time = run_state::network_time + stream->max_delay_interval; auto new_delay_info = std::make_shared(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()->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); diff --git a/src/zeek-setup.cc b/src/zeek-setup.cc index 8fa92d4983..afe5cec284 100644 --- a/src/zeek-setup.cc +++ b/src/zeek-setup.cc @@ -244,6 +244,8 @@ const char* zeek_version() { namespace detail { +zeek::OpaqueTypePtr log_delay_token_type; + static std::vector to_cargs(const std::vector& args) { std::vector rval; rval.reserve(args.size()); @@ -719,6 +721,7 @@ SetupResult setup(int argc, char** argv, Options* zopts) { int_histogram_metric_family_type = make_intrusive("int_histogram_metric_family"); dbl_histogram_metric_type = make_intrusive("dbl_histogram_metric"); dbl_histogram_metric_family_type = make_intrusive("dbl_histogram_metric_family"); + log_delay_token_type = make_intrusive("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 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stderr similarity index 66% rename from testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr rename to testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stderr index f5d890f163..49d861c74c 100644 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr +++ b/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 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stdout new file mode 100644 index 0000000000..53a917ca3d --- /dev/null +++ b/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, +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 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/test.cut similarity index 56% rename from testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr rename to testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/test.cut index 23205c7478..7ca18d40f9 100644 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr +++ b/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 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-4/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-4/.stderr index 643fc6706d..0ff66ed885 100644 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-4/.stderr +++ b/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<...> diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr index 0ff66ed885..23205c7478 100644 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr +++ b/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 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-3/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-3/.stderr new file mode 100644 index 0000000000..d602ff9d4a --- /dev/null +++ b/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)) diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-4/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-4/.stderr new file mode 100644 index 0000000000..e635f77752 --- /dev/null +++ b/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)) diff --git a/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek b/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek index 9c83f4bdc4..1855e77e02 100644 --- a/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek +++ b/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); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek b/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek index 1e713bb761..113c4b992c 100644 --- a/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek +++ b/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. diff --git a/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek b/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek index 40281ac26f..60ef1ed1dc 100644 --- a/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek +++ b/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); + }