diff --git a/CHANGES b/CHANGES index f1e3217319..a03e0e1bf1 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,99 @@ +6.2.0-dev.218 | 2023-12-01 12:04:32 +0100 + + * logging: ref() to record_ref() renaming (Arne Welzel, Corelight) + + * logging: Fix typos from review (Arne Welzel, Corelight) + + * logging/Manager: Make LogDelayExpiredTimer an implementation detail (Arne Welzel, Corelight) + + The only reason this was a private component of Manager was to access + the Stream's function. Use a generic callback and a lambda to avoid + that exposure. + + * logging/WriteToFilters: Use range-based for loop (Arne Welzel, Corelight) + + * testing/btest: Log::delay() from JavaScript (Arne Welzel, Corelight) + + * NEWS: Entry for delayed log writes (Arne Welzel, Corelight) + + * Bump doc submodule to branch (Arne Welzel, Corelight) + + * logging: Do not keep delay state persistent (Arne Welzel, Corelight) + + If Log::remove_stream() and Log::create_stream() is called for a stream, + do not restore the previously used max delay or max queue size. + + * logging: delay documentation polishing (Arne Welzel, Corelight) + + Based on PR feedback. + + * logging: Better error messages for invalid Log::delay() calls (Arne Welzel, Corelight) + + Add a test for Log::delay() usage within filter policy hooks, too. + + * logging/Manager: Implement DelayTokenType as an actual opaque (Arne Welzel, Corelight) + + With a bit of tweaking in the JavaScript plugin to support opaque types, this + will allow the delay functionality to work there, too. + + Making the LogDelayToken an actual opaque seems reasonable, too. It's not + supposed to be user inspected. + + * logging: Implement get_delay_queue_size() (Arne Welzel, Corelight) + + Primarily for introspection given that re-delaying may exceed + queue sizes. + + * logging: Introduce Log::delay() and Log::delay_finish() (Arne Welzel, Corelight) + + 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. + + * logging/Manager: zeek::detail'ify (Arne Welzel, Corelight) + + Introducing zeek::logging::detail requires detail:: references to be + qualified as preparation. + + * logging/Manager: Split Write() (Arne Welzel, Corelight) + + If we delay in the stream policy hook, we'll need to resume writing + to the attached filters later on. Prepare for that by splitting out + the filter processing. + + * Timer: Add LOG_DELAY_EXPIRE timer type (Arne Welzel, Corelight) + + * Ascii: Remove extra include (Arne Welzel, Corelight) + + Should not be needed, not sure what I was thinking. + 6.2.0-dev.200 | 2023-11-30 10:16:13 +0100 * GH-3473: OpaqueVal: Register TelemetryVals, too (Arne Welzel, Corelight) diff --git a/NEWS b/NEWS index 5e72aa73f2..07e6af35b6 100644 --- a/NEWS +++ b/NEWS @@ -45,6 +45,30 @@ New Functionality pattern. For observability, a new bif ``table_pattern_matcher_stats()`` can be used to gather ``MatcherStats``. +- Support for delaying log writes. + + The logging framework offers two new functions ``Log::delay()`` and ``Log::delay_finish()`` + to delay a ``Log::write()`` operation. This new functionality allows delaying of + a specific log record within the logging pipeline for a variable but bounded + amount of time. This can be used, for example, to query and wait for additional + information to attach to the pending record, or even change its final verdict. + + Conceptually, delaying a log record happens after the execution of the global + ``Log::log_stream_policy`` hook for a given ``Log::write()`` and before the + execution of filter policy hooks. Any mutation of the log record within the + delay period will be visible to filter policy hooks. Calling ``Log::delay()`` + is currently only allowed within the context of the ``Log::log_stream_policy`` hook + for the active ``Log::write()` operation (or during the execution of post delay callbacks). + While this may appear restrictive, it makes it explicit which ``Log::write()`` + operation is subject to the delay. + + Interactions, semantics and conflicts of this feature when writing the same + log record multiple times to the same or different log streams need to be taken + into consideration by script writers. + + Given this is the first iteration of this feature, feedback around usability and + use-cases that aren't covered are more than welcome. + Changed Functionality --------------------- diff --git a/VERSION b/VERSION index 785e7cd068..546855ce2b 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -6.2.0-dev.200 +6.2.0-dev.218 diff --git a/doc b/doc index 39b10c9f28..b49a36577b 160000 --- a/doc +++ b/doc @@ -1 +1 @@ -Subproject commit 39b10c9f2874f5d09751a36e57a12bb77f10c9af +Subproject commit b49a36577bd3b02db570e6dee682cec0176bf26f diff --git a/scripts/base/frameworks/logging/main.zeek b/scripts/base/frameworks/logging/main.zeek index f901b97e97..0a55d25a38 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,24 @@ 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. + ## + ## This value can be increased using :zeek:see:`Log::set_max_delay_interval` + ## after the stream has been created. + ## + ## .. :zeek:see:`Log::default_max_delay_interval` + ## .. :zeek:see:`Log::set_max_delay_interval` + max_delay_interval: interval &default=default_max_delay_interval; + + ## Maximum delay queue size of this stream. + ## + ## This value can be changed using :zeek:see:`Log::set_max_delay_queue_size` + ## after the stream has been created. + ## + ## .. :zeek:see:`Log::default_max_delay_queue_size` + ## .. :zeek:see:`Log::set_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 +631,109 @@ 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. + ## + ## Functions of this type take the same arguments as :zeek:see:`Log::StreamPolicyHook` + ## and act as a callback passed to zeek:see:`Log::delay`. They execute + ## just before the record is forwarded to the individual log filters. + ## + ## Returning ``F`` 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: opaque of LogDelayToken; + + ## Represents a post delay callback that simply returns T. This is used + ## as a default value for :zeek:see:`Log::delay` and ignored internally. + 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 increments a reference count that can subsequently + ## be decremented 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_cb* is invoked when the delay completed. + ## + ## The *post_delay_cb* function can extend the delay by invoking + ## :zeek:see:`Log::delay` again. There's no limit to how often a write + ## can be re-delayed. Further, it can discard the log record altogether + ## by returning ``F``. If *post_delay_cb* is not provided, the behavior + ## is equivalent to a no-op callback solely returning ``T``. + ## + ## id: The ID associated with a logging stream. + ## + ## rec: The 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: The 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; + + ## Get the current size of the delay queue for a stream. + ## + ## id: The ID associated with a logging stream. + ## + ## Returns: The current size of the delay queue, or -1 on error. + global get_delay_queue_size: function(id: Log::ID): int; } global all_streams: table[ID] of Stream = table(); @@ -878,3 +1010,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; + + 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 ( ! Log::__set_max_delay_queue_size(id, max_size) ) + return F; + + all_streams[id]$max_delay_queue_size = max_size; + + return T; + } + +function get_delay_queue_size(id: Log::ID): int + { + return Log::__get_delay_queue_size(id); + } diff --git a/src/Timer.cc b/src/Timer.cc index be3c360afa..ef2763071a 100644 --- a/src/Timer.cc +++ b/src/Timer.cc @@ -49,6 +49,7 @@ const char* TimerNames[] = { "TimerMgrExpireTimer", "ThreadHeartbeat", "UnknownProtocolExpire", + "LogDelayExpire", }; const char* timer_type_to_string(TimerType type) { return TimerNames[type]; } diff --git a/src/Timer.h b/src/Timer.h index f6225f80f8..ff535f64e1 100644 --- a/src/Timer.h +++ b/src/Timer.h @@ -49,8 +49,9 @@ enum TimerType : uint8_t { TIMER_TIMERMGR_EXPIRE, TIMER_THREAD_HEARTBEAT, TIMER_UNKNOWN_PROTOCOL_EXPIRE, + TIMER_LOG_DELAY_EXPIRE, }; -constexpr int NUM_TIMER_TYPES = int(TIMER_UNKNOWN_PROTOCOL_EXPIRE) + 1; +constexpr int NUM_TIMER_TYPES = int(TIMER_LOG_DELAY_EXPIRE) + 1; extern const char* timer_type_to_string(TimerType type); diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index 01844e596c..4c61c20de9 100644 --- a/src/logging/Manager.cc +++ b/src/logging/Manager.cc @@ -3,6 +3,7 @@ #include "zeek/logging/Manager.h" #include +#include #include #include @@ -13,6 +14,7 @@ #include "zeek/Func.h" #include "zeek/IntrusivePtr.h" #include "zeek/NetVar.h" +#include "zeek/OpaqueVal.h" #include "zeek/RunState.h" #include "zeek/Type.h" #include "zeek/broker/Manager.h" @@ -28,8 +30,158 @@ using namespace std; +namespace zeek::detail { + +extern zeek::OpaqueTypePtr log_delay_token_type; + +}; + namespace zeek::logging { +namespace detail { +using DelayTokenType = zeek_uint_t; + +class DelayInfo; + +using DelayInfoPtr = std::shared_ptr; + +class LogDelayTokenVal : public OpaqueVal { +public: + explicit LogDelayTokenVal(DelayTokenType token) : OpaqueVal(zeek::detail::log_delay_token_type), token(token) {} + virtual ~LogDelayTokenVal() = default; + + ValPtr DoClone(CloneState* state) override; + + DelayTokenType Token() { return token; } + +protected: + explicit LogDelayTokenVal() : LogDelayTokenVal(0) {} + DECLARE_OPAQUE_VALUE(LogDelayTokenVal) + +private: + DelayTokenType token; +}; + +ValPtr LogDelayTokenVal::DoClone(CloneState* state) { + return state->NewClone(this, make_intrusive(Token())); +} + +// Delay tokens are only valid on the same worker. +broker::expected LogDelayTokenVal::DoSerialize() const { + return broker::make_error(broker::ec::invalid_data, "cannot serialize delay tokens"); +} + +bool LogDelayTokenVal::DoUnserialize(const broker::data&) { return false; } + +IMPLEMENT_OPAQUE_VALUE(LogDelayTokenVal) + +DelayTokenType to_internal_delay_token(const ValPtr& val) { + assert(val->GetType()->Tag() == TYPE_OPAQUE); + if ( auto* optr = dynamic_cast(val.get()) ) + return optr->Token(); + + zeek::reporter->Error("dynamic_cast of LogDelayToken failed: wrong opaque type provided?"); + return 0; +} + +using DelayWriteMap = std::map; +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: + // Active log write 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 at this instance in the delay_queue. + DelayQueue::const_iterator queue_position; +}; + +const DelayInfoPtr DelayInfo::nil = nullptr; + +// Timer for the head of the per stream delay queue using an opaque +// callback based approach to hide the Stream implementation details. +class LogDelayExpiredTimer : public zeek::detail::Timer { +public: + LogDelayExpiredTimer(std::function dispatch_callback, double t) + : Timer(t, zeek::detail::TIMER_LOG_DELAY_EXPIRE), dispatch_callback(dispatch_callback) {} + + void Dispatch(double t, bool is_expire) override { dispatch_callback(t, is_expire); } + +private: + std::function dispatch_callback; +}; + +// 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; @@ -64,7 +216,7 @@ struct Manager::Filter { struct Manager::WriterInfo { EnumVal* type = nullptr; double open_time = 0.0; - detail::Timer* rotation_timer = nullptr; + zeek::detail::Timer* rotation_timer = nullptr; double interval = 0.0; Func* postprocessor = nullptr; WriterFrontend* writer = nullptr; @@ -96,7 +248,27 @@ 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; + + detail::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); }; Manager::Filter::~Filter() { @@ -131,8 +303,120 @@ 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; + } + + auto cb = [this](double ts, bool is_expire) { this->DispatchDelayExpiredTimer(ts, is_expire); }; + delay_timer = new detail::LogDelayExpiredTimer(cb, 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"}, @@ -310,6 +594,8 @@ bool Manager::CreateStream(EnumVal* id, RecordVal* sval) { streams[idx]->event = event ? event_registry->Lookup(event->Name()) : nullptr; streams[idx]->policy = policy; streams[idx]->columns = columns->Ref()->AsRecordType(); + streams[idx]->max_delay_interval = sval->GetField("max_delay_interval")->AsTime(); + streams[idx]->max_delay_queue_size = sval->GetField("max_delay_queue_size")->AsCount(); streams[idx]->enable_remote = id::find_val("Log::enable_remote_logging")->AsBool(); @@ -404,7 +690,7 @@ bool Manager::TraverseRecord(Stream* stream, Filter* filter, RecordType* rt, Tab const auto& t = rtype->GetFieldType(i); // Ignore if &log not specified. - if ( ! rtype->FieldDecl(i)->GetAttr(detail::ATTR_LOG) ) + if ( ! rtype->FieldDecl(i)->GetAttr(zeek::detail::ATTR_LOG) ) continue; list new_indices = indices; @@ -494,7 +780,7 @@ bool Manager::TraverseRecord(Stream* stream, Filter* filter, RecordType* rt, Tab else if ( t->Tag() == TYPE_VECTOR ) st = t->AsVectorType()->Yield()->Tag(); - bool optional = (bool)rtype->FieldDecl(i)->GetAttr(detail::ATTR_OPTIONAL); + bool optional = (bool)rtype->FieldDecl(i)->GetAttr(zeek::detail::ATTR_OPTIONAL); filter->fields[filter->num_fields - 1] = new threading::Field(new_path.c_str(), nullptr, t->Tag(), st, optional); @@ -660,30 +946,60 @@ 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 = detail::extract_module_name(stream->name.c_str()); + std::string module_name = zeek::detail::extract_module_name(stream->name.c_str()); std::initializer_list labels{{"module", module_name}, {"stream", stream->name}}; stream->total_writes = total_log_stream_writes_family.GetOrAdd(labels); } stream->total_writes->Inc(); - // Send to each of our filters. - for ( list::iterator i = stream->filters.begin(); i != stream->filters.end(); ++i ) { - Filter* filter = *i; + 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); +} + +bool Manager::WriteToFilters(const Manager::Stream* stream, zeek::RecordValPtr columns, PolicyVerdict stream_verdict) { + for ( auto* filter : stream->filters ) { string path = filter->path; // Policy hooks may veto the logging or alter the log @@ -692,12 +1008,15 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) { // handlers/bodies. Doing this skips sampling and // plugin hooks, though, so for now we do invoke. if ( filter->policy ) { - auto v = filter->policy->Invoke(columns, IntrusivePtr{NewRef{}, id}, IntrusivePtr{NewRef{}, filter->fval}); + auto v = filter->policy->Invoke(columns, IntrusivePtr{NewRef{}, stream->id}, + IntrusivePtr{NewRef{}, filter->fval}); if ( v && ! v->AsBool() ) continue; } - if ( stream_veto ) + // Even if Log::log_stream_policy vetoed, we invoke filter policy + // hooks. Skip actually writing here. + if ( stream_verdict == PolicyVerdict::VETO ) continue; if ( filter->path_func ) { @@ -717,7 +1036,8 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) { // Can be TYPE_ANY here. rec_arg = columns; - auto v = filter->path_func->Invoke(IntrusivePtr{NewRef{}, id}, std::move(path_arg), std::move(rec_arg)); + auto v = + filter->path_func->Invoke(IntrusivePtr{NewRef{}, stream->id}, std::move(path_arg), std::move(rec_arg)); if ( ! v ) return false; @@ -743,7 +1063,7 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) { Stream::WriterPathPair wpp(filter->writer->AsEnum(), path); // See if we already have a writer for this path. - Stream::WriterMap::iterator w = stream->writers.find(wpp); + Stream::WriterMap::const_iterator w = stream->writers.find(wpp); if ( w != stream->writers.end() && CheckFilterWriterConflict(w->second, filter) ) { // Auto-correct path due to conflict over the writer/path pairs. @@ -871,6 +1191,204 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) { 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: outside of Log::log_stream_policy() hook"); + return make_intrusive(); + } + + const auto& active_write_ctx = active_writes.back(); + if ( active_write_ctx.id != id || active_write_ctx.record != record ) { + reporter->Error("invalid Log::delay() call: argument mismatch with active Log::write()"); + return make_intrusive(); + } + + 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 and return it to script land. + detail::DelayTokenType token = ++last_delay_token; + token_val = zeek::make_intrusive(token); + double expire_time = run_state::network_time + stream->max_delay_interval; + auto new_delay_info = std::make_shared(active_write_ctx, token_val, expire_time); + if ( post_delay_cb ) + 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() != TYPE_OPAQUE ) { + reporter->Error("invalid delay token type %s", zeek::type_name(token_val->GetType()->Tag())); + return false; + } + + const auto& token_type_name = token_val->GetType()->Name(); + if ( token_type_name != std::string_view{"LogDelayToken"} ) { + reporter->Error("invalid Log::delay_finish() call: wrong opaque token type: %s", token_type_name.c_str()); + return false; + } + + detail::DelayTokenType token = detail::to_internal_delay_token(token_val); + if ( token == 0 ) { + reporter->Error("invalid Log::delay_finish() call: invalid token provided"); + return false; + } + + DBG_LOG(DBG_LOGGING, "DelayFinish() for %p RefCnt=%d token=%ld", record.get(), record->RefCnt(), token); + const auto& it = stream->delay_tokens.find(token); + + 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-delaying 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; +} + +zeek_int_t Manager::GetDelayQueueSize(const EnumValPtr& id) { + Stream* stream = FindStream(id.get()); + if ( ! stream ) + return -1; + + return stream->delay_queue.size(); +} + +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); @@ -1003,7 +1521,7 @@ threading::Value* Manager::ValToLogVal(std::optional& val, Type* ty) { return lval; } -threading::Value** Manager::RecordToFilterVals(Stream* stream, Filter* filter, RecordVal* columns) { +threading::Value** Manager::RecordToFilterVals(const Stream* stream, Filter* filter, RecordVal* columns) { RecordValPtr ext_rec; if ( filter->num_ext_fields > 0 ) { @@ -1092,7 +1610,7 @@ WriterFrontend* Manager::CreateWriter(EnumVal* id, EnumVal* writer, WriterBacken } // Initialize metric for this frontend. - std::string stream_module_name = detail::extract_module_name(stream->name.c_str()); + std::string stream_module_name = zeek::detail::extract_module_name(stream->name.c_str()); std::string writer_name = writer->GetType()->AsEnumType()->Lookup(writer->AsEnum()); std::initializer_list labels{{"writer", writer_name}, {"module", stream_module_name}, diff --git a/src/logging/Manager.h b/src/logging/Manager.h index 3a42d4ca5f..d1e39d55d2 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,72 @@ 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); + + /** + * Returns the current size for the delay queue for the stream identified by \a id. + * + * @param id The enum value corresponding to the log stream. + * + * @return The size of the delay queue or -1 on error. + */ + zeek_int_t GetDelayQueueSize(const EnumValPtr& id); + /** * Create a new log writer frontend. This is exposed so that the * communication system can recreate remote log streams locally. @@ -283,7 +376,7 @@ private: bool TraverseRecord(Stream* stream, Filter* filter, RecordType* rt, TableVal* include, TableVal* exclude, const std::string& path, const std::list& indices); - threading::Value** RecordToFilterVals(Stream* stream, Filter* filter, RecordVal* columns); + threading::Value** RecordToFilterVals(const Stream* stream, Filter* filter, RecordVal* columns); threading::Value* ValToLogVal(std::optional& val, Type* ty); Stream* FindStream(EnumVal* id); @@ -294,8 +387,17 @@ private: bool CompareFields(const Filter* filter, const WriterFrontend* writer); bool CheckFilterWriterConflict(const WriterInfo* winfo, const Filter* filter); + // Verdict of a PolicyHook. + enum class PolicyVerdict { + PASS, + VETO, + }; + bool WriteToFilters(const Manager::Stream* stream, zeek::RecordValPtr columns, PolicyVerdict stream_verdict); + 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; @@ -303,6 +405,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..15c4309c77 100644 --- a/src/logging/logging.bif +++ b/src/logging/logging.bif @@ -70,3 +70,87 @@ 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 record_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 = record_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 = record_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); + %} + +function Log::__get_delay_queue_size%(id: Log::ID%): int + %{ + auto idptr = enum_ref(id); + if ( ! idptr ) + return zeek::val_mgr->Bool(false); + + return zeek::val_mgr->Int(zeek::log_mgr->GetDelayQueueSize(idptr)); + %} diff --git a/src/logging/writers/ascii/Ascii.cc b/src/logging/writers/ascii/Ascii.cc index 811b88583a..00a490fb2b 100644 --- a/src/logging/writers/ascii/Ascii.cc +++ b/src/logging/writers/ascii/Ascii.cc @@ -19,7 +19,6 @@ #include "zeek/Func.h" #include "zeek/RunState.h" #include "zeek/logging/Manager.h" -#include "zeek/logging/logging.bif.h" #include "zeek/logging/writers/ascii/ascii.bif.h" #include "zeek/threading/SerialTypes.h" #include "zeek/util.h" diff --git a/src/zeek-setup.cc b/src/zeek-setup.cc index 8fa92d4983..afe5cec284 100644 --- a/src/zeek-setup.cc +++ b/src/zeek-setup.cc @@ -244,6 +244,8 @@ const char* zeek_version() { namespace detail { +zeek::OpaqueTypePtr log_delay_token_type; + static std::vector to_cargs(const std::vector& args) { std::vector rval; rval.reserve(args.size()); @@ -719,6 +721,7 @@ SetupResult setup(int argc, char** argv, Options* zopts) { int_histogram_metric_family_type = make_intrusive("int_histogram_metric_family"); dbl_histogram_metric_type = make_intrusive("dbl_histogram_metric"); dbl_histogram_metric_family_type = make_intrusive("dbl_histogram_metric_family"); + log_delay_token_type = make_intrusive("LogDelayToken"); // After spinning up Broker, we have background threads running now. If // we exit early, we need to shut down at least Broker to get a clean diff --git a/testing/btest/Baseline/javascript.log-delay/.stdout b/testing/btest/Baseline/javascript.log-delay/.stdout new file mode 100644 index 0000000000..2f2bd3a208 --- /dev/null +++ b/testing/btest/Baseline/javascript.log-delay/.stdout @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692527.009775 delaying record +1362692527.080972 delay finish +1362692527.080972 HTTP::log_policy CHhAvVGS1DHFjwGM9 141.142.228.5 192.150.187.43 JS: after delay diff --git a/testing/btest/Baseline/javascript.log-delay/http.log.cut b/testing/btest/Baseline/javascript.log-delay/http.log.cut new file mode 100644 index 0000000000..2b573a5c1b --- /dev/null +++ b/testing/btest/Baseline/javascript.log-delay/http.log.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 id.resp_h new_field +XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 141.142.228.5 192.150.187.43 JS: after delay diff --git a/testing/btest/Baseline/plugins.hooks/output b/testing/btest/Baseline/plugins.hooks/output index faf63ede72..5bebc930f3 100644 --- a/testing/btest/Baseline/plugins.hooks/output +++ b/testing/btest/Baseline/plugins.hooks/output @@ -49,18 +49,18 @@ 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::add_default_filter, , (Analyzer::Logging::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Broker::LOG)) -> @@ -98,18 +98,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,18 +967,18 @@ 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::add_default_filter, , (Analyzer::Logging::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Broker::LOG)) @@ -1016,18 +1016,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,18 +1884,18 @@ 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::add_default_filter(Analyzer::Logging::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Broker::LOG) @@ -1933,18 +1933,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-5/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-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.basic-5/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stdout new file mode 100644 index 0000000000..53a917ca3d --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/.stdout @@ -0,0 +1,21 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +1362692526.869344, new_connection, CHhAvVGS1DHFjwGM9 +1362692526.869344, log_stream_policy, LOG, CHhAvVGS1DHFjwGM9 +token, +to_json(token), {"opaque_type":"LogDelayTokenVal"} +1362692526.869344, new_packet, 1 +1362692526.939084, new_packet, 2 +1362692526.939378, new_packet, 3 +1362692526.939527, new_packet, 4 +1362692527.008509, new_packet, 5 +1362692527.009512, new_packet, 6 +1362692527.009721, new_packet, 7 +1362692527.009765, new_packet, 8 +1362692527.009775, new_packet, 9 +1362692527.009855, new_packet, 10 +1362692527.009887, new_packet, 11 +1362692527.011846, new_packet, 12 +1362692527.080828, log_policy, CHhAvVGS1DHFjwGM9 +1362692527.080828, new_packet, 13 +1362692527.080972, new_packet, 14 +1362692527.080972, Pcap::file_done diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/test.cut new file mode 100644 index 0000000000..7ca18d40f9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.basic-5/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..a16128e7a8 --- /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: argument mismatch with active Log::write() 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..a16128e7a8 --- /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: argument mismatch with active Log::write() 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..0ff66ed885 --- /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: record mismatch token=1 0x<...> and 0x<...> diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-5/.stderr new file mode 100644 index 0000000000..23205c7478 --- /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: delay reference underflow for token=1 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..2087442926 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors-6/.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.080972 error: invalid Log::delay() call: outside of Log::log_stream_policy() hook +1362692527.080972 error: invalid Log::delay_finish() call: invalid token provided 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..eab4cf6651 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.errors/.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. +error: invalid Log::delay() call: outside of Log::log_stream_policy() hook +error: invalid Log::delay_finish() call: invalid token provided 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-size/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/.stderr new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/.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-size/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/.stdout new file mode 100644 index 0000000000..5b52ab0ead --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/.stdout @@ -0,0 +1,75 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, queue_size non-existing, -1 +0.0, queue_size existing, 0 +1362692526.869344, new_packet, 1, queue size, 0 +1362692526.869344, log_stream_policy, LOG, [ts=1362692526.869344, post_ts=, write_ts=, msg=packet number 1] +1362692526.869344, queue_size post write, 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, queue size, 0 +1362692526.939084, log_stream_policy, LOG, [ts=1362692526.939084, post_ts=, write_ts=, msg=packet number 2] +1362692526.939084, queue_size post write, 1 +1362692526.939378, new_packet, 3, queue size, 1 +1362692526.939378, log_stream_policy, LOG, [ts=1362692526.939378, post_ts=, write_ts=, msg=packet number 3] +1362692526.939378, queue_size post write, 2 +1362692526.939527, new_packet, 4, queue size, 2 +1362692526.939527, log_stream_policy, LOG, [ts=1362692526.939527, post_ts=, write_ts=, msg=packet number 4] +1362692526.939527, queue_size post write, 3 +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, queue size, 0 +1362692527.008509, log_stream_policy, LOG, [ts=1362692527.008509, post_ts=, write_ts=, msg=packet number 5] +1362692527.008509, queue_size post write, 1 +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, queue size, 0 +1362692527.009512, log_stream_policy, LOG, [ts=1362692527.009512, post_ts=, write_ts=, msg=packet number 6] +1362692527.009512, queue_size post write, 1 +1362692527.009721, new_packet, 7, queue size, 1 +1362692527.009721, log_stream_policy, LOG, [ts=1362692527.009721, post_ts=, write_ts=, msg=packet number 7] +1362692527.009721, queue_size post write, 2 +1362692527.009765, new_packet, 8, queue size, 2 +1362692527.009765, log_stream_policy, LOG, [ts=1362692527.009765, post_ts=, write_ts=, msg=packet number 8] +1362692527.009765, queue_size post write, 3 +1362692527.009775, new_packet, 9, queue size, 3 +1362692527.009775, log_stream_policy, LOG, [ts=1362692527.009775, post_ts=, write_ts=, msg=packet number 9] +1362692527.009775, queue_size post write, 4 +1362692527.009855, new_packet, 10, queue size, 4 +1362692527.009855, log_stream_policy, LOG, [ts=1362692527.009855, post_ts=, write_ts=, msg=packet number 10] +1362692527.009855, queue_size post write, 5 +1362692527.009887, new_packet, 11, queue size, 5 +1362692527.009887, log_stream_policy, LOG, [ts=1362692527.009887, post_ts=, write_ts=, msg=packet number 11] +1362692527.009887, queue_size post write, 6 +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, queue size, 0 +1362692527.011846, log_stream_policy, LOG, [ts=1362692527.011846, post_ts=, write_ts=, msg=packet number 12] +1362692527.011846, queue_size post write, 1 +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, queue size, 0 +1362692527.080828, log_stream_policy, LOG, [ts=1362692527.080828, post_ts=, write_ts=, msg=packet number 13] +1362692527.080828, queue_size post write, 1 +1362692527.080972, new_packet, 14, queue size, 1 +1362692527.080972, log_stream_policy, LOG, [ts=1362692527.080972, post_ts=, write_ts=, msg=packet number 14] +1362692527.080972, queue_size post write, 2 +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 +1362692527.080972, queue_size done, 0 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/test.cut b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/test.cut new file mode 100644 index 0000000000..733d2afc29 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.queue-size/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.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..e6e75f40cf --- /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 642 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 642: 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-3/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-3/.stderr new file mode 100644 index 0000000000..b5726af3b5 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-3/.stderr @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +error in <...>/main.zeek, line 647 and <...>/static-errors.zeek, line 8: type clash (Log::DelayToken and 42) +error in <...>/static-errors.zeek, line 8 and <...>/main.zeek, line 647: type mismatch (42 and Log::DelayToken) +error in <...>/static-errors.zeek, line 8: argument type mismatch in function call (Log::delay_finish(id, to_any_coercerec, 42)) diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-4/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-4/.stderr new file mode 100644 index 0000000000..025a9f455d --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors-4/.stderr @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +error in <...>/main.zeek, line 647 and <...>/static-errors.zeek, line 8: arithmetic mixed with non-arithmetic (Log::DelayToken and 42) +error in <...>/static-errors.zeek, line 8 and <...>/main.zeek, line 647: type mismatch (42 and Log::DelayToken) +error in <...>/static-errors.zeek, line 8: argument type mismatch in function call (Log::delay_finish(id, to_any_coercerec, 42)) diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.delay.static-errors/.stderr new file mode 100644 index 0000000000..292040868f --- /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 642 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 642: 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/javascript/log-delay.js b/testing/btest/javascript/log-delay.js new file mode 100644 index 0000000000..e3c1fe2edd --- /dev/null +++ b/testing/btest/javascript/log-delay.js @@ -0,0 +1,53 @@ +/* + * @TEST-DOC: Test delaying a log record from JavaScript + * @TEST-REQUIRES: $SCRIPTS/have-javascript + * @TEST-EXEC: zeek -b -Cr $TRACES/http/get.trace main.zeek exit_only_after_terminate=T + * @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff .stdout + * @TEST-EXEC: zeek-cut -m ts uid id.orig_h id.resp_h new_field < http.log > http.log.cut + * @TEST-EXEC: btest-diff http.log.cut + */ +@TEST-START-FILE main.zeek +@load base/protocols/http + +redef record HTTP::Info += { + new_field: string &optional &log; +}; + +# Load the JavaScript pieces +@load ./main.js +@TEST-END-FILE + +@TEST-START-FILE main.js +zeek.hook('Log::log_stream_policy', (rec, id) => { + if ( id != "HTTP::LOG" ) + return; + + let nt = zeek.invoke('network_time'); + console.log(nt, 'delaying record'); + + // Log::delay() of the in-flight write. + let token = zeek.invoke('Log::delay', [id, rec]); + + // 10msec delayed record enrichment + setTimeout(() => { + let nt = zeek.invoke('network_time'); + rec.new_field = "JS: after delay"; + console.log(nt, 'delay finish'); + zeek.invoke('Log::delay_finish', [id, rec, token]); + + // Shutdown, too. + zeek.invoke('terminate'); + }, 10); + +}); + +zeek.hook('HTTP::log_policy', (rec, id, filter) => { + let nt = zeek.invoke('network_time'); + console.log(nt, 'HTTP::log_policy', rec.uid, rec.id.orig_h, rec.id.resp_h, rec.new_field); +}); + +setTimeout(() => { + console.error('force exit'); + process.exit(1); +}, 5000); +@TEST-END-FILE 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..1855e77e02 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/basic.zeek @@ -0,0 +1,122 @@ +# @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); + } + +@TEST-START-NEXT +# Delay twice, never release, print the token value and its JSON representation. +hook Log::log_stream_policy(rec: Info, id: Log::ID) + { + if ( id != LOG ) + return; + + print network_time(), "log_stream_policy", id, rec$uid; + + local token = Log::delay(id, rec); + print "token", token; + print "to_json(token)", to_json(token); + } diff --git a/testing/btest/scripts/base/frameworks/logging/delay/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..fab379de87 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/errors.zeek @@ -0,0 +1,69 @@ +# @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 }; + +type Info: record { + ts: time &log &default=network_time(); +}; + +event zeek_init() + { + # Log::delay() not within a Log::log_stream_policy hook + Log::create_stream(LOG, [$columns=Info]); + local rec = Info(); + local token = Log::delay(LOG, rec); + Log::delay_finish(LOG, rec, token); + } + +@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 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) + { + # Delay underflow. + local token = Log::delay(id, rec); + Log::delay_finish(id, rec, token); + Log::delay_finish(id, rec, token); + } + +@TEST-START-NEXT +@load base/protocols/conn + +hook Conn::log_policy(rec: Conn::Info, id: Log::ID, filter: Log::Filter) + { + # Calling Log::delay() in a filter policy hook is an error. + local token = Log::delay(id, rec); + 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-size.zeek b/testing/btest/scripts/base/frameworks/logging/delay/queue-size.zeek new file mode 100644 index 0000000000..de5c1c7866 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/queue-size.zeek @@ -0,0 +1,83 @@ +# @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, "queue size", Log::get_delay_queue_size(LOG); + local info = Info($ts=network_time(), $msg=fmt("packet number %s", packet_count)); + Log::write(LOG, info); + print network_time(), "queue_size post write", Log::get_delay_queue_size(LOG); + } + + +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 + +event zeek_init() + { + print network_time(), "queue_size non-existing", Log::get_delay_queue_size(LOG); + Log::create_stream(LOG, [ + $columns=Info, + $path="test", + $policy=log_policy, + $max_delay_interval=1msec, + ]); + + print network_time(), "queue_size existing", Log::get_delay_queue_size(LOG); + } + +event zeek_done() + { + print network_time(), "queue_size done", Log::get_delay_queue_size(LOG); + } + +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; + }); + } 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..60ef1ed1dc --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/delay/static-errors.zeek @@ -0,0 +1,55 @@ +# @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); + } + +@TEST-START-NEXT +# Bad token type 1 +@load base/protocols/conn + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + # Wrong token type for delay_finish() + local token = Log::delay(id, rec); + Log::delay_finish(id, rec, "42"); + } + +@TEST-START-NEXT +# Bad token type 2 +@load base/protocols/conn + +hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) + { + # Wrong token type for delay_finish() + local token = Log::delay(id, rec); + Log::delay_finish(id, rec, 42); + }