From f0e67022fd9d4e2d1b22f802a40f4353cc4e47cc Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Sun, 12 Nov 2023 16:03:23 +0100 Subject: [PATCH] logging: Introduce Log::delay() and Log::delay_finish() This is a verbose, opinionated and fairly restrictive version of the log delay idea. Main drivers are explicitly, foot-gun-avoidance and implementation simplicity. Calling the new Log::delay() function is only allowed within the execution of a Log::log_stream_policy() hook for the currently active log write. Conceptually, the delay is placed between the execution of the global stream policy hook and the individual filter policy hooks. A post delay callback can be registered with every Log::delay() invocation. Post delay callbacks can (1) modify a log record as they see fit, (2) veto the forwarding of the log record to the log filters and (3) extend the delay duration by calling Log::delay() again. The last point allows to delay a record by an indefinite amount of time, rather than a fixed maximum amount. This should be rare and is therefore explicit. Log::delay() increases an internal reference count and returns an opaque token value to be passed to Log::delay_finish() to release a delay reference. Once all references are released, the record is forwarded to all filters attached to a stream when the delay completes. This functionality separates Log::log_stream_policy() and individual filter policy hooks. One consequence is that a common use-case of filter policy hooks, removing unproductive log records, may run after a record was delayed. Users can lift their filtering logic to the stream level (or replicate the condition before the delay decision). The main motivation here is that deciding on a stream-level delay in per-filter hooks is too late. Attaching multiple filters to a stream can additionally result in hard to understand behavior. On the flip side, filter policy hooks are guaranteed to run after the delay and can be used for further mangling or filtering of a delayed record. --- scripts/base/frameworks/logging/main.zeek | 188 +++++++ src/logging/Manager.cc | 477 +++++++++++++++++- src/logging/Manager.h | 90 ++++ src/logging/logging.bif | 75 +++ testing/btest/Baseline/plugins.hooks/output | 216 +++++--- .../.stderr | 1 + .../.stdout | 19 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 19 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 19 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 19 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 21 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 21 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 22 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 22 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 20 + .../test.cut | 1 + .../.stderr | 1 + .../.stdout | 20 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 22 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 22 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 21 + .../test.cut | 3 + .../.stderr | 2 + .../.stderr | 2 + .../.stderr | 2 + .../.stderr | 2 + .../.stderr | 2 + .../.stderr | 2 + .../.stderr | 2 + .../.stderr | 1 + .../.stdout | 5 + .../conn.cut | 3 + .../.stderr | 1 + .../.stdout | 22 + .../test.cut | 4 + .../.stderr | 1 + .../.stdout | 23 + .../test-other.cut | 3 + .../test.cut | 3 + .../.stderr | 1 + .../.stdout | 23 + .../test-other.cut | 3 + .../test.cut | 3 + .../.stderr | 3 + .../.stdout | 73 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 59 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 58 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 58 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 58 +++ .../test.cut | 16 + .../.stderr | 3 + .../.stdout | 72 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 72 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 72 +++ .../test.cut | 16 + .../.stderr | 1 + .../.stdout | 58 +++ .../test.cut | 16 + .../.stderr | 4 + .../.stderr | 4 + .../base/frameworks/logging/delay/basic.zeek | 108 ++++ .../base/frameworks/logging/delay/coerce.zeek | 80 +++ .../logging/delay/delay-cb-redelay.zeek | 118 +++++ .../frameworks/logging/delay/delay-cb.zeek | 223 ++++++++ .../base/frameworks/logging/delay/errors.zeek | 72 +++ .../frameworks/logging/delay/example.zeek | 58 +++ .../frameworks/logging/delay/multi-write.zeek | 87 ++++ .../logging/delay/nested-write.zeek | 112 ++++ .../logging/delay/queue-setter.zeek | 142 ++++++ .../frameworks/logging/delay/queue-test.zeek | 340 +++++++++++++ .../logging/delay/static-errors.zeek | 33 ++ 105 files changed, 3505 insertions(+), 86 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-3/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-4/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/conn.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test-other.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test-other.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stdout create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/test.cut create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-2/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors/.stderr create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/basic.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/coerce.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/delay-cb-redelay.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/delay-cb.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/errors.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/example.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/multi-write.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/nested-write.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/queue-setter.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/queue-test.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek diff --git a/scripts/base/frameworks/logging/main.zeek b/scripts/base/frameworks/logging/main.zeek index f901b97e97..374b010cb3 100644 --- a/scripts/base/frameworks/logging/main.zeek +++ b/scripts/base/frameworks/logging/main.zeek @@ -215,6 +215,17 @@ export { const Log::default_ext_func: function(path: string): any = function(path: string) { } &redef; + ## Maximum default log write delay for a stream. A :zeek:see:`Log::write` + ## operation is delayed by at most this interval if :zeek:see:`Log::delay` + ## is called within :zeek:see:`Log::log_stream_policy`. + const default_max_delay_interval = 200msec &redef; + + ## The maximum length of the write delay queue per stream. If exceeded, + ## an attempt is made to evict the oldest writes from the queue. If + ## post delay callbacks re-delay a write operation, the maximum queue + ## size may be exceeded. + const default_max_delay_queue_size = 1000 &redef; + ## A filter type describes how to customize logging streams. type Filter: record { ## Descriptive name to reference this filter. @@ -393,6 +404,16 @@ export { ## log stream is disabled and enabled when the stream is ## enabled again. event_groups: set[string] &default=set(); + + ## Maximum delay interval for this stream. + ## + ## .. :zeek:see:`Log::default_max_delay_interval` + max_delay_interval: interval &default=default_max_delay_interval; + + ## Maximum delay queue size of this stream. + ## + ## .. :zeek:see:`Log::default_max_delay_queue_size` + max_delay_queue_size: count &default=default_max_delay_queue_size; }; ## Sentinel value for indicating that a filter was not found when looked up. @@ -602,6 +623,102 @@ export { ## of the given log record. Note that filter-level policy hooks still get ## invoked after the global hook vetoes, but they cannot "un-veto" the write. global log_stream_policy: Log::StreamPolicyHook; + + ## Type of function to invoke when delaying a log write has completed. + ## + ## This is similar to a :zeek:see:`Log::StreamPolicyHook`, but a callback + ## of this type is passed to zeek:see:`Log::delay` and executes just before + ## the record is forwarded to the individual log filters. + ## + ## Returning false from a post delay callback discards the log write. + type PostDelayCallback: function(rec: any, id: ID): bool; + + ## 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; + + ## Represents a post delay callback that simply returns T. This is used + ## as a default value for :zeek:see:`Log::delay` and ignored internally. + global empty_post_delay_cb: PostDelayCallback; + + ## Delay a log write. + ## + ## Calling this function is currently only allowed within the execution + ## of a :zeek:see:`Log::log_stream_policy` hook and requires the caller + ## to provide the stream ID and log record of the active write operation + ## as parameters. + ## + ## Conceptually, the delay is inserted between the execution of the + ## zeek:see:`Log::log_stream_policy` hook and the policy hooks of filters. + ## + ## Calling this function increases a reference count that can subsequently + ## be released using :zeek:see:`Log::delay_finish`. + ## The delay completes when either the reference count reaches zero, or + ## the configured maximum delay interval for the stream expires. The + ## optional *post_delay_callback* is invoked when the delay completed. + ## + ## The *post_delay_callback* function can extend the delay by invoking + ## :zeek:see:`Log::delay`. There's no limit to how often a write can be + ## re-delayed. Further, it can veto the forwarding of the log record + ## to the stream's filters by returning ``F``. If *post_delay_cb* is not + ## provided, it's equivalent to a function solely returning ``T``. + ## + ## id: The ID associated with a logging stream. + ## + ## rec: Log record + ## + ## post_delay_cb: A callback to invoke when the delay completed. + ## + ## Returns: An opaque token of type :zeek:see:`Log::DelayToken` + ## to be passed to :zeek:see:`Log::delay_finish`. + global delay: function(id: ID, rec: any, post_delay_cb: PostDelayCallback &default=empty_post_delay_cb): DelayToken; + + ## Release a delay reference taken with :zeek:see:`Log::delay`. + ## + ## When the last reference is released, :zeek:see:`Log::delay_finish` + ## synchronously resumes the delayed :zeek:see:`Log::write` operation. + ## + ## id: The ID associated with a logging stream. + ## + ## rec: Log record + ## + ## token: The opaque token as returned by :zeek:see:`Log::delay`. + ## + ## Returns: ``T`` on success, ``F`` if an inconsistent combination of + ## *id*, *rec* and *token* was provided. + global delay_finish: function(id: ID, rec: any, token: DelayToken): bool; + + ## Set the maximum delay for a stream. + ## + ## Multiple calls to this function will only ever increase the maximum + ## delay, the delay cannot be lowered. The default maximum delay for a + ## stream is zeek:see:`Log::default_max_delay_interval`. + ## + ## When a stream is removed and re-created via :zeek:see:`Log::create_stream`, + ## the new stream is re-configured with the previously used maximum delay. + ## + ## id: The ID associated with a logging stream. + ## + ## max_delay: The maximum delay interval for this stream. + ## + ## Returns: ``T`` on success, else ``F``. + global set_max_delay_interval: function(id: Log::ID, max_delay: interval): bool; + + ## Set the given stream's delay queue size. + ## + ## If the queue holds more records than the given *queue_size*, these are + ## attempted to be evicted at the time of the call. + ## + ## When a stream is removed and re-created via :zeek:see:`Log::create_stream`, + ## the new stream is re-configured with the most recently used queue size. + ## + ## id: The ID associated with a logging stream. + ## + ## max_delay: The maximum delay interval of this stream. + ## + ## Returns: ``T`` on success, else ``F``. + global set_max_delay_queue_size: function(id: Log::ID, queue_size: count): bool; } global all_streams: table[ID] of Stream = table(); @@ -728,11 +845,32 @@ function Log::rotation_format_func(ri: Log::RotationFmtInfo): Log::RotationPath return rval; } +# Keep maximum stream delay and last queue sizes around. +global max_stream_delay_intervals: table[ID] of interval; +global max_stream_delay_queue_sizes: table[ID] of count; + function create_stream(id: ID, stream: Stream) : bool { if ( ! __create_stream(id, stream) ) return F; + # Restore max value of any prior set_max_delay_interval(). + if ( id in max_stream_delay_intervals && + max_stream_delay_intervals[id] > stream$max_delay_interval ) + stream$max_delay_interval = max_stream_delay_intervals[id]; + else + max_stream_delay_intervals[id] = stream$max_delay_interval; + + # Restore the previous queue size. + if ( id in max_stream_delay_queue_sizes && + max_stream_delay_queue_sizes[id] != stream$max_delay_queue_size ) + stream$max_delay_queue_size = max_stream_delay_queue_sizes[id]; + else + max_stream_delay_queue_sizes[id] = stream$max_delay_queue_size; + + Log::__set_max_delay_interval(id, stream$max_delay_interval); + Log::__set_max_delay_queue_size(id, stream$max_delay_queue_size); + active_streams[id] = stream; all_streams[id] = stream; @@ -878,3 +1016,53 @@ event zeek_init() &priority=5 if ( print_to_log != REDIRECT_NONE ) Log::create_stream(PRINTLOG, [$columns=PrintLogInfo, $ev=log_print, $path=print_log_path]); } + +function empty_post_delay_cb(rec: any, id: ID): bool { + return T; +} + +function delay(id: ID, rec: any, post_delay_cb: PostDelayCallback &default=empty_post_delay_cb): DelayToken + { + return Log::__delay(id, rec, post_delay_cb); + } + +function delay_finish(id: ID, rec: any, token: DelayToken): bool + { + return Log::__delay_finish(id, rec, token); + } + +function set_max_delay_interval(id: Log::ID, max_delay: interval): bool + { + # Only allow setting larger values on created streams. + if ( id !in all_streams ) + return F; + + # Already larger interval. + if ( all_streams[id]$max_delay_interval >= max_delay ) + return T; + + if ( ! Log::__set_max_delay_interval(id, max_delay) ) + return F; + + max_stream_delay_intervals[id] = max_delay; + all_streams[id]$max_delay_interval = max_delay; + + return T; + } + +function set_max_delay_queue_size(id: Log::ID, max_size: count): bool + { + if ( id !in all_streams ) + return F; + + if ( all_streams[id]$max_delay_queue_size == max_size ) + return T; + + if ( ! Log::__set_max_delay_queue_size(id, max_size) ) + return F; + + max_stream_delay_queue_sizes[id] = max_size; + all_streams[id]$max_delay_queue_size = max_size; + + return T; + } diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index ebbcf7838b..298cf4d87f 100644 --- a/src/logging/Manager.cc +++ b/src/logging/Manager.cc @@ -30,6 +30,104 @@ using namespace std; namespace zeek::logging { +namespace detail { +using DelayTokenType = zeek_uint_t; + +class DelayInfo; + +using DelayInfoPtr = std::shared_ptr; + +constexpr zeek::TypeTag ZeekDelayTokenTypeTag = TYPE_COUNT; +DelayTokenType to_internal_delay_token(const ValPtr& val) { + assert(val->GetType()->Tag() == ZeekDelayTokenTypeTag); + return val->AsCount(); +} + +using DelayWriteMap = std::map; +using DelayTokenMap = std::unordered_map; +using DelayQueue = std::list; + +// DelayInfo tracks information of Log::write() operation that was +// delayed during execution of the Log::log_stream_policy hook. +class DelayInfo { +public: + static const DelayInfoPtr nil; + + explicit DelayInfo(const WriteContext& ctx, const zeek::ValPtr token_val, double expire_time) + : ctx(ctx), token_val(token_val), expire_time(expire_time) {} + + // No copy or assignment of DelayInfo itself, should + // always be managed through a shared pointer. + DelayInfo(const DelayInfo&) = delete; + DelayInfo& operator=(const DelayInfo&) = delete; + + void IncDelayRefs() { ++delay_refs; }; + void DecDelayRefs() { + assert(delay_refs > 0); + --delay_refs; + }; + int DelayRefs() const { return delay_refs; }; + bool HasDelayRefs() const { return delay_refs > 0; }; + + const RecordValPtr& Record() const { return ctx.record; } + const EnumValPtr& StreamId() const { return ctx.id; } + const WriteContext& Context() const { return ctx; } + + const ValPtr& TokenVal() const { return token_val; } + double ExpireTime() const { return expire_time; } + + // The position in the delay queue for efficient removal. + DelayQueue::const_iterator QueuePosition() const { return queue_position; } + bool IsInQueue() const { return enqueued; } + void SetQueuePosition(DelayQueue::const_iterator pos) { + queue_position = pos; + enqueued = true; + } + + const std::vector& PostDelayCallbacks() const { return post_delay_callbacks; } + void AppendPostDelayCallback(FuncPtr f) { post_delay_callbacks.emplace_back(std::move(f)); } + +private: + // ActiveWrite information + WriteContext ctx; + + // References - number of Log::delay() calls. + int delay_refs = 1; + + // Token for this delay. + ValPtr token_val; + + // Stamped on the first Log::delay() call during + // Log::log_stream_policy execution. + double expire_time = 0.0; + + // Callbacks to invoke when all references were released, or the delay expired. + std::vector post_delay_callbacks; + + // Has this DelayInfo object been enqueued? + bool enqueued = false; + + // Iterator pointing this instance in the delay_queue. + DelayQueue::const_iterator queue_position; +}; + +const DelayInfoPtr DelayInfo::nil = nullptr; + +// Helper class for dealing with nested Write() calls. +class ActiveWriteScope { +public: + ActiveWriteScope(std::vector& active_writes, WriteContext w) : active_writes{active_writes} { + active_writes.push_back(std::move(w)); + } + ~ActiveWriteScope() { active_writes.pop_back(); } + +private: + std::vector& active_writes; +}; + +} // namespace detail + + struct Manager::Filter { Val* fval = nullptr; string name; @@ -96,9 +194,42 @@ struct Manager::Stream { std::optional total_writes; // Initialized on first write. + // State about delayed writes for this Stream. + detail::DelayQueue delay_queue; + detail::DelayTokenMap delay_tokens; + detail::DelayWriteMap delayed_writes; + detail::WriteIdx write_idx = 0; + + Manager::LogDelayExpiredTimer* delay_timer = nullptr; + double max_delay_interval = 0.0; + zeek_uint_t max_delay_queue_size = 1; + bool evicting = false; + + ~Stream(); + + + const detail::DelayInfoPtr& GetDelayInfo(const detail::WriteContext& ctx); + + void EnqueueWriteForDelay(const detail::WriteContext& ctx); + void EvictDelayedWrites(); + void ScheduleLogDelayExpiredTimer(double t); + void DispatchDelayExpiredTimer(double t, bool is_expire); }; +// Timer for the head of the per stream delay queue. +class Manager::LogDelayExpiredTimer : public zeek::detail::Timer { +public: + LogDelayExpiredTimer(Manager::Stream* const stream, double t) + : Timer(t, zeek::detail::TIMER_LOG_DELAY_EXPIRE), stream(stream) {} + + void Dispatch(double t, bool is_expire) override { stream->DispatchDelayExpiredTimer(t, is_expire); } + +private: + Manager::Stream* const stream; +}; + + Manager::Filter::~Filter() { Unref(fval); Unref(field_name_map); @@ -131,8 +262,119 @@ Manager::Stream::~Stream() { for ( list::iterator f = filters.begin(); f != filters.end(); ++f ) delete *f; + + if ( delay_timer ) + zeek::detail::timer_mgr->Cancel(delay_timer); + + delay_timer = nullptr; } +const detail::DelayInfoPtr& Manager::Stream::GetDelayInfo(const detail::WriteContext& ctx) { + const auto& it = delayed_writes.find(ctx); + if ( it != delayed_writes.end() ) + return it->second; + + return detail::DelayInfo::nil; +} + +void Manager::Stream::EnqueueWriteForDelay(const detail::WriteContext& ctx) { + const auto delay_info = GetDelayInfo(ctx); + assert(delay_info != nullptr); + const auto& position = delay_queue.insert(delay_queue.end(), delay_info); + delay_info->SetQueuePosition(position); + + DBG_LOG(DBG_LOGGING, "Enqueue record %p with delay_refs=%d, expire_time=%lf", ctx.record.get(), + delay_info->DelayRefs(), delay_info->ExpireTime()); + + EvictDelayedWrites(); + + // If all delays have already been resolved after Log::write() returned, + // directly complete the delay. + if ( ! delay_info->HasDelayRefs() ) { + zeek::log_mgr->DelayCompleted(this, *delay_info); + return; + } + + ScheduleLogDelayExpiredTimer(delay_info->ExpireTime()); +} + +void Manager::Stream::EvictDelayedWrites() { + // Prevent recursion as DelayCompleted() may call EnqueueWriteForDelay() + // in turn calling into eviction. + DBG_LOG(DBG_LOGGING, "EvictDelayedWrites queue_size=%ld max=%ld evicting=%d", delay_queue.size(), + max_delay_queue_size, evicting); + if ( evicting ) + return; + + evicting = true; + + if ( delay_queue.size() > max_delay_queue_size ) { + if ( delay_timer ) { + zeek::detail::timer_mgr->Cancel(delay_timer); + delay_timer = nullptr; + } + + // It may happen that all records are re-delayed, which we allow, + // but also trigger a warning. This could be caused by indefinite + // redelaying through post_delay_callbacks. + auto start_queue_size = delay_queue.size(); + decltype(start_queue_size) current = 0; + + while ( delay_queue.size() > max_delay_queue_size ) { + ++current; + const auto& evict_delay_info = delay_queue.front(); + + DBG_LOG(DBG_LOGGING, "Evicting record %p", evict_delay_info->Record().get()); + + // Delay completed will remove it from the queue, no need to pop. + zeek::log_mgr->DelayCompleted(this, *evict_delay_info); + + if ( current == start_queue_size ) { + reporter->Warning("unable to evict delayed records for stream %s queue_size=%ld, all re-delayed?", + id->GetType()->Lookup(id->InternalInt()), delay_queue.size()); + break; + } + } + + + ScheduleLogDelayExpiredTimer(delay_queue.front()->ExpireTime()); + } + + evicting = false; +} + +void Manager::Stream::ScheduleLogDelayExpiredTimer(double t) { + if ( delay_timer != nullptr ) { + assert(delay_timer->Time() <= t); + return; + } + + delay_timer = new LogDelayExpiredTimer(this, t); + zeek::detail::timer_mgr->Add(delay_timer); +} + +void Manager::Stream::DispatchDelayExpiredTimer(double t, bool is_expire) { + delay_timer = nullptr; + + while ( ! delay_queue.empty() ) { + const auto& delay_info = delay_queue.front(); + + // If is_expire, drain the queue. Otherwise, stop + // when the next record in the queue is in the future. + if ( ! is_expire && delay_info->ExpireTime() > t ) + break; + + assert(delay_info->Record() != nullptr); + DBG_LOG(DBG_LOGGING, "Delayed record %p expired", delay_info->Record().get()); + zeek::log_mgr->DelayCompleted(this, *delay_info); + } + + // Re-arm the timer if there's more to do. + if ( ! delay_queue.empty() ) + ScheduleLogDelayExpiredTimer(delay_queue.front()->ExpireTime()); +} + + Manager::Manager() : plugin::ComponentManager("Log", "Writer"), total_log_stream_writes_family(telemetry_mgr->CounterFamily("zeek", "log-stream-writes", {"module", "stream"}, @@ -660,19 +902,6 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) { if ( stream->event ) event_mgr.Enqueue(stream->event, columns); - bool stream_veto = false; - - if ( log_stream_policy_hook ) { - auto v = log_stream_policy_hook->Invoke(columns, IntrusivePtr{NewRef{}, id}); - if ( v && ! v->AsBool() ) { - // We record the fact that this hook is vetoing - // the write, but continue on to the filter- - // level hooks to allow them to run anyway. - // They cannot "un-veto". - stream_veto = true; - } - } - if ( ! stream->total_writes ) { std::string module_name = zeek::detail::extract_module_name(stream->name.c_str()); std::initializer_list labels{{"module", module_name}, {"stream", stream->name}}; @@ -681,6 +910,47 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) { stream->total_writes->Inc(); + bool stream_veto = false; + + { + // Scope for active write. + uint64_t idx = ++stream->write_idx; + detail::WriteContext active_write{{zeek::NewRef{}, id}, columns, idx}; + detail::ActiveWriteScope active_write_scope{active_writes, active_write}; + + if ( log_stream_policy_hook ) { + auto v = log_stream_policy_hook->Invoke(columns, IntrusivePtr{NewRef{}, id}); + if ( v && ! v->AsBool() ) { + // We record the fact that this hook is vetoing + // the write, but continue on to the filter- + // level hooks to allow them to run anyway. + // They cannot "un-veto". + stream_veto = true; + } + } + + // Assert a Log::write() happening during the Log::log_stream_policy + // didn't corrupt our notion of active_writes. + assert(active_writes.back().record == active_write.record); + assert(active_writes.back().idx == active_write.idx); + + if ( const auto& delay_info = stream->GetDelayInfo(active_write); delay_info ) { + if ( ! stream_veto ) { + DBG_LOG(DBG_LOGGING, "Active write %p was delayed", delay_info->Record().get()); + stream->EnqueueWriteForDelay(active_write); + + // We're done for now. + return true; + } + + // There's a stream veto, so we've never put anything into + // the queue. Do the cleanup here and fall through to the + // policy hooks. + stream->delay_tokens.erase(detail::to_internal_delay_token(delay_info->TokenVal())); + stream->delayed_writes.erase(active_writes.back()); + } + } // scope for active write. + return WriteToFilters(stream, columns, stream_veto ? PolicyVerdict::VETO : PolicyVerdict::PASS); } @@ -701,7 +971,7 @@ bool Manager::WriteToFilters(const Manager::Stream* stream, zeek::RecordValPtr c continue; } - // Even if Log::log_stream_policy vetoed, we, invoke filter policy + // Even if Log::log_stream_policy vetoed, we invoke filter policy // hooks. Skip actually writing here. if ( stream_verdict == PolicyVerdict::VETO ) continue; @@ -878,6 +1148,185 @@ bool Manager::WriteToFilters(const Manager::Stream* stream, zeek::RecordValPtr c return true; } +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); + } + 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); + } + + DBG_LOG(DBG_LOGGING, "Delay() for %p RefCnt=%d", record.get(), record->RefCnt()); + + ValPtr token_val; + Stream* stream = FindStream(id.get()); + + if ( const auto& delay_info = stream->GetDelayInfo(active_write_ctx); delay_info ) { + // Previously delayed, return the same token to script-land. + token_val = delay_info->TokenVal(); + delay_info->IncDelayRefs(); + if ( post_delay_cb ) + delay_info->AppendPostDelayCallback(post_delay_cb); + } + else { + // 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); + 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 ) + new_delay_info->AppendPostDelayCallback(post_delay_cb); + + // Immediately keep information via the token, too, so that DelayFinish() + // works right away (even directly after Delay(). + stream->delay_tokens[token] = new_delay_info; + stream->delayed_writes.emplace(active_write_ctx, new_delay_info); + + assert(stream->GetDelayInfo(active_write_ctx) != detail::DelayInfo::nil); + } + + DBG_LOG(DBG_LOGGING, "Delayed log record %p RefCnt=%d token=%ld post_delay_cb=%p", record.get(), record->RefCnt(), + token_val->AsCount(), post_delay_cb.get()); + + return token_val; +} + + +bool Manager::DelayFinish(const EnumValPtr& id, const RecordValPtr& record, const ValPtr& token_val) { + Stream* stream = FindStream(id.get()); + if ( ! stream ) + return false; + + if ( token_val->GetType()->Tag() != detail::ZeekDelayTokenTypeTag ) { + reporter->Error("invalid delay token type %s", zeek::type_name(token_val->GetType()->Tag())); + return false; + } + + detail::DelayTokenType token = detail::to_internal_delay_token(token_val); + + DBG_LOG(DBG_LOGGING, "DelayFinish() for %p RefCnt=%d token=%ld", record.get(), record->RefCnt(), token); + const auto& it = stream->delay_tokens.find(token); + + if ( it == stream->delay_tokens.end() ) { + reporter->Error("non-existing log record for token=%ld %p", token, record.get()); + return false; + } + + auto& delay_info = it->second; + + if ( delay_info->Record() != record ) { + reporter->Error("record mismatch token=%ld %p and %p", token, record.get(), delay_info->Record().get()); + return false; + } + + if ( ! delay_info->HasDelayRefs() ) { + reporter->Error("delay reference underflow for token=%ld", token); + return false; + } + + delay_info->DecDelayRefs(); + + // Only call DelayCompleted() if this was ever properly enqueued. + if ( delay_info->IsInQueue() && ! delay_info->HasDelayRefs() ) + DelayCompleted(stream, *delay_info); + + return true; +} + +// Delaying has completed. +bool Manager::DelayCompleted(Stream* stream, detail::DelayInfo& delay_info) { + auto token = detail::to_internal_delay_token(delay_info.TokenVal()); + assert(stream->delay_tokens.find(token) != stream->delay_tokens.end()); + + DBG_LOG(DBG_LOGGING, "DelayCompleted() for log record %p RefCnt=%d token=%ld", delay_info.Record().get(), + delay_info.Record()->RefCnt(), token); + + bool res = false; + bool allow = true; + + { + // Push a new active write when running the post delay callbacks. This + // allows re-delay the record and putting it at the end of the queue. + uint64_t idx = ++stream->write_idx; + detail::WriteContext write_context{delay_info.StreamId(), delay_info.Record(), idx}; + detail::ActiveWriteScope active_write_scope{active_writes, write_context}; + + for ( const auto& cb : delay_info.PostDelayCallbacks() ) { + auto v = cb->Invoke(delay_info.Record(), delay_info.StreamId()); + if ( v ) + allow &= v->AsBool(); + } + + DBG_LOG(DBG_LOGGING, "DelayCompleted() post_delay_callback for record %p outcome=%d", delay_info.Record().get(), + allow); + + if ( const auto& new_delay_info = stream->GetDelayInfo(write_context); new_delay_info ) { + // Post delay callbacks re-delayed, clean-up. + stream->delay_queue.erase(delay_info.QueuePosition()); + stream->delay_tokens.erase(token); + stream->delayed_writes.erase(delay_info.Context()); + + DBG_LOG(DBG_LOGGING, "Enqueue re-delayed record %p as %ld (delay_refs=%d)", new_delay_info->Record().get(), + write_context.idx, new_delay_info->DelayRefs()); + stream->EnqueueWriteForDelay(write_context); + return true; + } + } + + // If any of the callbacks vetoed, don't even let the filter policy hooks + // see it. This is somewhat different from Log::log_stream_policy, but + // seems somewhat saner. + if ( allow ) + res = WriteToFilters(stream, delay_info.Record(), PolicyVerdict::PASS); + + // Clear the state. + stream->delay_queue.erase(delay_info.QueuePosition()); + stream->delay_tokens.erase(token); + stream->delayed_writes.erase(delay_info.Context()); + + return res; +} + +bool Manager::SetMaxDelayInterval(const EnumValPtr& id, double delay) { + Stream* stream = FindStream(id.get()); + if ( ! stream ) + return false; + + DBG_LOG(DBG_LOGGING, "SetMaxDelayInterval: stream=%s max_delay=%f", stream->name.c_str(), delay); + + // We rely on script land to protect us from not setting a lower value. + // Could consider to update the expiration time for all pending writes + // the queue and start expiring from the head, too. + + if ( delay < stream->max_delay_interval ) { + reporter->Warning("refusing to set lower delay %f < %f", delay, stream->max_delay_interval); + return false; + } + + stream->max_delay_interval = delay; + + return true; +} + +bool Manager::SetMaxDelayQueueSize(const EnumValPtr& id, zeek_uint_t queue_size) { + Stream* stream = FindStream(id.get()); + if ( ! stream ) + return false; + + DBG_LOG(DBG_LOGGING, "SetMaxDelayQueueSize: stream=%s queue_size=%ld", stream->name.c_str(), queue_size); + + stream->max_delay_queue_size = queue_size; + + stream->EvictDelayedWrites(); + + + return true; +} + threading::Value* Manager::ValToLogVal(std::optional& val, Type* ty) { if ( ! val ) return new threading::Value(ty->Tag(), false); diff --git a/src/logging/Manager.h b/src/logging/Manager.h index 7ca1500639..6fa5391d5e 100644 --- a/src/logging/Manager.h +++ b/src/logging/Manager.h @@ -30,6 +30,33 @@ class WriterFrontend; class RotationFinishedMessage; class RotationTimer; +namespace detail { + +class DelayInfo; + +using WriteIdx = uint64_t; + +/** + * Information about a Log::write() call. + */ +struct WriteContext { + EnumValPtr id = nullptr; + RecordValPtr record = nullptr; + WriteIdx idx = 0; // Ever increasing counter. + + bool operator<(const WriteContext& o) const { + assert(id == o.id); + return idx < o.idx; + } + + bool operator==(const WriteContext& o) const { + assert(id == o.id); + return idx == o.idx; + } +}; + +} // namespace detail + /** * Singleton class for managing log streams. */ @@ -152,6 +179,63 @@ public: */ bool Write(EnumVal* id, RecordVal* columns); + /** + * Delay the currently active @ref Write operation. + * + * This method is only allowed to be called during the execution of the + * Log::log_stream_policy Zeek script hook. This restriction may be + * relaxed in the future. + * + * @param id The enum value corresponding the log stream. + * + * @param record The log record to delay. + * + * @param post_delay_cb A callback function to invoke when the delay + * has completed or nullptr. + * + * @return An opaque token that can be passed to DelayFinish() to + * release a delayed Log::write() operation. + */ + ValPtr Delay(const EnumValPtr& id, const RecordValPtr record, FuncPtr post_delay_cb); + + /** + * Release reference for a delayed Log::write(). + * + * @param id The enum value corresponding the log stream. + * + * @param record The log record previously passed to Delay() + * + * @param token The token returned by the Delay() call. + * + * @return Returns true if the call was successful. + */ + bool DelayFinish(const EnumValPtr& id, const RecordValPtr& record, const ValPtr& token); + + /** + * Update the maximum delay interval of a given stream. + * + * Currently, it is only allowed to increase the maximum + * delay of a stream. + * + * @param id The enum value corresponding to the log stream. + * + * @param max_delay The new maximum delay, in seconds. + * + * @return Returns true if the call was successful, else false. + */ + bool SetMaxDelayInterval(const EnumValPtr& id, double max_delay); + + /** + * Set the maximum delay queue size for the given stream. + * + * @param id The enum value corresponding to the log stream. + * + * @param max_queue_length The new maximum queue length. + * + * @return Returns true if the call was successful, else false. + */ + bool SetMaxDelayQueueSize(const EnumValPtr& id, zeek_uint_t max_queue_length); + /** * Create a new log writer frontend. This is exposed so that the * communication system can recreate remote log streams locally. @@ -279,6 +363,7 @@ private: struct Filter; struct Stream; struct WriterInfo; + class LogDelayExpiredTimer; bool TraverseRecord(Stream* stream, Filter* filter, RecordType* rt, TableVal* include, TableVal* exclude, const std::string& path, const std::list& indices); @@ -303,6 +388,8 @@ private: bool RemoveStream(unsigned int idx); + bool DelayCompleted(Manager::Stream* stream, detail::DelayInfo& delay_info); + std::vector streams; // Indexed by stream enum. int rotations_pending; // Number of rotations not yet finished. FuncPtr rotation_format_func; @@ -310,6 +397,9 @@ private: telemetry::IntCounterFamily total_log_stream_writes_family; telemetry::IntCounterFamily total_log_writer_writes_family; + + zeek_uint_t last_delay_token = 0; + std::vector active_writes; }; } // namespace logging diff --git a/src/logging/logging.bif b/src/logging/logging.bif index fa0c611497..9ca3a965e7 100644 --- a/src/logging/logging.bif +++ b/src/logging/logging.bif @@ -70,3 +70,78 @@ function Log::__flush%(id: Log::ID%): bool bool result = zeek::log_mgr->Flush(id->AsEnumVal()); return zeek::val_mgr->Bool(result); %} + +%%{ +namespace + { + zeek::EnumValPtr enum_ref(zeek::Val *v) + { + if ( v->GetType()->Tag() != zeek::TYPE_ENUM ) + { + zeek::emit_builtin_error("not an enum"); + return nullptr; + } + + return zeek::IntrusivePtr{zeek::NewRef{}, v->AsEnumVal()}; + } + } + + // Create intrusive pointer adopting reference. + zeek::RecordValPtr ref(zeek::Val *v) + { + if ( v->GetType()->Tag() != zeek::TYPE_RECORD ) + { + zeek::emit_builtin_error("not a record"); + return nullptr; + } + + return zeek::IntrusivePtr{zeek::NewRef{}, v->AsRecordVal()}; + } +%%} + +function Log::__delay%(id: Log::ID, rec: any, post_delay_cb: PostDelayCallback%): Log::DelayToken + %{ + auto idptr = enum_ref(id); + auto recptr = ref(rec); + if ( ! idptr || ! recptr ) + return zeek::val_mgr->Bool(false); + + static auto empty_post_delay_cb_ptr = zeek::id::find_func("Log::empty_post_delay_cb"); + + auto post_delay_cb_ptr = post_delay_cb->AsFuncVal()->AsFuncPtr(); + if ( post_delay_cb_ptr == empty_post_delay_cb_ptr ) + post_delay_cb_ptr = Func::nil; + + return zeek::log_mgr->Delay(idptr, recptr, post_delay_cb_ptr); + %} + +function Log::__delay_finish%(id: Log::ID, rec: any, token: Log::DelayToken%): bool + %{ + auto idptr = enum_ref(id); + auto recptr = ref(rec); + if ( ! idptr || ! recptr ) + return zeek::val_mgr->Bool(false); + + bool result = zeek::log_mgr->DelayFinish(idptr, recptr, {zeek::NewRef{}, token}); + return zeek::val_mgr->Bool(result); + %} + +function Log::__set_max_delay_interval%(id: Log::ID, max_delay: interval%): bool + %{ + auto idptr = enum_ref(id); + if ( ! idptr ) + return zeek::val_mgr->Bool(false); + + bool result = zeek::log_mgr->SetMaxDelayInterval(idptr, max_delay); + return zeek::val_mgr->Bool(result); + %} + +function Log::__set_max_delay_queue_size%(id: Log::ID, max_queue_size: count%): bool + %{ + auto idptr = enum_ref(id); + if ( ! idptr ) + return zeek::val_mgr->Bool(false); + + bool result = zeek::log_mgr->SetMaxDelayQueueSize(idptr, max_queue_size); + return zeek::val_mgr->Bool(result); + %} diff --git a/testing/btest/Baseline/plugins.hooks/output b/testing/btest/Baseline/plugins.hooks/output index faf63ede72..53b9095773 100644 --- a/testing/btest/Baseline/plugins.hooks/output +++ b/testing/btest/Baseline/plugins.hooks/output @@ -49,19 +49,43 @@ 0.000000 MetaHookPost CallFunction(Log::__add_filter, , (Notice::LOG, [name=default, writer=Log::WRITER_ASCII, path=notice, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=])) -> 0.000000 MetaHookPost CallFunction(Log::__add_filter, , (Tunnel::LOG, [name=default, writer=Log::WRITER_ASCII, path=tunnel, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=])) -> 0.000000 MetaHookPost CallFunction(Log::__add_filter, , (Weird::LOG, [name=default, writer=Log::WRITER_ASCII, path=weird, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> 0.000000 MetaHookPost CallFunction(Log::__enable_stream, , (Analyzer::Logging::LOG)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Analyzer::Logging::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Broker::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Cluster::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Config::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Conn::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (DPD::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Files::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (HTTP::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Notice::ALARM_LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Notice::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Tunnel::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_interval, , (Weird::LOG, 200.0 msecs)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Analyzer::Logging::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Broker::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Cluster::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Config::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Conn::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (DPD::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Files::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (HTTP::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Notice::ALARM_LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Notice::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Tunnel::LOG, 1000)) -> +0.000000 MetaHookPost CallFunction(Log::__set_max_delay_queue_size, , (Weird::LOG, 1000)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Analyzer::Logging::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Broker::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Cluster::LOG)) -> @@ -98,18 +122,18 @@ 0.000000 MetaHookPost CallFunction(Log::add_stream_filters, , (Notice::LOG, default)) -> 0.000000 MetaHookPost CallFunction(Log::add_stream_filters, , (Tunnel::LOG, default)) -> 0.000000 MetaHookPost CallFunction(Log::add_stream_filters, , (Weird::LOG, default)) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}])) -> -0.000000 MetaHookPost CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> +0.000000 MetaHookPost CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) -> 0.000000 MetaHookPost CallFunction(Log::enable_stream, , (Analyzer::Logging::LOG)) -> 0.000000 MetaHookPost CallFunction(Option::set, , (Site::local_nets, {64:ff9b:1::<...>/15,fc00::<...>/10,::/128,2002:ffff:ffff::/48,::1/128,2002:cb00:7100::<...>/4,2002:c633:6400::/40,2002:a00::/24,100::<...>/8,2001:2::/48,2002:c000:200::<...>/12,2002:f000::/20,2002:7f00::/24,2001::/23,2002:6440::/26,2002:c000::<...>/16,2002:ac10::/28,2002:a9fe::/32,2002:c612::<...>/16,2002::/24,fe80::/10,2001:db8::<...>/24,2002:c0a8::<...>/24}, )) -> 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (Analyzer::Logging::enable, Config::config_option_changed{ if ( == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> @@ -967,19 +991,43 @@ 0.000000 MetaHookPre CallFunction(Log::__add_filter, , (Notice::LOG, [name=default, writer=Log::WRITER_ASCII, path=notice, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=])) 0.000000 MetaHookPre CallFunction(Log::__add_filter, , (Tunnel::LOG, [name=default, writer=Log::WRITER_ASCII, path=tunnel, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=])) 0.000000 MetaHookPre CallFunction(Log::__add_filter, , (Weird::LOG, [name=default, writer=Log::WRITER_ASCII, path=weird, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) 0.000000 MetaHookPre CallFunction(Log::__enable_stream, , (Analyzer::Logging::LOG)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Analyzer::Logging::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Broker::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Cluster::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Config::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Conn::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (DPD::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Files::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (HTTP::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Notice::ALARM_LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Notice::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Tunnel::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_interval, , (Weird::LOG, 200.0 msecs)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Analyzer::Logging::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Broker::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Cluster::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Config::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Conn::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (DPD::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Files::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (HTTP::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Notice::ALARM_LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Notice::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Tunnel::LOG, 1000)) +0.000000 MetaHookPre CallFunction(Log::__set_max_delay_queue_size, , (Weird::LOG, 1000)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Analyzer::Logging::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Broker::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Cluster::LOG)) @@ -1016,18 +1064,18 @@ 0.000000 MetaHookPre CallFunction(Log::add_stream_filters, , (Notice::LOG, default)) 0.000000 MetaHookPre CallFunction(Log::add_stream_filters, , (Tunnel::LOG, default)) 0.000000 MetaHookPre CallFunction(Log::add_stream_filters, , (Weird::LOG, default)) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}])) -0.000000 MetaHookPre CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) +0.000000 MetaHookPre CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000])) 0.000000 MetaHookPre CallFunction(Log::enable_stream, , (Analyzer::Logging::LOG)) 0.000000 MetaHookPre CallFunction(Option::set, , (Site::local_nets, {64:ff9b:1::<...>/15,fc00::<...>/10,::/128,2002:ffff:ffff::/48,::1/128,2002:cb00:7100::<...>/4,2002:c633:6400::/40,2002:a00::/24,100::<...>/8,2001:2::/48,2002:c000:200::<...>/12,2002:f000::/20,2002:7f00::/24,2001::/23,2002:6440::/26,2002:c000::<...>/16,2002:ac10::/28,2002:a9fe::/32,2002:c612::<...>/16,2002::/24,fe80::/10,2001:db8::<...>/24,2002:c0a8::<...>/24}, )) 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (Analyzer::Logging::enable, Config::config_option_changed{ if ( == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) @@ -1884,19 +1932,43 @@ 0.000000 | HookCallFunction Log::__add_filter(Notice::LOG, [name=default, writer=Log::WRITER_ASCII, path=notice, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=]) 0.000000 | HookCallFunction Log::__add_filter(Tunnel::LOG, [name=default, writer=Log::WRITER_ASCII, path=tunnel, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=]) 0.000000 | HookCallFunction Log::__add_filter(Weird::LOG, [name=default, writer=Log::WRITER_ASCII, path=weird, path_func=, include=, exclude=, log_local=T, log_remote=T, field_name_map={}, scope_sep=., ext_prefix=_, ext_func=lambda_<2528247166937952945>, interv=0 secs, postprocessor=, config={}, policy=]) -0.000000 | HookCallFunction Log::__create_stream(Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}]) -0.000000 | HookCallFunction Log::__create_stream(Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}]) +0.000000 | HookCallFunction Log::__create_stream(Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) 0.000000 | HookCallFunction Log::__enable_stream(Analyzer::Logging::LOG) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Analyzer::Logging::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Broker::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Cluster::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Config::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Conn::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(DPD::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Files::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(HTTP::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Notice::ALARM_LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Notice::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Tunnel::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_interval(Weird::LOG, 200.0 msecs) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Analyzer::Logging::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Broker::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Cluster::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Config::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Conn::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(DPD::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Files::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(HTTP::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Notice::ALARM_LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Notice::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Tunnel::LOG, 1000) +0.000000 | HookCallFunction Log::__set_max_delay_queue_size(Weird::LOG, 1000) 0.000000 | HookCallFunction Log::add_default_filter(Analyzer::Logging::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Broker::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Cluster::LOG) @@ -1933,18 +2005,18 @@ 0.000000 | HookCallFunction Log::add_stream_filters(Notice::LOG, default) 0.000000 | HookCallFunction Log::add_stream_filters(Tunnel::LOG, default) 0.000000 | HookCallFunction Log::add_stream_filters(Weird::LOG, default) -0.000000 | HookCallFunction Log::create_stream(Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}]) -0.000000 | HookCallFunction Log::create_stream(Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}]) -0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}]) +0.000000 | HookCallFunction Log::create_stream(Analyzer::Logging::LOG, [columns=Analyzer::Logging::Info, ev=, path=analyzer, policy=Analyzer::Logging::log_policy, event_groups={Analyzer::Logging}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Broker::LOG, [columns=Broker::Info, ev=, path=broker, policy=Broker::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Cluster::LOG, [columns=Cluster::Info, ev=, path=cluster, policy=Cluster::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Config::LOG, [columns=Config::Info, ev=Config::log_config, path=config, policy=Config::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Conn::LOG, [columns=Conn::Info, ev=Conn::log_conn, path=conn, policy=Conn::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(DPD::LOG, [columns=DPD::Info, ev=, path=dpd, policy=DPD::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Files::LOG, [columns=Files::Info, ev=Files::log_files, path=files, policy=Files::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(HTTP::LOG, [columns=HTTP::Info, ev=HTTP::log_http, path=http, policy=HTTP::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Notice::ALARM_LOG, [columns=Notice::Info, ev=, path=notice_alarm, policy=Notice::log_policy_alarm, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Notice::LOG, [columns=Notice::Info, ev=Notice::log_notice, path=notice, policy=Notice::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Tunnel::LOG, [columns=Tunnel::Info, ev=, path=tunnel, policy=Tunnel::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) +0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird, policy=Weird::log_policy, event_groups={}, max_delay_interval=200.0 msecs, max_delay_queue_size=1000]) 0.000000 | HookCallFunction Log::enable_stream(Analyzer::Logging::LOG) 0.000000 | HookCallFunction Option::set(Site::local_nets, {64:ff9b:1::<...>/15,fc00::<...>/10,::/128,2002:ffff:ffff::/48,::1/128,2002:cb00:7100::<...>/4,2002:c633:6400::/40,2002:a00::/24,100::<...>/8,2001:2::/48,2002:c000:200::<...>/12,2002:f000::/20,2002:7f00::/24,2001::/23,2002:6440::/26,2002:c000::<...>/16,2002:ac10::/28,2002:a9fe::/32,2002:c612::<...>/16,2002::/24,fe80::/10,2001:db8::<...>/24,2002:c0a8::<...>/24}, ) 0.000000 | HookCallFunction Option::set_change_handler(Analyzer::Logging::enable, Config::config_option_changed{ if ( == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100) diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stdout new file mode 100644 index 0000000000..38c8e054f9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/.stdout @@ -0,0 +1,19 @@ +### 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 +1362692526.869344, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/test.cut new file mode 100644 index 0000000000..903d97d4c8 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-2/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.869344|CHhAvVGS1DHFjwGM9|inital-value diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stdout new file mode 100644 index 0000000000..8f86d9741d --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/.stdout @@ -0,0 +1,19 @@ +### 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 +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.basic-3/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/test.cut new file mode 100644 index 0000000000..7ca18d40f9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-3/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stdout new file mode 100644 index 0000000000..8f86d9741d --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/.stdout @@ -0,0 +1,19 @@ +### 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 +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.basic-4/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/test.cut new file mode 100644 index 0000000000..7ca18d40f9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-4/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stdout new file mode 100644 index 0000000000..38c8e054f9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/.stdout @@ -0,0 +1,19 @@ +### 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 +1362692526.869344, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/test.cut new file mode 100644 index 0000000000..903d97d4c8 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.869344|CHhAvVGS1DHFjwGM9|inital-value diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.stdout new file mode 100644 index 0000000000..ee7e4de1da --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/.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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=initial-value] +1362692526.869344, Updating info$msg after write! +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, post_delay_cb, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=initial-value delayed 211.0 msecs 483.955383 usecs] +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.coerce/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/test.cut new file mode 100644 index 0000000000..39e556bbd8 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.coerce/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|initial-value delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.stdout new file mode 100644 index 0000000000..b2eff25141 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/.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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.939084, post_delay_cb, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 69.0 msecs 740.056992 usecs], 69.0 msecs 740.056992 usecs +1362692526.939084, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/test.cut new file mode 100644 index 0000000000..e482f54043 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-2/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.939084|CHhAvVGS1DHFjwGM9|inital-value delayed 69.0 msecs 740.056992 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stdout new file mode 100644 index 0000000000..82bb17ae0b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/.stdout @@ -0,0 +1,22 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +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, post_delay_cb - 1, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 211.0 msecs 483.955383 usecs], 211.0 msecs 483.955383 usecs +1362692527.080828, post_delay_cb - 2, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 211.0 msecs 483.955383 usecs] +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.delay-cb-3/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/test.cut new file mode 100644 index 0000000000..969869dded --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-3/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stdout new file mode 100644 index 0000000000..5078396877 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/.stdout @@ -0,0 +1,22 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.939084, post_delay_cb - 1, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 69.0 msecs 740.056992 usecs], 69.0 msecs 740.056992 usecs +1362692526.939084, post_delay_cb - 2, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 69.0 msecs 740.056992 usecs] +1362692526.939084, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/test.cut new file mode 100644 index 0000000000..e482f54043 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-4/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.939084|CHhAvVGS1DHFjwGM9|inital-value delayed 69.0 msecs 740.056992 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stdout new file mode 100644 index 0000000000..6c7a480835 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/.stdout @@ -0,0 +1,20 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.939084, post_delay_cb, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value], 69.0 msecs 740.056992 usecs +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/test.cut new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-5/test.cut @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stdout new file mode 100644 index 0000000000..73b5c152c2 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/.stdout @@ -0,0 +1,20 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, post_delay_cb, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value], 0 secs +1362692526.869344, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/test.cut new file mode 100644 index 0000000000..903d97d4c8 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-6/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.869344|CHhAvVGS1DHFjwGM9|inital-value diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stdout new file mode 100644 index 0000000000..aecf79f474 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/.stdout @@ -0,0 +1,22 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, post_delay_cb - 1, delaying again, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value], 0 secs +1362692526.869344, post_delay_cb - 1, delay_finish, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value], 0 secs +1362692526.869344, post_delay_cb - 2, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 0 secs], 0 secs +1362692526.869344, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/test.cut new file mode 100644 index 0000000000..ebf486f505 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay-2/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.869344|CHhAvVGS1DHFjwGM9|inital-value delayed 0 secs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stdout new file mode 100644 index 0000000000..92b1078be7 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/.stdout @@ -0,0 +1,22 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.939084, post_delay_cb - 1, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value], 69.0 msecs 740.056992 usecs +1362692526.939084, new_packet, 2 +1362692526.939378, new_packet, 3 +1362692526.939527, new_packet, 4 +1362692527.008509, post_delay_cb - 2, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 139.0 msecs 164.924622 usecs], 139.0 msecs 164.924622 usecs +1362692527.008509, log_policy, CHhAvVGS1DHFjwGM9 +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, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/test.cut new file mode 100644 index 0000000000..6e60c41c98 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb-redelay/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.008509|CHhAvVGS1DHFjwGM9|inital-value delayed 139.0 msecs 164.924622 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.stdout new file mode 100644 index 0000000000..5d28b325c2 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/.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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +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, post_delay_cb, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 211.0 msecs 483.955383 usecs], 211.0 msecs 483.955383 usecs +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.delay-cb/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/test.cut new file mode 100644 index 0000000000..969869dded --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.delay-cb/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-2/.stderr new file mode 100644 index 0000000000..b7683d027b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-2/.stderr @@ -0,0 +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: invalid Log::delay() call: active write mismatch diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-3/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-3/.stderr new file mode 100644 index 0000000000..b7683d027b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-3/.stderr @@ -0,0 +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: invalid Log::delay() call: active write mismatch 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 new file mode 100644 index 0000000000..643fc6706d --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-4/.stderr @@ -0,0 +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<...> 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 new file mode 100644 index 0000000000..0ff66ed885 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr @@ -0,0 +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<...> diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr new file mode 100644 index 0000000000..f5d890f163 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.stderr @@ -0,0 +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: invalid delay token type string diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr new file mode 100644 index 0000000000..23205c7478 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-7/.stderr @@ -0,0 +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: delay reference underflow for token=1 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors/.stderr new file mode 100644 index 0000000000..f6c79f1e6a --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors/.stderr @@ -0,0 +1,2 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +error: invalid Log::delay() call: no active write context available diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stdout new file mode 100644 index 0000000000..c79e01272f --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/.stdout @@ -0,0 +1,5 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692527.080972, Pcap::file_done +1362692527.080972, log_stream_policy, Conn::LOG, [ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856/tcp, resp_h=192.150.187.43, resp_p=80/tcp], proto=tcp, service=, duration=211.0 msecs 483.955383 usecs, orig_bytes=136, resp_bytes=5007, conn_state=SF, local_orig=F, local_resp=F, missed_bytes=0, history=ShADadFf, orig_pkts=7, orig_ip_bytes=512, resp_pkts=7, resp_ip_bytes=5379, tunnel_parents=, orig_name=, resp_name=] +1362692527.080972, token1 delay hook +1362692527.080972, token2 delay hook diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/conn.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/conn.cut new file mode 100644 index 0000000000..b532a4f3df --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.example/conn.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts uid id.orig_h orig_name id.resp_h resp_name +XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 141.142.228.5 fake_addr_lookup_result_141.142.228.5 192.150.187.43 fake_addr_lookup_result_192.150.187.43 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stdout new file mode 100644 index 0000000000..279fcec074 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/.stdout @@ -0,0 +1,22 @@ +### 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, 1, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, log_policy, CHhAvVGS1DHFjwGM9, initial-value-second-write +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, msg=initial-value-second-write] +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, post_delay_cb, [ts=1362692526.869344, write_ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, msg=initial-value-second-write delayed 211.0 msecs 483.955383 usecs], 211.0 msecs 483.955383 usecs +1362692527.080828, log_policy, CHhAvVGS1DHFjwGM9, initial-value-second-write delayed 211.0 msecs 483.955383 usecs +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.multi-write/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/test.cut new file mode 100644 index 0000000000..da25a2bb27 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.multi-write/test.cut @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.869344|CHhAvVGS1DHFjwGM9|initial-value-second-write +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|initial-value-second-write delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stdout new file mode 100644 index 0000000000..7056295b5c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/.stdout @@ -0,0 +1,23 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +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, post_delay_cb, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 211.0 msecs 483.955383 usecs], 211.0 msecs 483.955383 usecs +1362692527.080828, log_stream_policy, LOG_OTHER, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 211.0 msecs 483.955383 usecs] +1362692527.080828, log_policy, CHhAvVGS1DHFjwGM9, LOG_OTHER, inital-value delayed 211.0 msecs 483.955383 usecs +1362692527.080828, log_policy, CHhAvVGS1DHFjwGM9, LOG, inital-value delayed 211.0 msecs 483.955383 usecs +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.nested-write-2/test-other.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test-other.cut new file mode 100644 index 0000000000..969869dded --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test-other.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test.cut new file mode 100644 index 0000000000..969869dded --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write-2/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stdout new file mode 100644 index 0000000000..22c3fd64bd --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/.stdout @@ -0,0 +1,23 @@ +### 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, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, log_stream_policy, LOG_OTHER, [ts=1362692526.869344, write_ts=, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +1362692526.869344, log_policy, CHhAvVGS1DHFjwGM9, LOG_OTHER, inital-value +1362692526.869344, new_packet, 1 +1362692526.939084, when timeout, [ts=1362692526.869344, write_ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, msg=inital-value] +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, post_delay_cb, [ts=1362692526.869344, write_ts=1362692526.869344, uid=CHhAvVGS1DHFjwGM9, msg=inital-value delayed 211.0 msecs 483.955383 usecs], 211.0 msecs 483.955383 usecs +1362692527.080828, log_policy, CHhAvVGS1DHFjwGM9, LOG, inital-value delayed 211.0 msecs 483.955383 usecs +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.nested-write/test-other.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test-other.cut new file mode 100644 index 0000000000..903d97d4c8 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test-other.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692526.869344|CHhAvVGS1DHFjwGM9|inital-value diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test.cut new file mode 100644 index 0000000000..969869dded --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.nested-write/test.cut @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|write_ts|uid|msg +1362692526.869344|1362692527.080828|CHhAvVGS1DHFjwGM9|inital-value delayed 211.0 msecs 483.955383 usecs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stderr new file mode 100644 index 0000000000..6485d7c60e --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stderr @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692527.009855 warning: unable to evict delayed records for stream LOG queue_size=10, all re-delayed? +1362692527.080972 warning: unable to evict delayed records for stream LOG queue_size=4, all re-delayed? diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stdout new file mode 100644 index 0000000000..7347489a27 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/.stdout @@ -0,0 +1,73 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.009855, set_max_delay_queue_size to 3 +1362692527.009855, post_delay_cb - re-delay, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.009887, post_delay_cb - done, [ts=1362692526.869344, post_ts=1362692527.009855, write_ts=, msg=packet number 1, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692526.939084, post_ts=1362692527.009855, write_ts=, msg=packet number 2, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692526.939378, post_ts=1362692527.009855, write_ts=, msg=packet number 3, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692526.939527, post_ts=1362692527.009855, write_ts=, msg=packet number 4, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692527.008509, post_ts=1362692527.009855, write_ts=, msg=packet number 5, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692527.009512, post_ts=1362692527.009855, write_ts=, msg=packet number 6, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692527.009721, post_ts=1362692527.009855, write_ts=, msg=packet number 7, redelayed=T] +1362692527.009887, log_policy +1362692527.009887, post_delay_cb - done, [ts=1362692527.009765, post_ts=1362692527.009855, write_ts=, msg=packet number 8, redelayed=T] +1362692527.009887, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.011846, post_delay_cb - done, [ts=1362692527.009775, post_ts=1362692527.009855, write_ts=, msg=packet number 9, redelayed=T] +1362692527.011846, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080828, post_delay_cb - done, [ts=1362692527.009855, post_ts=1362692527.009855, write_ts=, msg=packet number 10, redelayed=T] +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb - done, [ts=1362692527.009887, post_ts=1362692527.080972, write_ts=, msg=packet number 11, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.011846, post_ts=1362692527.080972, write_ts=, msg=packet number 12, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.080828, post_ts=1362692527.080972, write_ts=, msg=packet number 13, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14, redelayed=T] +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/test.cut new file mode 100644 index 0000000000..a908a72398 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter-2/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692527.009855|1362692527.009887|packet number 1 +1362692526.939084|1362692527.009855|1362692527.009887|packet number 2 +1362692526.939378|1362692527.009855|1362692527.009887|packet number 3 +1362692526.939527|1362692527.009855|1362692527.009887|packet number 4 +1362692527.008509|1362692527.009855|1362692527.009887|packet number 5 +1362692527.009512|1362692527.009855|1362692527.009887|packet number 6 +1362692527.009721|1362692527.009855|1362692527.009887|packet number 7 +1362692527.009765|1362692527.009855|1362692527.009887|packet number 8 +1362692527.009775|1362692527.009855|1362692527.011846|packet number 9 +1362692527.009855|1362692527.009855|1362692527.080828|packet number 10 +1362692527.009887|1362692527.080972|1362692527.080972|packet number 11 +1362692527.011846|1362692527.080972|1362692527.080972|packet number 12 +1362692527.080828|1362692527.080972|1362692527.080972|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stdout new file mode 100644 index 0000000000..dee6cee79e --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/.stdout @@ -0,0 +1,59 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1] +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2] +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3] +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4] +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5] +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6] +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7] +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8] +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9] +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10] +1362692527.009855, set_max_delay_queue_size to 3 +1362692527.009855, post_delay_cb, [ts=1362692526.869344, post_ts=1362692527.009855, write_ts=, msg=packet number 1], 140.0 msecs 511.035919 usecs +1362692527.009855, log_policy +1362692527.009855, post_delay_cb, [ts=1362692526.939084, post_ts=1362692527.009855, write_ts=, msg=packet number 2], 70.0 msecs 770.978928 usecs +1362692527.009855, log_policy +1362692527.009855, post_delay_cb, [ts=1362692526.939378, post_ts=1362692527.009855, write_ts=, msg=packet number 3], 70.0 msecs 477.00882 usecs +1362692527.009855, log_policy +1362692527.009855, post_delay_cb, [ts=1362692526.939527, post_ts=1362692527.009855, write_ts=, msg=packet number 4], 70.0 msecs 327.997208 usecs +1362692527.009855, log_policy +1362692527.009855, post_delay_cb, [ts=1362692527.008509, post_ts=1362692527.009855, write_ts=, msg=packet number 5], 1.0 msec 346.111298 usecs +1362692527.009855, log_policy +1362692527.009855, post_delay_cb, [ts=1362692527.009512, post_ts=1362692527.009855, write_ts=, msg=packet number 6], 343.084335 usecs +1362692527.009855, log_policy +1362692527.009855, post_delay_cb, [ts=1362692527.009721, post_ts=1362692527.009855, write_ts=, msg=packet number 7], 133.991241 usecs +1362692527.009855, log_policy +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11] +1362692527.009887, post_delay_cb, [ts=1362692527.009765, post_ts=1362692527.009887, write_ts=, msg=packet number 8], 122.070312 usecs +1362692527.009887, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12] +1362692527.011846, post_delay_cb, [ts=1362692527.009775, post_ts=1362692527.011846, write_ts=, msg=packet number 9], 2.0 msecs 71.142197 usecs +1362692527.011846, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13] +1362692527.080828, post_delay_cb, [ts=1362692527.009855, post_ts=1362692527.080828, write_ts=, msg=packet number 10], 70.0 msecs 972.919464 usecs +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14] +1362692527.080972, post_delay_cb, [ts=1362692527.009887, post_ts=1362692527.080972, write_ts=, msg=packet number 11], 71.0 msecs 84.976196 usecs +1362692527.080972, log_policy +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb, [ts=1362692527.011846, post_ts=1362692527.080972, write_ts=, msg=packet number 12], 69.0 msecs 125.890732 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.080828, post_ts=1362692527.080972, write_ts=, msg=packet number 13], 144.004822 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14], 0 secs +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/test.cut new file mode 100644 index 0000000000..587354f848 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-setter/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692527.009855|1362692527.009855|packet number 1 +1362692526.939084|1362692527.009855|1362692527.009855|packet number 2 +1362692526.939378|1362692527.009855|1362692527.009855|packet number 3 +1362692526.939527|1362692527.009855|1362692527.009855|packet number 4 +1362692527.008509|1362692527.009855|1362692527.009855|packet number 5 +1362692527.009512|1362692527.009855|1362692527.009855|packet number 6 +1362692527.009721|1362692527.009855|1362692527.009855|packet number 7 +1362692527.009765|1362692527.009887|1362692527.009887|packet number 8 +1362692527.009775|1362692527.011846|1362692527.011846|packet number 9 +1362692527.009855|1362692527.080828|1362692527.080828|packet number 10 +1362692527.009887|1362692527.080972|1362692527.080972|packet number 11 +1362692527.011846|1362692527.080972|1362692527.080972|packet number 12 +1362692527.080828|1362692527.080972|1362692527.080972|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stdout new file mode 100644 index 0000000000..41949b14e7 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/.stdout @@ -0,0 +1,58 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG +1362692526.869344, post_delay_cb, [ts=1362692526.869344, post_ts=1362692526.869344, write_ts=, msg=packet number 1], 0 secs +1362692526.869344, log_policy +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG +1362692526.939084, post_delay_cb, [ts=1362692526.939084, post_ts=1362692526.939084, write_ts=, msg=packet number 2], 0 secs +1362692526.939084, log_policy +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG +1362692526.939378, post_delay_cb, [ts=1362692526.939378, post_ts=1362692526.939378, write_ts=, msg=packet number 3], 0 secs +1362692526.939378, log_policy +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG +1362692526.939527, post_delay_cb, [ts=1362692526.939527, post_ts=1362692526.939527, write_ts=, msg=packet number 4], 0 secs +1362692526.939527, log_policy +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG +1362692527.008509, post_delay_cb, [ts=1362692527.008509, post_ts=1362692527.008509, write_ts=, msg=packet number 5], 0 secs +1362692527.008509, log_policy +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG +1362692527.009512, post_delay_cb, [ts=1362692527.009512, post_ts=1362692527.009512, write_ts=, msg=packet number 6], 0 secs +1362692527.009512, log_policy +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG +1362692527.009721, post_delay_cb, [ts=1362692527.009721, post_ts=1362692527.009721, write_ts=, msg=packet number 7], 0 secs +1362692527.009721, log_policy +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG +1362692527.009765, post_delay_cb, [ts=1362692527.009765, post_ts=1362692527.009765, write_ts=, msg=packet number 8], 0 secs +1362692527.009765, log_policy +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG +1362692527.009775, post_delay_cb, [ts=1362692527.009775, post_ts=1362692527.009775, write_ts=, msg=packet number 9], 0 secs +1362692527.009775, log_policy +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG +1362692527.009855, post_delay_cb, [ts=1362692527.009855, post_ts=1362692527.009855, write_ts=, msg=packet number 10], 0 secs +1362692527.009855, log_policy +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG +1362692527.009887, post_delay_cb, [ts=1362692527.009887, post_ts=1362692527.009887, write_ts=, msg=packet number 11], 0 secs +1362692527.009887, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG +1362692527.011846, post_delay_cb, [ts=1362692527.011846, post_ts=1362692527.011846, write_ts=, msg=packet number 12], 0 secs +1362692527.011846, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG +1362692527.080828, post_delay_cb, [ts=1362692527.080828, post_ts=1362692527.080828, write_ts=, msg=packet number 13], 0 secs +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG +1362692527.080972, post_delay_cb, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14], 0 secs +1362692527.080972, log_policy +1362692527.080972, Pcap::file_done, <...>/get.trace diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/test.cut new file mode 100644 index 0000000000..a9978f6af9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-2/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692526.869344|1362692526.869344|packet number 1 +1362692526.939084|1362692526.939084|1362692526.939084|packet number 2 +1362692526.939378|1362692526.939378|1362692526.939378|packet number 3 +1362692526.939527|1362692526.939527|1362692526.939527|packet number 4 +1362692527.008509|1362692527.008509|1362692527.008509|packet number 5 +1362692527.009512|1362692527.009512|1362692527.009512|packet number 6 +1362692527.009721|1362692527.009721|1362692527.009721|packet number 7 +1362692527.009765|1362692527.009765|1362692527.009765|packet number 8 +1362692527.009775|1362692527.009775|1362692527.009775|packet number 9 +1362692527.009855|1362692527.009855|1362692527.009855|packet number 10 +1362692527.009887|1362692527.009887|1362692527.009887|packet number 11 +1362692527.011846|1362692527.011846|1362692527.011846|packet number 12 +1362692527.080828|1362692527.080828|1362692527.080828|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stdout new file mode 100644 index 0000000000..8e3892cb39 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/.stdout @@ -0,0 +1,58 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG +1362692526.869344, post_delay_cb, [ts=1362692526.869344, post_ts=1362692526.869344, write_ts=, msg=packet number 1], 0 secs +1362692526.869344, log_policy +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG +1362692526.939378, post_delay_cb, [ts=1362692526.939378, post_ts=1362692526.939378, write_ts=, msg=packet number 3], 0 secs +1362692526.939378, log_policy +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG +1362692527.008509, post_delay_cb, [ts=1362692526.939084, post_ts=1362692527.008509, write_ts=, msg=packet number 2], 69.0 msecs 424.86763 usecs +1362692527.008509, log_policy +1362692527.008509, post_delay_cb, [ts=1362692526.939527, post_ts=1362692527.008509, write_ts=, msg=packet number 4], 68.0 msecs 981.88591 usecs +1362692527.008509, log_policy +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG +1362692527.008509, post_delay_cb, [ts=1362692527.008509, post_ts=1362692527.008509, write_ts=, msg=packet number 5], 0 secs +1362692527.008509, log_policy +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG +1362692527.009721, post_delay_cb, [ts=1362692527.009721, post_ts=1362692527.009721, write_ts=, msg=packet number 7], 0 secs +1362692527.009721, log_policy +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG +1362692527.009775, post_delay_cb, [ts=1362692527.009775, post_ts=1362692527.009775, write_ts=, msg=packet number 9], 0 secs +1362692527.009775, log_policy +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG +1362692527.009887, post_delay_cb, [ts=1362692527.009887, post_ts=1362692527.009887, write_ts=, msg=packet number 11], 0 secs +1362692527.009887, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009512, post_ts=1362692527.011846, write_ts=, msg=packet number 6], 2.0 msecs 334.117889 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009765, post_ts=1362692527.011846, write_ts=, msg=packet number 8], 2.0 msecs 81.155777 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009855, post_ts=1362692527.011846, write_ts=, msg=packet number 10], 1.0 msec 991.033554 usecs +1362692527.011846, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG +1362692527.080828, post_delay_cb, [ts=1362692527.011846, post_ts=1362692527.080828, write_ts=, msg=packet number 12], 68.0 msecs 981.88591 usecs +1362692527.080828, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG +1362692527.080828, post_delay_cb, [ts=1362692527.080828, post_ts=1362692527.080828, write_ts=, msg=packet number 13], 0 secs +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14], 0 secs +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/test.cut new file mode 100644 index 0000000000..97420a0c5a --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-3/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692526.869344|1362692526.869344|packet number 1 +1362692526.939378|1362692526.939378|1362692526.939378|packet number 3 +1362692526.939084|1362692527.008509|1362692527.008509|packet number 2 +1362692526.939527|1362692527.008509|1362692527.008509|packet number 4 +1362692527.008509|1362692527.008509|1362692527.008509|packet number 5 +1362692527.009721|1362692527.009721|1362692527.009721|packet number 7 +1362692527.009775|1362692527.009775|1362692527.009775|packet number 9 +1362692527.009887|1362692527.009887|1362692527.009887|packet number 11 +1362692527.009512|1362692527.011846|1362692527.011846|packet number 6 +1362692527.009765|1362692527.011846|1362692527.011846|packet number 8 +1362692527.009855|1362692527.011846|1362692527.011846|packet number 10 +1362692527.011846|1362692527.080828|1362692527.080828|packet number 12 +1362692527.080828|1362692527.080828|1362692527.080828|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stdout new file mode 100644 index 0000000000..2032bf78c5 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/.stdout @@ -0,0 +1,58 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1] +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2] +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3] +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4] +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5] +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6] +1362692527.009512, post_delay_cb, [ts=1362692526.869344, post_ts=1362692527.009512, write_ts=, msg=packet number 1], 140.0 msecs 167.951584 usecs +1362692527.009512, log_policy +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7] +1362692527.009721, post_delay_cb, [ts=1362692526.939084, post_ts=1362692527.009721, write_ts=, msg=packet number 2], 70.0 msecs 636.987686 usecs +1362692527.009721, log_policy +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8] +1362692527.009765, post_delay_cb, [ts=1362692526.939378, post_ts=1362692527.009765, write_ts=, msg=packet number 3], 70.0 msecs 386.886597 usecs +1362692527.009765, log_policy +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9] +1362692527.009775, post_delay_cb, [ts=1362692526.939527, post_ts=1362692527.009775, write_ts=, msg=packet number 4], 70.0 msecs 247.888565 usecs +1362692527.009775, log_policy +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10] +1362692527.009855, post_delay_cb, [ts=1362692527.008509, post_ts=1362692527.009855, write_ts=, msg=packet number 5], 1.0 msec 346.111298 usecs +1362692527.009855, log_policy +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11] +1362692527.009887, post_delay_cb, [ts=1362692527.009512, post_ts=1362692527.009887, write_ts=, msg=packet number 6], 375.032425 usecs +1362692527.009887, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12] +1362692527.011846, post_delay_cb, [ts=1362692527.009721, post_ts=1362692527.011846, write_ts=, msg=packet number 7], 2.0 msecs 125.024796 usecs +1362692527.011846, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13] +1362692527.080828, post_delay_cb, [ts=1362692527.009765, post_ts=1362692527.080828, write_ts=, msg=packet number 8], 71.0 msecs 63.041687 usecs +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14] +1362692527.080972, post_delay_cb, [ts=1362692527.009775, post_ts=1362692527.080972, write_ts=, msg=packet number 9], 71.0 msecs 197.032928 usecs +1362692527.080972, log_policy +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb, [ts=1362692527.009855, post_ts=1362692527.080972, write_ts=, msg=packet number 10], 71.0 msecs 116.924286 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.009887, post_ts=1362692527.080972, write_ts=, msg=packet number 11], 71.0 msecs 84.976196 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.011846, post_ts=1362692527.080972, write_ts=, msg=packet number 12], 69.0 msecs 125.890732 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.080828, post_ts=1362692527.080972, write_ts=, msg=packet number 13], 144.004822 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14], 0 secs +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/test.cut new file mode 100644 index 0000000000..1aefd1e4e3 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-4/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692527.009512|1362692527.009512|packet number 1 +1362692526.939084|1362692527.009721|1362692527.009721|packet number 2 +1362692526.939378|1362692527.009765|1362692527.009765|packet number 3 +1362692526.939527|1362692527.009775|1362692527.009775|packet number 4 +1362692527.008509|1362692527.009855|1362692527.009855|packet number 5 +1362692527.009512|1362692527.009887|1362692527.009887|packet number 6 +1362692527.009721|1362692527.011846|1362692527.011846|packet number 7 +1362692527.009765|1362692527.080828|1362692527.080828|packet number 8 +1362692527.009775|1362692527.080972|1362692527.080972|packet number 9 +1362692527.009855|1362692527.080972|1362692527.080972|packet number 10 +1362692527.009887|1362692527.080972|1362692527.080972|packet number 11 +1362692527.011846|1362692527.080972|1362692527.080972|packet number 12 +1362692527.080828|1362692527.080972|1362692527.080972|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stderr new file mode 100644 index 0000000000..de5c61b2e8 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stderr @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692527.009512 warning: unable to evict delayed records for stream LOG queue_size=6, all re-delayed? +1362692527.011846 warning: unable to evict delayed records for stream LOG queue_size=6, all re-delayed? diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stdout new file mode 100644 index 0000000000..f4e9b4832a --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/.stdout @@ -0,0 +1,72 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.009721, post_delay_cb - done, [ts=1362692526.869344, post_ts=1362692527.009512, write_ts=, msg=packet number 1, redelayed=T] +1362692527.009721, log_policy +1362692527.009721, post_delay_cb - done, [ts=1362692526.939084, post_ts=1362692527.009512, write_ts=, msg=packet number 2, redelayed=T] +1362692527.009721, log_policy +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.009765, post_delay_cb - done, [ts=1362692526.939378, post_ts=1362692527.009512, write_ts=, msg=packet number 3, redelayed=T] +1362692527.009765, log_policy +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.009775, post_delay_cb - done, [ts=1362692526.939527, post_ts=1362692527.009512, write_ts=, msg=packet number 4, redelayed=T] +1362692527.009775, log_policy +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.009855, post_delay_cb - done, [ts=1362692527.008509, post_ts=1362692527.009512, write_ts=, msg=packet number 5, redelayed=T] +1362692527.009855, log_policy +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.009887, post_delay_cb - done, [ts=1362692527.009512, post_ts=1362692527.009512, write_ts=, msg=packet number 6, redelayed=T] +1362692527.009887, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080828, post_delay_cb - done, [ts=1362692527.009721, post_ts=1362692527.011846, write_ts=, msg=packet number 7, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - done, [ts=1362692527.009765, post_ts=1362692527.011846, write_ts=, msg=packet number 8, redelayed=T] +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, post_delay_cb - done, [ts=1362692527.009775, post_ts=1362692527.011846, write_ts=, msg=packet number 9, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb - done, [ts=1362692527.009855, post_ts=1362692527.011846, write_ts=, msg=packet number 10, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.009887, post_ts=1362692527.011846, write_ts=, msg=packet number 11, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.011846, post_ts=1362692527.011846, write_ts=, msg=packet number 12, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, post_delay_cb - done, [ts=1362692527.080828, post_ts=1362692527.080972, write_ts=, msg=packet number 13, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14, redelayed=T] +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/test.cut new file mode 100644 index 0000000000..768e039c8f --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-5/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692527.009512|1362692527.009721|packet number 1 +1362692526.939084|1362692527.009512|1362692527.009721|packet number 2 +1362692526.939378|1362692527.009512|1362692527.009765|packet number 3 +1362692526.939527|1362692527.009512|1362692527.009775|packet number 4 +1362692527.008509|1362692527.009512|1362692527.009855|packet number 5 +1362692527.009512|1362692527.009512|1362692527.009887|packet number 6 +1362692527.009721|1362692527.011846|1362692527.080828|packet number 7 +1362692527.009765|1362692527.011846|1362692527.080828|packet number 8 +1362692527.009775|1362692527.011846|1362692527.080972|packet number 9 +1362692527.009855|1362692527.011846|1362692527.080972|packet number 10 +1362692527.009887|1362692527.011846|1362692527.080972|packet number 11 +1362692527.011846|1362692527.011846|1362692527.080972|packet number 12 +1362692527.080828|1362692527.080972|1362692527.080972|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stdout new file mode 100644 index 0000000000..63e9bb4e93 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/.stdout @@ -0,0 +1,72 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692526.939084, post_delay_cb - re-delay, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692527.008509, post_delay_cb - done, [ts=1362692526.869344, post_ts=1362692526.939084, write_ts=, msg=packet number 1, redelayed=T] +1362692527.008509, log_policy +1362692527.008509, post_delay_cb - re-delay, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692527.008509, post_delay_cb - re-delay, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692527.008509, post_delay_cb - re-delay, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.009512, post_delay_cb - done, [ts=1362692526.939084, post_ts=1362692527.008509, write_ts=, msg=packet number 2, redelayed=T] +1362692527.009512, log_policy +1362692527.009512, post_delay_cb - done, [ts=1362692526.939378, post_ts=1362692527.008509, write_ts=, msg=packet number 3, redelayed=T] +1362692527.009512, log_policy +1362692527.009512, post_delay_cb - done, [ts=1362692526.939527, post_ts=1362692527.008509, write_ts=, msg=packet number 4, redelayed=T] +1362692527.009512, log_policy +1362692527.009512, post_delay_cb - re-delay, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.011846, post_delay_cb - done, [ts=1362692527.008509, post_ts=1362692527.009512, write_ts=, msg=packet number 5, redelayed=T] +1362692527.011846, log_policy +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.080828, post_delay_cb - done, [ts=1362692527.009512, post_ts=1362692527.011846, write_ts=, msg=packet number 6, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - done, [ts=1362692527.009721, post_ts=1362692527.011846, write_ts=, msg=packet number 7, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - done, [ts=1362692527.009765, post_ts=1362692527.011846, write_ts=, msg=packet number 8, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - done, [ts=1362692527.009775, post_ts=1362692527.011846, write_ts=, msg=packet number 9, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - done, [ts=1362692527.009855, post_ts=1362692527.011846, write_ts=, msg=packet number 10, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - done, [ts=1362692527.009887, post_ts=1362692527.011846, write_ts=, msg=packet number 11, redelayed=T] +1362692527.080828, log_policy +1362692527.080828, post_delay_cb - re-delay, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb - done, [ts=1362692527.011846, post_ts=1362692527.080828, write_ts=, msg=packet number 12, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, post_delay_cb - done, [ts=1362692527.080828, post_ts=1362692527.080972, write_ts=, msg=packet number 13, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, post_delay_cb - done, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14, redelayed=T] +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/test.cut new file mode 100644 index 0000000000..879b3eadfe --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-6/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692526.939084|1362692527.008509|packet number 1 +1362692526.939084|1362692527.008509|1362692527.009512|packet number 2 +1362692526.939378|1362692527.008509|1362692527.009512|packet number 3 +1362692526.939527|1362692527.008509|1362692527.009512|packet number 4 +1362692527.008509|1362692527.009512|1362692527.011846|packet number 5 +1362692527.009512|1362692527.011846|1362692527.080828|packet number 6 +1362692527.009721|1362692527.011846|1362692527.080828|packet number 7 +1362692527.009765|1362692527.011846|1362692527.080828|packet number 8 +1362692527.009775|1362692527.011846|1362692527.080828|packet number 9 +1362692527.009855|1362692527.011846|1362692527.080828|packet number 10 +1362692527.009887|1362692527.011846|1362692527.080828|packet number 11 +1362692527.011846|1362692527.080828|1362692527.080972|packet number 12 +1362692527.080828|1362692527.080972|1362692527.080972|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stdout new file mode 100644 index 0000000000..7df6131e92 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/.stdout @@ -0,0 +1,72 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692526.869344, post_delay_cb - re-delay, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1, redelayed=F] +1362692526.869344, post_delay_cb - done, [ts=1362692526.869344, post_ts=1362692526.869344, write_ts=, msg=packet number 1, redelayed=T] +1362692526.869344, log_policy +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692526.939084, post_delay_cb - re-delay, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2, redelayed=F] +1362692526.939084, post_delay_cb - done, [ts=1362692526.939084, post_ts=1362692526.939084, write_ts=, msg=packet number 2, redelayed=T] +1362692526.939084, log_policy +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692526.939378, post_delay_cb - re-delay, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3, redelayed=F] +1362692526.939378, post_delay_cb - done, [ts=1362692526.939378, post_ts=1362692526.939378, write_ts=, msg=packet number 3, redelayed=T] +1362692526.939378, log_policy +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692526.939527, post_delay_cb - re-delay, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4, redelayed=F] +1362692526.939527, post_delay_cb - done, [ts=1362692526.939527, post_ts=1362692526.939527, write_ts=, msg=packet number 4, redelayed=T] +1362692526.939527, log_policy +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.008509, post_delay_cb - re-delay, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5, redelayed=F] +1362692527.008509, post_delay_cb - done, [ts=1362692527.008509, post_ts=1362692527.008509, write_ts=, msg=packet number 5, redelayed=T] +1362692527.008509, log_policy +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009512, post_delay_cb - re-delay, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6, redelayed=F] +1362692527.009512, post_delay_cb - done, [ts=1362692527.009512, post_ts=1362692527.009512, write_ts=, msg=packet number 6, redelayed=T] +1362692527.009512, log_policy +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.009721, post_delay_cb - re-delay, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7, redelayed=F] +1362692527.009721, post_delay_cb - done, [ts=1362692527.009721, post_ts=1362692527.009721, write_ts=, msg=packet number 7, redelayed=T] +1362692527.009721, log_policy +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.009765, post_delay_cb - re-delay, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8, redelayed=F] +1362692527.009765, post_delay_cb - done, [ts=1362692527.009765, post_ts=1362692527.009765, write_ts=, msg=packet number 8, redelayed=T] +1362692527.009765, log_policy +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.009775, post_delay_cb - re-delay, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9, redelayed=F] +1362692527.009775, post_delay_cb - done, [ts=1362692527.009775, post_ts=1362692527.009775, write_ts=, msg=packet number 9, redelayed=T] +1362692527.009775, log_policy +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.009855, post_delay_cb - re-delay, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10, redelayed=F] +1362692527.009855, post_delay_cb - done, [ts=1362692527.009855, post_ts=1362692527.009855, write_ts=, msg=packet number 10, redelayed=T] +1362692527.009855, log_policy +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.009887, post_delay_cb - re-delay, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11, redelayed=F] +1362692527.009887, post_delay_cb - done, [ts=1362692527.009887, post_ts=1362692527.009887, write_ts=, msg=packet number 11, redelayed=T] +1362692527.009887, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.011846, post_delay_cb - re-delay, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12, redelayed=F] +1362692527.011846, post_delay_cb - done, [ts=1362692527.011846, post_ts=1362692527.011846, write_ts=, msg=packet number 12, redelayed=T] +1362692527.011846, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080828, post_delay_cb - re-delay, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13, redelayed=F] +1362692527.080828, post_delay_cb - done, [ts=1362692527.080828, post_ts=1362692527.080828, write_ts=, msg=packet number 13, redelayed=T] +1362692527.080828, log_policy +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, post_delay_cb - re-delay, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14, redelayed=F] +1362692527.080972, post_delay_cb - done, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14, redelayed=T] +1362692527.080972, log_policy +1362692527.080972, Pcap::file_done, <...>/get.trace diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/test.cut new file mode 100644 index 0000000000..a9978f6af9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test-7/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692526.869344|1362692526.869344|packet number 1 +1362692526.939084|1362692526.939084|1362692526.939084|packet number 2 +1362692526.939378|1362692526.939378|1362692526.939378|packet number 3 +1362692526.939527|1362692526.939527|1362692526.939527|packet number 4 +1362692527.008509|1362692527.008509|1362692527.008509|packet number 5 +1362692527.009512|1362692527.009512|1362692527.009512|packet number 6 +1362692527.009721|1362692527.009721|1362692527.009721|packet number 7 +1362692527.009765|1362692527.009765|1362692527.009765|packet number 8 +1362692527.009775|1362692527.009775|1362692527.009775|packet number 9 +1362692527.009855|1362692527.009855|1362692527.009855|packet number 10 +1362692527.009887|1362692527.009887|1362692527.009887|packet number 11 +1362692527.011846|1362692527.011846|1362692527.011846|packet number 12 +1362692527.080828|1362692527.080828|1362692527.080828|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stderr @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stdout new file mode 100644 index 0000000000..07913cca22 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/.stdout @@ -0,0 +1,58 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_packet, 1 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1] +1362692526.939084, post_delay_cb, [ts=1362692526.869344, post_ts=1362692526.939084, write_ts=, msg=packet number 1], 69.0 msecs 740.056992 usecs +1362692526.939084, log_policy +1362692526.939084, new_packet, 2 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2] +1362692526.939378, new_packet, 3 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3] +1362692526.939527, new_packet, 4 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4] +1362692527.008509, post_delay_cb, [ts=1362692526.939084, post_ts=1362692527.008509, write_ts=, msg=packet number 2], 69.0 msecs 424.86763 usecs +1362692527.008509, log_policy +1362692527.008509, post_delay_cb, [ts=1362692526.939378, post_ts=1362692527.008509, write_ts=, msg=packet number 3], 69.0 msecs 130.897522 usecs +1362692527.008509, log_policy +1362692527.008509, post_delay_cb, [ts=1362692526.939527, post_ts=1362692527.008509, write_ts=, msg=packet number 4], 68.0 msecs 981.88591 usecs +1362692527.008509, log_policy +1362692527.008509, new_packet, 5 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5] +1362692527.009512, post_delay_cb, [ts=1362692527.008509, post_ts=1362692527.009512, write_ts=, msg=packet number 5], 1.0 msec 3.026962 usecs +1362692527.009512, log_policy +1362692527.009512, new_packet, 6 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6] +1362692527.009721, new_packet, 7 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7] +1362692527.009765, new_packet, 8 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8] +1362692527.009775, new_packet, 9 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9] +1362692527.009855, new_packet, 10 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10] +1362692527.009887, new_packet, 11 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11] +1362692527.011846, post_delay_cb, [ts=1362692527.009512, post_ts=1362692527.011846, write_ts=, msg=packet number 6], 2.0 msecs 334.117889 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009721, post_ts=1362692527.011846, write_ts=, msg=packet number 7], 2.0 msecs 125.024796 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009765, post_ts=1362692527.011846, write_ts=, msg=packet number 8], 2.0 msecs 81.155777 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009775, post_ts=1362692527.011846, write_ts=, msg=packet number 9], 2.0 msecs 71.142197 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009855, post_ts=1362692527.011846, write_ts=, msg=packet number 10], 1.0 msec 991.033554 usecs +1362692527.011846, log_policy +1362692527.011846, post_delay_cb, [ts=1362692527.009887, post_ts=1362692527.011846, write_ts=, msg=packet number 11], 1.0 msec 959.085464 usecs +1362692527.011846, log_policy +1362692527.011846, new_packet, 12 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12] +1362692527.080828, post_delay_cb, [ts=1362692527.011846, post_ts=1362692527.080828, write_ts=, msg=packet number 12], 68.0 msecs 981.88591 usecs +1362692527.080828, log_policy +1362692527.080828, new_packet, 13 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13] +1362692527.080972, new_packet, 14 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14] +1362692527.080972, Pcap::file_done, <...>/get.trace +1362692527.080972, post_delay_cb, [ts=1362692527.080828, post_ts=1362692527.080972, write_ts=, msg=packet number 13], 144.004822 usecs +1362692527.080972, log_policy +1362692527.080972, post_delay_cb, [ts=1362692527.080972, post_ts=1362692527.080972, write_ts=, msg=packet number 14], 0 secs +1362692527.080972, log_policy diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/test.cut new file mode 100644 index 0000000000..733d2afc29 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-test/test.cut @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +ts|post_ts|write_ts|msg +1362692526.869344|1362692526.939084|1362692526.939084|packet number 1 +1362692526.939084|1362692527.008509|1362692527.008509|packet number 2 +1362692526.939378|1362692527.008509|1362692527.008509|packet number 3 +1362692526.939527|1362692527.008509|1362692527.008509|packet number 4 +1362692527.008509|1362692527.009512|1362692527.009512|packet number 5 +1362692527.009512|1362692527.011846|1362692527.011846|packet number 6 +1362692527.009721|1362692527.011846|1362692527.011846|packet number 7 +1362692527.009765|1362692527.011846|1362692527.011846|packet number 8 +1362692527.009775|1362692527.011846|1362692527.011846|packet number 9 +1362692527.009855|1362692527.011846|1362692527.011846|packet number 10 +1362692527.009887|1362692527.011846|1362692527.011846|packet number 11 +1362692527.011846|1362692527.080828|1362692527.080828|packet number 12 +1362692527.080828|1362692527.080972|1362692527.080972|packet number 13 +1362692527.080972|1362692527.080972|1362692527.080972|packet number 14 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-2/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-2/.stderr new file mode 100644 index 0000000000..124879e152 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-2/.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 634 and <...>/static-errors.zeek, line 12: type clash (Log::PostDelayCallback and post_delay_cb) +error in <...>/static-errors.zeek, line 12 and <...>/main.zeek, line 634: type mismatch (post_delay_cb and Log::PostDelayCallback) +error in <...>/static-errors.zeek, line 12: argument type mismatch in function call (Log::delay(id, to_any_coercerec, post_delay_cb)) diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors/.stderr new file mode 100644 index 0000000000..8ec6765e9d --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors/.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 634 and <...>/static-errors.zeek, line 16: type clash (Log::PostDelayCallback and post_delay_cb) +error in <...>/static-errors.zeek, line 16 and <...>/main.zeek, line 634: type mismatch (post_delay_cb and Log::PostDelayCallback) +error in <...>/static-errors.zeek, line 16: argument type mismatch in function call (Log::delay(id, to_any_coercerec, post_delay_cb)) diff --git a/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek b/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek new file mode 100644 index 0000000000..9c83f4bdc4 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek @@ -0,0 +1,108 @@ +# @TEST-DOC: Basic tests. + +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout +# @TEST-EXEC: btest-diff .stderr +# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + + +@TEST-START-FILE test.zeek +# Used by all tests below. + +# Debug printing +global packet_count = 0; +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done"; + } + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + write_ts: time &log &optional; + uid: string &log; + msg: string &log; +}; + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy", rec$uid; + rec$write_ts = network_time(); + } + +event zeek_init() + { + Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]); + } + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value"); + Log::write(LOG, info); + } +@TEST-END-FILE test.zeek + + +# Delay and immediately release. +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); + Log::delay_finish(id, rec, token); + } + +@TEST-START-NEXT +# Delay and immediately release, twice. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + print network_time(), "log_stream_policy", id, rec$uid; + + local token1 = Log::delay(id, rec); + Log::delay_finish(id, rec, token1); + + local token2 = Log::delay(id, rec); + Log::delay_finish(id, rec, token2); + } + +@TEST-START-NEXT +# Delay once, never release. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + print network_time(), "log_stream_policy", id, rec$uid; + + Log::delay(id, rec); + } + +@TEST-START-NEXT +# Delay twice, never release. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + print network_time(), "log_stream_policy", id, rec$uid; + + Log::delay(id, rec); + Log::delay(id, rec); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/coerce.zeek b/testing/btest/scripts/base/frameworks/logging/delay/coerce.zeek new file mode 100644 index 0000000000..45f003b225 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/coerce.zeek @@ -0,0 +1,80 @@ +# @TEST-DOC: Check usage delay in when statements. + +# @TEST-EXEC: zeek -B tm,logging -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + +@TEST-START-FILE test.zeek +# Debug printing +global packet_count = 0; +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done"; + } + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + write_ts: time &log &optional; + uid: string &log; + msg: string &log; +}; + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy", rec$uid; + rec$write_ts = network_time(); + } + +event zeek_init() + { + Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]); + } +@TEST-END-FILE test.zeek + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb", rec2; + return T; + }); + } + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + + # Using an anonymous record type with field reordering. + # + # This is quirky: Because internally this record is coerced + # very early on, the hooks and delay pipeline work with a different + # record val ptr. So an update of this record is not visible! + local info = [$msg="initial-value", $ts=network_time(), $uid=c$uid]; + + Log::write(LOG, info); + + # Not visible after delay due to record coercion. + print network_time(), "Updating info$msg after write!"; + info$msg = "after-write"; + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/delay-cb-redelay.zeek b/testing/btest/scripts/base/frameworks/logging/delay/delay-cb-redelay.zeek new file mode 100644 index 0000000000..36e2b00e32 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/delay-cb-redelay.zeek @@ -0,0 +1,118 @@ +# @TEST-DOC: Calling Log::delay() during the post delay callback() +# +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + +redef Log::default_max_delay_interval = 50msec; + +@TEST-START-FILE test.zeek + +global packet_count = 0; +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done"; + } + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + write_ts: time &log &optional; + uid: string &log; + msg: string &log; +}; + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy", rec$uid; + rec$write_ts = network_time(); + } + +event zeek_init() + { + Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]); + } + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value"); + Log::write(LOG, info); + } +@TEST-END-FILE test.zeek + +# Delay the given record twice using a nested lambda. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + print network_time(), "post_delay_cb - 1", rec2, delayed_for; + + Log::delay(LOG, rec2, function[now](rec3: Info, id3: Log::ID): bool { + local delayed_for2 = network_time() - now; + rec3$msg = fmt("%s delayed %s", rec3$msg, delayed_for2); + print network_time(), "post_delay_cb - 2", rec3, delayed_for2; + return T; + }); + + return T; + }); + + when [rec] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + } + } + +@TEST-START-NEXT +# Delay the given record twice using a nested lambda, but also immediate release. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token1 = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + print network_time(), "post_delay_cb - 1, delaying again", rec2, delayed_for; + + local token2 = Log::delay(LOG, rec2, function[now](rec3: Info, id3: Log::ID): bool { + local delayed_for2 = network_time() - now; + rec3$msg = fmt("%s delayed %s", rec3$msg, delayed_for2); + print network_time(), "post_delay_cb - 2", rec3, delayed_for2; + return T; + }); + + print network_time(), "post_delay_cb - 1, delay_finish", rec2, delayed_for; + Log::delay_finish(LOG, rec2, token2); + + return T; + }); + + Log::delay_finish(LOG, rec, token1); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/delay-cb.zeek b/testing/btest/scripts/base/frameworks/logging/delay/delay-cb.zeek new file mode 100644 index 0000000000..0fcb07d5a0 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/delay-cb.zeek @@ -0,0 +1,223 @@ +# @TEST-DOC: Test the post delay callback and timing behavior. +# +# During new_connection() a Log::write() happens. Each packet is printed +# to observe timing behavior. +# +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + +@TEST-START-FILE test.zeek + +global packet_count = 0; +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done"; + } + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + write_ts: time &log &optional; + uid: string &log; + msg: string &log; +}; + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy", rec$uid; + rec$write_ts = network_time(); + } + +event zeek_init() + { + Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]); + } + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value"); + Log::write(LOG, info); + } +@TEST-END-FILE test.zeek + +# Basic delay() test, no delay_finish() +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + when [rec] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + } + } + +# @TEST-START-NEXT +# Basic delay() test with delay_finish(), expect callback to be invoked +# right at Log::delay_finish() +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + when [id, rec, token] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + Log::delay_finish(id, rec, token); + } + } + +# @TEST-START-NEXT +# Basic delay() test with two callbacks but just one Log::delay_finish() call. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token1 = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb - 1", rec2, delayed_for; + return T; + }); + + local token2 = Log::delay(LOG, rec, function(rec2: Info, id2: Log::ID): bool { + print network_time(), "post_delay_cb - 2", rec2; + return T; + }); + + when [id, rec, token1] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + Log::delay_finish(id, rec, token1); + } + } + +# @TEST-START-NEXT +# Basic delay() test two callbacks and two Log::delay_finish() calls. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token1 = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb - 1", rec2, delayed_for; + return T; + }); + + local token2 = Log::delay(LOG, rec, function(rec2: Info, id2: Log::ID): bool { + print network_time(), "post_delay_cb - 2", rec2; + return T; + }); + + when [id, rec, token1, token2] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + Log::delay_finish(id, rec, token1); + Log::delay_finish(id, rec, token2); + } + } + +# @TEST-START-NEXT +# The delay callback suppresses the log by return F. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + print network_time(), "post_delay_cb", rec2, delayed_for; + return F; + }); + + when [id, rec, token] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + Log::delay_finish(id, rec, token); + } + } + +# @TEST-START-NEXT +# Do a delay and immediate release with a callback. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token = Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + Log::delay_finish(id, rec, token); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek b/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek new file mode 100644 index 0000000000..1e713bb761 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek @@ -0,0 +1,72 @@ +# @TEST-DOC: Test some error cases + +# @TEST-EXEC: zeek -b -r $TRACES/http/get.trace %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER='$SCRIPTS/diff-remove-abspath | sed -r "s/0x[0-9a-z]+/0x<...>/g"' btest-diff .stderr + +redef enum Log::ID += { LOG }; + +event zeek_init() + { + # Not within a log write + Log::delay(LOG, []); + } + +@TEST-START-NEXT +@load base/protocols/conn + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + # Not the same record as the one from the hook. + Log::delay(id, copy(rec)); + } + +@TEST-START-NEXT +@load base/protocols/conn +@load base/protocols/dns + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + # Wrong stream identifier + Log::delay(DNS::LOG, rec); + } + +@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() + local token = Log::delay(id, rec); + Log::delay_finish(id, copy(rec), token); + } + +@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. + local token = Log::delay(id, rec); + Log::delay_finish(id, rec, token); + Log::delay_finish(id, rec, token); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/example.zeek b/testing/btest/scripts/base/frameworks/logging/delay/example.zeek new file mode 100644 index 0000000000..99d1499f5f --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/example.zeek @@ -0,0 +1,58 @@ +# @TEST-DOC: Example using lookup_addr() + +# @TEST-EXEC: zeek -b -r $TRACES/http/get.trace %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout +# @TEST-EXEC: btest-diff .stderr +# @TEST-EXEC: zeek-cut -m ts uid id.orig_h orig_name id.resp_h resp_name < conn.log > conn.cut +# @TEST-EXEC: btest-diff conn.cut + + +# Enrich conn.log with lookup_addr() result +@load base/protocols/conn + +redef record Conn::Info += { + orig_name: string &log &optional; + resp_name: string &log &optional; +}; + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + if ( id != Conn::LOG ) + return; + + print network_time(), "log_stream_policy", id, rec; + + local token1 = Log::delay(id, rec, function(rec2: Conn::Info, id2: Log::ID): bool { + print network_time(), "token1 delay hook"; + return T; + }); + local token2 = Log::delay(id, rec, function(rec2: Conn::Info, id2: Log::ID): bool { + print network_time(), "token2 delay hook"; + return T; + }); + + when [id, rec, token1] ( local orig_name = lookup_addr(rec$id$orig_h) ) + { + rec$orig_name = orig_name; + Log::delay_finish(id, rec, token1); + } + timeout 150msec + { + Reporter::warning(fmt("lookup_addr timeout for %s", rec$id$orig_h)); + } + + when [id, rec, token2] ( local resp_name = lookup_addr(rec$id$resp_h) ) + { + rec$resp_name = resp_name; + Log::delay_finish(id, rec, token2); + } + timeout 150msec + { + Reporter::warning(fmt("lookup_addr timeout for %s", rec$id$resp_h)); + } + } + +event Pcap::file_done(path: string) + { + print network_time(), "Pcap::file_done"; + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/multi-write.zeek b/testing/btest/scripts/base/frameworks/logging/delay/multi-write.zeek new file mode 100644 index 0000000000..9283cbffcd --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/multi-write.zeek @@ -0,0 +1,87 @@ +# @TEST-DOC: Test the behavior when the same record is written twice. Each Log::write() is delayed independenly. In the test below, the second Log::write() is not delayed. + +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + +@TEST-START-FILE test.zeek + +global packet_count = 0; +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done"; + } + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + write_ts: time &log &optional; + uid: string &log; + msg: string &log; +}; + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy", rec$uid, rec$msg; + rec$write_ts = network_time(); + } + +event zeek_init() + { + Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]); + } +@TEST-END-FILE test.zeek + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value"); + Log::write(LOG, info); + # This becomes visible on the first write. + info$msg = "initial-value-second-write"; + Log::write(LOG, info); + } + +global write = 0; +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + ++write; + + # Second write is directly going to the filters. + if ( write == 2 ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, write, rec; + + Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + when [rec] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + } + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/nested-write.zeek b/testing/btest/scripts/base/frameworks/logging/delay/nested-write.zeek new file mode 100644 index 0000000000..4ba803ee67 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/nested-write.zeek @@ -0,0 +1,112 @@ +# @TEST-DOC: Test the behavior when a Log::write() happens within Log::log_stream_policy(), or within a post_delay_cb hook. + +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: touch test.log && zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut +# +# @TEST-EXEC: touch test-other.log && zeek-cut -m -F'|' < test-other.log > test-other.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test-other.cut + +@TEST-START-FILE test.zeek + +# Debug printing +global packet_count = 0; +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done"; + } + +redef enum Log::ID += { + LOG, + LOG_OTHER, +}; + +type Info: record { + ts: time &log; + write_ts: time &log &optional; + uid: string &log; + msg: string &log; +}; + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy", rec$uid, id, rec$msg; + rec$write_ts = network_time(); + } + +event zeek_init() + { + Log::create_stream(LOG, [$columns=Info, $path="test", $policy=log_policy]); + Log::create_stream(LOG_OTHER, [$columns=Info, $path="test-other", $policy=log_policy]); + } + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + local info = Info($ts=network_time(), $uid=c$uid, $msg="inital-value"); + Log::write(LOG, info); + } +@TEST-END-FILE test.zeek + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + local now = network_time(); + print now, "log_stream_policy", id, rec; + + if ( id != LOG ) + return; + + # Send to the other log. + Log::write(LOG_OTHER, rec); + + Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + when [rec] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + } + } + +@TEST-START-NEXT +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + local now = network_time(); + print now, "log_stream_policy", id, rec; + + if ( id != LOG ) + return; + + Log::delay(LOG, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$msg = fmt("%s delayed %s", rec2$msg, delayed_for); + print network_time(), "post_delay_cb", rec2, delayed_for; + Log::write(LOG_OTHER, rec2); + + return T; + }); + + when [rec] ( T == F ) + { + } + timeout 10msec + { + print network_time(), "when timeout", rec; + } + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/queue-setter.zeek b/testing/btest/scripts/base/frameworks/logging/delay/queue-setter.zeek new file mode 100644 index 0000000000..447fe3b583 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/queue-setter.zeek @@ -0,0 +1,142 @@ +# @TEST-DOC: Changing queue parameters while writes are pending. + +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + +@TEST-START-FILE test.zeek +# Used by all tests below. + +# Debug printing +global packet_count = 0; + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + post_ts: time &log &optional; + write_ts: time &log &optional; + msg: string &log; +}; + +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + local info = Info($ts=network_time(), $msg=fmt("packet number %s", packet_count)); + Log::write(LOG, info); + } + + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy"; + rec$write_ts = network_time(); + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done", p; + } + +@TEST-END-FILE test.zeek +# Delay records for a long time, reduce queue size after 10 packets to 3. + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=10sec, + ]); + } + +event new_packet(c: connection, p: pkt_hdr) &priority=-5 + { + if ( packet_count == 10 ) + { + print network_time(), "set_max_delay_queue_size to 3"; + Log::set_max_delay_queue_size(LOG, 3); + } + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$post_ts = network_time(); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + } + +# @TEST-START-NEXT +# +# Delay records for a long time, reduce queue size after 10 packets to 3, +# re-delay all records once, provoking failure to free any space in the +# queue. +# +redef record Info += { + redelayed: bool &default=F; +}; + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=10sec, + ]); + } + +function post_delay_cb(rec: Info, id: Log::ID): bool + { + if ( ! rec$redelayed ) + { + print network_time(), "post_delay_cb - re-delay", rec; + rec$post_ts = network_time(); + rec$redelayed = T; + Log::delay(id, rec, post_delay_cb); + return T; + } + + + print network_time(), "post_delay_cb - done", rec; + return T; + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(id, rec, post_delay_cb); + } + +event new_packet(c: connection, p: pkt_hdr) &priority=-5 + { + if ( packet_count == 10 ) + { + print network_time(), "set_max_delay_queue_size to 3"; + Log::set_max_delay_queue_size(LOG, 3); + } + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/queue-test.zeek b/testing/btest/scripts/base/frameworks/logging/delay/queue-test.zeek new file mode 100644 index 0000000000..1e010efec2 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/queue-test.zeek @@ -0,0 +1,340 @@ +# @TEST-DOC: Delay queue testing. + +# @TEST-EXEC: zeek -B logging,tm -b -r $TRACES/http/get.trace test.zeek %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +# @TEST-EXEC: zeek-cut -m -F'|' < test.log > test.cut +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff test.cut + +@TEST-START-FILE test.zeek +# Used by all tests below. + +# Debug printing +global packet_count = 0; + +redef enum Log::ID += { + LOG +}; + +type Info: record { + ts: time &log; + post_ts: time &log &optional; + write_ts: time &log &optional; + msg: string &log; +}; + +event new_packet(c: connection, p: pkt_hdr) + { + ++packet_count; + print network_time(), "new_packet", packet_count; + local info = Info($ts=network_time(), $msg=fmt("packet number %s", packet_count)); + Log::write(LOG, info); + } + + +hook log_policy(rec: Info, id: Log::ID, filter: Log::Filter) + { + print network_time(), "log_policy"; + rec$write_ts = network_time(); + } + +event Pcap::file_done(p: string) + { + print network_time(), "Pcap::file_done", p; + } + +@TEST-END-FILE test.zeek + +# Delay every record by 1msec. +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=1msec, + ]); + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$post_ts = network_time(); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + } + +# @TEST-START-NEXT +# +# Delay every record, but call Log::delay_finish() immediately afterwards +# through an event. + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=1msec, + ]); + } + +event release_delay(rec: Info, token: Log::DelayToken) + { + Log::delay_finish(LOG, rec, token); + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id; + + local token = Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$post_ts = network_time(); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + event release_delay(rec, token); + } + +# @TEST-START-NEXT +# +# Delay every record, and for every other record call Log::delay_finish() +# immediately afterwards via an event. + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=1msec, + ]); + } + +event release_delay(rec: Info, token: Log::DelayToken) + { + Log::delay_finish(LOG, rec, token); + } + +global write = 0; + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + ++write; + + local now = network_time(); + + print now, "log_stream_policy", id; + + local token = Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$post_ts = network_time(); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + + if ( write % 2 == 1 ) + event release_delay(rec, token); + + } + +# @TEST-START-NEXT + +# Delay every entry by 10 seconds, but set queue size to 5 such that +# entries are evicted when the queue size is reached. + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=10sec, + $max_delay_queue_size=5, + ]); + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(id, rec, function[now](rec2: Info, id2: Log::ID): bool { + local delayed_for = network_time() - now; + rec2$post_ts = network_time(); + print network_time(), "post_delay_cb", rec2, delayed_for; + return T; + }); + } + + +# @TEST-START-NEXT + +# Re-delaying works even if that results in more forceful expiration. +redef record Info += { + redelayed: bool &default=F; +}; + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=10sec, + $max_delay_queue_size=5, + ]); + } + +function post_delay_cb(rec: Info, id: Log::ID): bool + { + if ( ! rec$redelayed ) + { + print network_time(), "post_delay_cb - re-delay", rec; + rec$post_ts = network_time(); + rec$redelayed = T; + Log::delay(id, rec, post_delay_cb); + return T; + } + + + print network_time(), "post_delay_cb - done", rec; + return T; + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(id, rec, post_delay_cb); + } + +# @TEST-START-NEXT + +# Re-delay once after the delay expired. +redef record Info += { + redelayed: bool &default=F; +}; + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=1msec, + ]); + } + +function post_delay_cb(rec: Info, id: Log::ID): bool + { + if ( ! rec$redelayed ) + { + print network_time(), "post_delay_cb - re-delay", rec; + rec$post_ts = network_time(); + rec$redelayed = T; + Log::delay(id, rec, post_delay_cb); + return T; + } + + + print network_time(), "post_delay_cb - done", rec; + return T; + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + Log::delay(id, rec, post_delay_cb); + } + +# @TEST-START-NEXT + +# Re-delay once after Log::delay_finish() +redef record Info += { + redelayed: bool &default=F; +}; + +event release_delay(rec: Info, token: Log::DelayToken) + { + Log::delay_finish(LOG, rec, token); + } + + +event zeek_init() + { + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=1msec, + ]); + } + +function post_delay_cb(rec: Info, id: Log::ID): bool + { + if ( ! rec$redelayed ) + { + print network_time(), "post_delay_cb - re-delay", rec; + rec$post_ts = network_time(); + rec$redelayed = T; + local token = Log::delay(id, rec, post_delay_cb); + + event release_delay(rec, token); + return T; + } + + + print network_time(), "post_delay_cb - done", rec; + return T; + } + +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + local now = network_time(); + + print now, "log_stream_policy", id, rec; + + local token = Log::delay(id, rec, post_delay_cb); + + event release_delay(rec, token); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek b/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek new file mode 100644 index 0000000000..40281ac26f --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek @@ -0,0 +1,33 @@ +# @TEST-DOC: Test bad signature of callback function. + +# @TEST-EXEC-FAIL: zeek -b -r $TRACES/http/get.trace %INPUT +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff .stderr + +@load base/protocols/conn + +# PostDelayCallback needs to return a bool +function post_delay_cb(rec: Conn::Info, id: Log::ID) + { + print "post_delay_cb"; + } + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + Log::delay(id, rec, post_delay_cb); + } + + +# @TEST-START-NEXT +@load base/protocols/conn + +# PostDelayCallback needs to return a bool +function post_delay_cb(rec: Conn::Info, id: Log::ID): count + { + print "post_delay_cb"; + return 1; + } + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + Log::delay(id, rec, post_delay_cb); + }