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