Return weird if a log line is over a configurable size limit

This commit is contained in:
Tim Wojtulewicz 2025-07-15 15:23:43 -07:00
parent d203b90d71
commit a58503ab91
11 changed files with 253 additions and 26 deletions

14
NEWS
View file

@ -6,10 +6,20 @@ release. For an exhaustive list of changes, see the ``CHANGES`` file
Zeek 7.2.2
==========
We would like to thank @cccs-jsjm and @edoardomich for their contributions to this release.
We would like to thank @cccs-jsjm, @edoardomich, and the Canadian Cyber Defence Collective
for their contributions to this release.
This release fixes the following security issue:
- Very large log records can cause Zeek to overflow memory and potentially crash. Due to
the possibility of building these log records with packets from remote hosts, this is a
DoS risk. The fix adds additional length checking when serializing log data for writing
to logging streams. This can be controlled via a new ``Log::max_log_record_size``
redefinable constant, and reports a new ``log_record_too_large`` weird if the limitation
is reached for any individual log entry. There is an also a new
``log-writer-discarded-writes`` metric that tracks when this limitation is
reached.
This release fixes the following bugs:
- The Redis storage backend now requires libhiredis 1.1.0 or later.
@ -22,7 +32,7 @@ This release fixes the following bugs:
- The response to BDAT ``LAST`` was never recognized by the SMTP analyzer, resulting in
the BDAT ``LAST`` commands not being logged in a timely fashion and receiving the wrong
status. Zeek now correctly reports these comands.
status. Zeek now correctly reports these commands.
- The Docker images for zeek 7.0 releases now include the ``net-tools`` (for ``iproute2``)
package to silience a warning from ``zeekctl``. They also now include the ``procps``

View file

@ -3648,6 +3648,14 @@ export {
## .. :zeek:see:`Log::flush_interval`
const write_buffer_size = 1000 &redef;
## Maximum size of a message that can be sent to a remote logger or logged
## locally. If this limit is met, report a ``log_line_too_large`` weird and drop
## the log entry. This isn't necessarily the full size of a line that might be
## written to a log, but a general representation of the size as the log record is
## serialized for writing. The size of end result from serialization might be
## higher than this limit, but it prevents runaway-sized log entries from causing
## problems.
const max_log_record_size = 1024*1024*64 &redef;
}
module POP3;

View file

@ -244,8 +244,11 @@ struct Manager::WriterInfo {
string instantiating_filter;
std::shared_ptr<telemetry::Counter> total_writes;
std::shared_ptr<telemetry::Counter> total_discarded_writes;
WriterInfo(std::shared_ptr<telemetry::Counter> total_writes) : total_writes(std::move(total_writes)) {}
WriterInfo(std::shared_ptr<telemetry::Counter> total_writes,
std::shared_ptr<telemetry::Counter> total_discarded_writes)
: total_writes(std::move(total_writes)), total_discarded_writes(std::move(total_discarded_writes)) {}
};
struct Manager::Stream {
@ -483,7 +486,11 @@ Manager::Manager()
telemetry_mgr
->CounterFamily("zeek", "log-writer-writes", {"writer", "module", "stream", "filter-name", "path"},
"Total number of log writes passed to a concrete log writer not vetoed by stream or "
"filter policies.")) {
"filter policies.")),
total_log_writer_discarded_writes_family(
telemetry_mgr->CounterFamily("zeek", "log-writer-discarded-writes",
{"writer", "module", "stream", "filter-name", "path"},
"Total number of log writes discarded due to size limitations.")) {
rotations_pending = 0;
}
@ -495,6 +502,7 @@ Manager::~Manager() {
void Manager::InitPostScript() {
rotation_format_func = id::find_func("Log::rotation_format_func");
log_stream_policy_hook = id::find_func("Log::log_stream_policy");
max_log_record_size = id::find_val("Log::max_log_record_size")->AsCount();
}
WriterBackend* Manager::CreateBackend(WriterFrontend* frontend, EnumVal* tag) {
@ -1152,7 +1160,14 @@ bool Manager::WriteToFilters(const Manager::Stream* stream, zeek::RecordValPtr c
assert(info);
// Alright, can do the write now.
auto rec = RecordToLogRecord(stream, filter, columns.get());
size_t total_size = 0;
auto rec = RecordToLogRecord(stream, filter, columns.get(), total_size);
if ( total_size > max_log_record_size ) {
reporter->Weird("log_record_too_large", util::fmt("%s", stream->name.c_str()));
w->second->total_discarded_writes->Inc();
continue;
}
if ( zeek::plugin_mgr->HavePluginForHook(zeek::plugin::HOOK_LOG_WRITE) ) {
// The current HookLogWrite API takes a threading::Value**.
@ -1385,7 +1400,7 @@ bool Manager::SetMaxDelayQueueSize(const EnumValPtr& id, zeek_uint_t queue_size)
return true;
}
threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty, size_t& total_size) {
if ( ! val )
return {ty->Tag(), false};
@ -1393,7 +1408,10 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
switch ( lval.type ) {
case TYPE_BOOL:
case TYPE_INT: lval.val.int_val = val->AsInt(); break;
case TYPE_INT:
lval.val.int_val = val->AsInt();
total_size += sizeof(lval.val.int_val);
break;
case TYPE_ENUM: {
const char* s = ty->AsEnumType()->Lookup(val->AsInt());
@ -1410,13 +1428,16 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
lval.val.string_val.data = util::copy_string("", 0);
lval.val.string_val.length = 0;
}
total_size += lval.val.string_val.length;
break;
}
case TYPE_COUNT: {
case TYPE_COUNT:
lval.val.uint_val = val->AsCount();
total_size += sizeof(lval.val.uint_val);
break;
}
case TYPE_PORT: {
auto p = val->AsCount();
@ -1432,16 +1453,26 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
lval.val.port_val.port = p & ~PORT_SPACE_MASK;
lval.val.port_val.proto = pt;
total_size += lval.val.port_val.size();
break;
}
case TYPE_SUBNET: val->AsSubNet()->Get().ConvertToThreadingValue(&lval.val.subnet_val); break;
case TYPE_SUBNET:
val->AsSubNet()->Get().ConvertToThreadingValue(&lval.val.subnet_val);
total_size += lval.val.subnet_val.size();
break;
case TYPE_ADDR: val->AsAddr()->Get().ConvertToThreadingValue(&lval.val.addr_val); break;
case TYPE_ADDR:
val->AsAddr()->Get().ConvertToThreadingValue(&lval.val.addr_val);
total_size += lval.val.addr_val.size();
break;
case TYPE_DOUBLE:
case TYPE_TIME:
case TYPE_INTERVAL: lval.val.double_val = val->AsDouble(); break;
case TYPE_INTERVAL:
lval.val.double_val = val->AsDouble();
total_size += sizeof(lval.val.double_val);
break;
case TYPE_STRING: {
const String* s = val->AsString()->AsString();
@ -1450,6 +1481,7 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
lval.val.string_val.data = buf;
lval.val.string_val.length = s->Len();
total_size += lval.val.string_val.length;
break;
}
@ -1459,6 +1491,7 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
auto len = strlen(s);
lval.val.string_val.data = util::copy_string(s, len);
lval.val.string_val.length = len;
total_size += lval.val.string_val.length;
break;
}
@ -1470,6 +1503,7 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
auto len = strlen(s);
lval.val.string_val.data = util::copy_string(s, len);
lval.val.string_val.length = len;
total_size += lval.val.string_val.length;
break;
}
@ -1486,14 +1520,15 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
auto& set_t = tbl_t->GetIndexTypes()[0];
bool is_managed = ZVal::IsManagedType(set_t);
lval.val.set_val.size = set->Length();
lval.val.set_val.vals = new threading::Value*[lval.val.set_val.size];
zeek_int_t set_length = set->Length();
lval.val.set_val.vals = new threading::Value*[set_length];
for ( zeek_int_t i = 0; i < lval.val.set_val.size; i++ ) {
for ( zeek_int_t i = 0; i < set_length && total_size < max_log_record_size; i++ ) {
std::optional<ZVal> s_i = ZVal(set->Idx(i), set_t);
lval.val.set_val.vals[i] = new threading::Value(ValToLogVal(s_i, set_t.get()));
lval.val.set_val.vals[i] = new threading::Value(ValToLogVal(s_i, set_t.get(), total_size));
if ( is_managed )
ZVal::DeleteManagedType(*s_i);
lval.val.set_val.size++;
}
break;
@ -1501,14 +1536,15 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
case TYPE_VECTOR: {
VectorVal* vec = val->AsVector();
lval.val.vector_val.size = vec->Size();
lval.val.vector_val.vals = new threading::Value*[lval.val.vector_val.size];
zeek_int_t vec_length = vec->Size();
lval.val.vector_val.vals = new threading::Value*[vec_length];
auto& vv = vec->RawVec();
auto& vt = vec->GetType()->Yield();
for ( zeek_int_t i = 0; i < lval.val.vector_val.size; i++ ) {
lval.val.vector_val.vals[i] = new threading::Value(ValToLogVal(vv[i], vt.get()));
for ( zeek_int_t i = 0; i < vec_length && total_size < max_log_record_size; i++ ) {
lval.val.vector_val.vals[i] = new threading::Value(ValToLogVal(vv[i], vt.get(), total_size));
lval.val.vector_val.size++;
}
break;
@ -1520,7 +1556,8 @@ threading::Value Manager::ValToLogVal(std::optional<ZVal>& val, Type* ty) {
return lval;
}
detail::LogRecord Manager::RecordToLogRecord(const Stream* stream, Filter* filter, RecordVal* columns) {
detail::LogRecord Manager::RecordToLogRecord(const Stream* stream, Filter* filter, RecordVal* columns,
size_t& total_size) {
RecordValPtr ext_rec;
if ( filter->num_ext_fields > 0 ) {
@ -1570,7 +1607,11 @@ detail::LogRecord Manager::RecordToLogRecord(const Stream* stream, Filter* filte
}
if ( val )
vals.emplace_back(ValToLogVal(val, vt));
vals.emplace_back(ValToLogVal(val, vt, total_size));
if ( total_size > max_log_record_size ) {
return {};
}
}
return vals;
@ -1619,7 +1660,8 @@ WriterFrontend* Manager::CreateWriter(EnumVal* id, EnumVal* writer, WriterBacken
{"filter-name", instantiating_filter},
{"path", info->path}};
WriterInfo* winfo = new WriterInfo(zeek::log_mgr->total_log_writer_writes_family->GetOrAdd(labels));
WriterInfo* winfo = new WriterInfo(zeek::log_mgr->total_log_writer_writes_family->GetOrAdd(labels),
zeek::log_mgr->total_log_writer_discarded_writes_family->GetOrAdd(labels));
winfo->type = writer->Ref()->AsEnumVal();
winfo->writer = nullptr;
winfo->open_time = run_state::network_time;

View file

@ -422,8 +422,8 @@ private:
bool TraverseRecord(Stream* stream, Filter* filter, RecordType* rt, TableVal* include, TableVal* exclude,
const std::string& path, const std::list<int>& indices);
detail::LogRecord RecordToLogRecord(const Stream* stream, Filter* filter, RecordVal* columns);
threading::Value ValToLogVal(std::optional<ZVal>& val, Type* ty);
detail::LogRecord RecordToLogRecord(const Stream* stream, Filter* filter, RecordVal* columns, size_t& total_size);
threading::Value ValToLogVal(std::optional<ZVal>& val, Type* ty, size_t& total_size);
Stream* FindStream(EnumVal* id);
void RemoveDisabledWriters(Stream* stream);
@ -445,12 +445,14 @@ private:
bool DelayCompleted(Manager::Stream* stream, detail::DelayInfo& delay_info);
std::vector<Stream*> streams; // Indexed by stream enum.
int rotations_pending; // Number of rotations not yet finished.
int rotations_pending = 0; // Number of rotations not yet finished.
FuncPtr rotation_format_func;
FuncPtr log_stream_policy_hook;
size_t max_log_record_size = 0;
std::shared_ptr<telemetry::CounterFamily> total_log_stream_writes_family;
std::shared_ptr<telemetry::CounterFamily> total_log_writer_writes_family;
std::shared_ptr<telemetry::CounterFamily> total_log_writer_discarded_writes_family;
zeek_uint_t last_delay_token = 0;
std::vector<detail::WriteContext> active_writes;

View file

@ -137,6 +137,7 @@ struct Value {
struct port_t {
zeek_uint_t port;
TransportProto proto;
constexpr size_t size() { return sizeof(port) + sizeof(proto); }
};
struct addr_t {
@ -145,6 +146,8 @@ struct Value {
struct in_addr in4;
struct in6_addr in6;
} in;
constexpr size_t size() { return sizeof(in) + sizeof(IPFamily); }
};
// A small note for handling subnet values: Subnet values emitted from
@ -157,6 +160,7 @@ struct Value {
struct subnet_t {
addr_t prefix;
uint8_t length;
constexpr size_t size() { return prefix.size() + sizeof(length); }
};
/**

View file

@ -0,0 +1,11 @@
### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path test
#open XXXX-XX-XX-XX-XX-XX
#fields strings
#types vector[string]
a,b,c
#close XXXX-XX-XX-XX-XX-XX

View file

@ -0,0 +1,11 @@
### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open XXXX-XX-XX-XX-XX-XX
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer source
#types time string addr port addr port string string bool string string
XXXXXXXXXX.XXXXXX - - - - - log_record_too_large Test::LOG F zeek -
#close XXXX-XX-XX-XX-XX-XX

View file

@ -0,0 +1,11 @@
### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path test
#open XXXX-XX-XX-XX-XX-XX
#fields strings
#types vector[string]
a,b,c
#close XXXX-XX-XX-XX-XX-XX

View file

@ -0,0 +1,11 @@
### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
#separator \x09
#set_separator ,
#empty_field (empty)
#unset_field -
#path weird
#open XXXX-XX-XX-XX-XX-XX
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p name addl notice peer source
#types time string addr port addr port string string bool string string
XXXXXXXXXX.XXXXXX - - - - - log_record_too_large Test::LOG F zeek -
#close XXXX-XX-XX-XX-XX-XX

View file

@ -10,7 +10,10 @@
XXXXXXXXXX.XXXXXX zeek counter zeek_log_stream_writes_total module,stream Conn,Conn::LOG 34.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_stream_writes_total module,stream DNS,DNS::LOG 34.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_stream_writes_total module,stream HTTP,HTTP::LOG 14.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_writer_discarded_writes_total filter_name,module,path,stream,writer default,Conn,conn,Conn::LOG,Log::WRITER_ASCII 0.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_writer_writes_total filter_name,module,path,stream,writer default,Conn,conn,Conn::LOG,Log::WRITER_ASCII 30.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_writer_discarded_writes_total filter_name,module,path,stream,writer default,DNS,dns,DNS::LOG,Log::WRITER_ASCII 0.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_writer_writes_total filter_name,module,path,stream,writer default,DNS,dns,DNS::LOG,Log::WRITER_ASCII 23.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_writer_discarded_writes_total filter_name,module,path,stream,writer default,HTTP,http,HTTP::LOG,Log::WRITER_ASCII 0.0
XXXXXXXXXX.XXXXXX zeek counter zeek_log_writer_writes_total filter_name,module,path,stream,writer default,HTTP,http,HTTP::LOG,Log::WRITER_ASCII 10.0
#close XXXX-XX-XX-XX-XX-XX

View file

@ -0,0 +1,114 @@
# @TEST-GROUP: broker
#
# @TEST-DOC: Limit the size of log lines that can be written.
#
# @TEST-PORT: BROKER_PORT
#
# @TEST-EXEC: btest-bg-run logger "zeek -b ../logger.zeek"
# @TEST-EXEC: btest-bg-run worker-1 "zeek -b ../worker-1.zeek"
# @TEST-EXEC: btest-bg-run worker-2 "zeek -b ../worker-2.zeek"
#
# @TEST-EXEC: btest-bg-wait -k 10
# @TEST-EXEC: btest-diff logger/weird.log
# @TEST-EXEC: btest-diff logger/test.log
# @TEST-EXEC: btest-diff worker-2/weird.log
# @TEST-EXEC: btest-diff worker-2/test.log
# @TEST-START-FILE common.zeek
@load base/frameworks/notice/weird
module Test;
export {
redef enum Log::ID += { LOG };
type Info: record {
strings: vector of string &log;
};
}
# Limit log lines to 1MB.
redef Log::max_log_record_size = 1024 * 1024;
redef Broker::disable_ssl = T;
event zeek_init()
{
Log::create_stream(LOG, [$columns=Info, $path="test"]);
}
# @TEST-END-FILE
# @TEST-START-FILE logger.zeek
@load ./common.zeek
redef Log::enable_remote_logging = F;
redef Log::enable_local_logging = T;
event zeek_init()
{
Broker::subscribe("zeek/logs");
Broker::listen("127.0.0.1", to_port(getenv("BROKER_PORT")));
}
global peers_lost = 0;
event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string)
{
print "peer lost";
++peers_lost;
if ( peers_lost == 2 )
terminate();
}
# @TEST-END-FILE
# @TEST-START-FILE worker.zeek
@load ./common.zeek
event zeek_init()
{
Broker::peer("127.0.0.1", to_port(getenv("BROKER_PORT")));
}
event do_write()
{
local s = "AAAAAAAAAAAAAAAAAAAA"; # 20 bytes
local s100 = s + s + s + s + s;
local s1000 = s100 + s100 + s100 + s100 + s100 + s100 + s100 + s100 + s100 + s100;
local rec = Test::Info();
local i = 0;
while ( ++i <= ( 1000 * 1000 ) )
{
rec$strings += s1000;
}
Log::write(Test::LOG, rec);
local rec2 = Test::Info();
rec2$strings += "a";
rec2$strings += "b";
rec2$strings += "c";
Log::write(Test::LOG, rec2);
terminate();
}
event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string)
{
print "new_peer", msg;
schedule 1sec { do_write() };
}
# @TEST-END-FILE
# @TEST-START-FILE worker-1.zeek
@load ./worker.zeek
redef Log::enable_remote_logging = T;
redef Log::enable_local_logging = F;
# @TEST-END-FILE worker-1.zeek
# @TEST-START-FILE worker-2.zeek
@load ./worker.zeek
redef Log::enable_remote_logging = F;
redef Log::enable_local_logging = T;
# @TEST-END-FILE worker-2.zeek