Merge remote-tracking branch 'origin/topic/awelzel/smb2-state-handling'

* origin/topic/awelzel/smb2-state-handling:
  NEWS: Add entry about SMB::max_pending_messages and state discarding
  scripts/smb2-main: Reset script-level state upon smb2_discarded_messages_state()
  smb2: Limit per-connection read/ioctl/tree state
This commit is contained in:
Arne Welzel 2023-05-04 09:30:18 +02:00
commit 12252743b1
17 changed files with 183 additions and 2 deletions

26
CHANGES
View file

@ -1,3 +1,29 @@
6.0.0-dev.498 | 2023-05-04 09:30:18 +0200
* scripts/smb2-main: Reset script-level state upon smb2_discarded_messages_state() (Arne Welzel, Corelight)
This is similar to what the external corelight/zeek-smb-clear-state script
does, but leverages the smb2_discarded_messages_state() event instead of
regularly checking on the state of SMB connections.
The pcap was created using the dperson/samba container image and mounting
a share with Linux's CIFS filesystem, then copying the content of a
directory with 100 files. The test uses a BPF filter to imitate mostly
"half-duplex" traffic.
* smb2: Limit per-connection read/ioctl/tree state (Arne Welzel, Corelight)
Users on Slack observed memory growth in an environment with a lot of
SMB traffic. jeprof memory profiling pointed at the offset and fid maps
kept per-connection for smb2 read requests.
These maps can grow unbounded if responses are seen before requests, there's
packet drops, just one side of the connection is visible, or we fail to parse
responses properly.
Forcefully wipe out these maps when they grow too large and raise
smb2_discarded_messages_state() to notify script land about this.
6.0.0-dev.493 | 2023-05-03 11:13:15 -0700
* Update Mozilla CA and Google CT lists (Johanna Amann, Corelight)

10
NEWS
View file

@ -316,6 +316,16 @@ Changed Functionality
instead, hello retry requests were logged like as a server hello (with the letter
`s`). This oversight was fixed, and hello retry requests are now correctly logged.
- When per-connection SMB parser state (read offsets, tree ids, ...) exceeds
``SMB::max_pending_messages`` (default 1000), Zeek discards such per-connection
state and raises a new ``smb2_discarded_messages_state()`` event. This event is
used to reset script-layer SMB state. This change provides protection against
unbounded state growth due to partial or one-sided SMB connections.
Setting ``SMB::max_pending_messages`` to 0 can be used to switch back to the
previous behavior of not discarding state. Setting ``SMB::enable_state_clear``
to ``F`` skips the script-layer state clearing logic.
Removed Functionality
---------------------

View file

@ -1 +1 @@
6.0.0-dev.493
6.0.0-dev.498

View file

@ -210,6 +210,7 @@ export {
["spontaneous_FIN"] = ACTION_IGNORE,
["spontaneous_RST"] = ACTION_IGNORE,
["SMB_parsing_error"] = ACTION_LOG,
["SMB_discarded_messages_state"] = ACTION_LOG,
["no_smb_session_using_parsesambamsg"] = ACTION_LOG,
["smb_andx_command_failed_to_parse"] = ACTION_LOG,
["smb_tree_connect_andx_response_without_tree"] = ACTION_LOG_PER_CONN,

View file

@ -2988,6 +2988,16 @@ export {
##
## .. zeek:see:: smb_pipe_connect_heuristic
const SMB::pipe_filenames: set[string] &redef;
## The maximum number of messages for which to retain state
## about offsets, fids, or tree ids within the parser. When
## the limit is reached, internal parser state is discarded
## and :zeek:see:`smb2_discarded_messages_state` raised.
##
## Setting this to zero will disable the functionality.
##
## .. zeek:see:: smb2_discarded_messages_state
const SMB::max_pending_messages = 1000 &redef;
}
module SMB1;

View file

@ -44,6 +44,13 @@ export {
PRINT_CLOSE,
};
## Whether to reset a connection's SMB script state whenever a
## :zeek:see:`smb2_discarded_messages_state` event is raised.
##
## This setting protects from unbounded script state growth in
## environments with high capture loss or traffic anomalies.
option enable_clear_script_state = T;
## This record is for the smb_files.log
type FileInfo: record {
## Time when the file was first discovered.

View file

@ -1,3 +1,5 @@
@load base/frameworks/notice/weird
@load ./main
module SMB2;
@ -344,3 +346,25 @@ event smb2_close_request(c: connection, hdr: SMB2::Header, file_id: SMB2::GUID)
#Reporter::warning("attempting to close an unknown file!");
}
}
event smb2_discarded_messages_state(c: connection, state: string)
{
if ( ! c?$smb_state )
return;
local addl = fmt("state=%s fid_map=%s tid_map=%s pending_cmds=%s pipe_map=%s",
state, |c$smb_state$fid_map|, |c$smb_state$tid_map|,
|c$smb_state$pending_cmds|, |c$smb_state$pipe_map|);
Reporter::conn_weird("SMB_discarded_messages_state", c, addl, "SMB2");
if ( ! SMB::enable_clear_script_state )
return;
# Wipe out script-level state for this connection.
c$smb_state$fid_map = table();
c$smb_state$pending_cmds = table();
# Not expected to grow overly large and the original
# zeek-smb-clear-state package didn't reset these either.
# c$smb_state$tid_map = table();
# c$smb_state$pipe_map = table();
}

View file

@ -1 +1,2 @@
const SMB::pipe_filenames: string_set;
const SMB::pipe_filenames: string_set;
const SMB::max_pending_messages: count;

View file

@ -17,6 +17,17 @@ refine connection SMB_Conn += {
function proc_smb2_ioctl_request(val: SMB2_ioctl_request) : bool
%{
if ( zeek::BifConst::SMB::max_pending_messages > 0 &&
smb2_ioctl_fids.size() >= zeek::BifConst::SMB::max_pending_messages )
{
if ( smb2_discarded_messages_state )
zeek::BifEvent::enqueue_smb2_discarded_messages_state(zeek_analyzer(), zeek_analyzer()->Conn(),
zeek::make_intrusive<zeek::StringVal>("ioctl"));
smb2_ioctl_fids.clear();
}
smb2_ioctl_fids[${val.header.message_id}] = ${val.file_id.persistent} + ${val.file_id._volatile};
return true;
%}

View file

@ -34,6 +34,17 @@ refine connection SMB_Conn += {
${val.read_len});
}
if ( zeek::BifConst::SMB::max_pending_messages > 0 &&
(smb2_read_offsets.size() >= zeek::BifConst::SMB::max_pending_messages ||
smb2_read_fids.size() >= zeek::BifConst::SMB::max_pending_messages) )
{
if ( smb2_discarded_messages_state )
zeek::BifEvent::enqueue_smb2_discarded_messages_state(zeek_analyzer(), zeek_analyzer()->Conn(),
zeek::make_intrusive<zeek::StringVal>("read"));
smb2_read_offsets.clear();
smb2_read_fids.clear();
}
smb2_read_offsets[${h.message_id}] = ${val.offset};
smb2_read_fids[${h.message_id}] = ${val.file_id.persistent} + ${val.file_id._volatile};

View file

@ -230,6 +230,16 @@ refine connection SMB_Conn += {
%{
if ( is_orig )
{
if ( zeek::BifConst::SMB::max_pending_messages > 0 &&
smb2_request_tree_id.size() >= zeek::BifConst::SMB::max_pending_messages )
{
if ( smb2_discarded_messages_state )
zeek::BifEvent::enqueue_smb2_discarded_messages_state(zeek_analyzer(), zeek_analyzer()->Conn(),
zeek::make_intrusive<zeek::StringVal>("tree"));
smb2_request_tree_id.clear();
}
// Store the tree_id
smb2_request_tree_id[${h.message_id}] = ${h.tree_id};
}

View file

@ -15,3 +15,16 @@
##
## .. zeek:see:: smb1_message
event smb2_message%(c: connection, hdr: SMB2::Header, is_orig: bool%);
## Generated for :abbr:`SMB (Server Message Block)`/:abbr:`CIFS (Common Internet File System)`
## version 2 connections for which pending read, ioctl or tree requests exceeds
## the :zeek:see:`SMB::max_pending_messages` setting. This event indicates either
## traffic loss, traffic load-balancing issues, or failures to parse or match
## SMB responses with SMB requests. When this event is raised, internal per-connection
## parser state has been reset.
##
## c: The affected connection.
##
## state: String describing what kind of state was affected.
## One of read, ioctl or tree.
event smb2_discarded_messages_state%(c: connection, state: string%);

View file

@ -575,6 +575,7 @@
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (RDP::disable_analyzer_after_detection, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (RDP::rdp_check_interval, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (SIP::sip_methods, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (SMB::enable_clear_script_state, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (SMB::logged_file_actions, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (SMTP::mail_path_capture, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (SMTP::mail_transaction_validation, Config::config_option_changed{ if (<skip-config-log> == 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)) -> <no result>
@ -2194,6 +2195,7 @@
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (RDP::disable_analyzer_after_detection, Config::config_option_changed{ if (<skip-config-log> == 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))
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (RDP::rdp_check_interval, Config::config_option_changed{ if (<skip-config-log> == 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))
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (SIP::sip_methods, Config::config_option_changed{ if (<skip-config-log> == 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))
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (SMB::enable_clear_script_state, Config::config_option_changed{ if (<skip-config-log> == 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))
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (SMB::logged_file_actions, Config::config_option_changed{ if (<skip-config-log> == 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))
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (SMTP::mail_path_capture, Config::config_option_changed{ if (<skip-config-log> == 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))
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (SMTP::mail_transaction_validation, Config::config_option_changed{ if (<skip-config-log> == 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))
@ -3812,6 +3814,7 @@
0.000000 | HookCallFunction Option::set_change_handler(RDP::disable_analyzer_after_detection, Config::config_option_changed{ if (<skip-config-log> == 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)
0.000000 | HookCallFunction Option::set_change_handler(RDP::rdp_check_interval, Config::config_option_changed{ if (<skip-config-log> == 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)
0.000000 | HookCallFunction Option::set_change_handler(SIP::sip_methods, Config::config_option_changed{ if (<skip-config-log> == 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)
0.000000 | HookCallFunction Option::set_change_handler(SMB::enable_clear_script_state, Config::config_option_changed{ if (<skip-config-log> == 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)
0.000000 | HookCallFunction Option::set_change_handler(SMB::logged_file_actions, Config::config_option_changed{ if (<skip-config-log> == 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)
0.000000 | HookCallFunction Option::set_change_handler(SMTP::mail_path_capture, Config::config_option_changed{ if (<skip-config-log> == 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)
0.000000 | HookCallFunction Option::set_change_handler(SMTP::mail_transaction_validation, Config::config_option_changed{ if (<skip-config-log> == 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)

View file

@ -0,0 +1,25 @@
### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, read, 15
smb2_discarded_messages_state after, read, 0
smb2_discarded_messages_state before, tree, 5
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, read, 15
smb2_discarded_messages_state after, read, 0
smb2_discarded_messages_state before, tree, 5
smb2_discarded_messages_state after, tree, 0
smb2_discarded_messages_state before, tree, 20
smb2_discarded_messages_state after, tree, 0

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 CHhAvVGS1DHFjwGM9 127.0.0.1 34884 127.0.0.1 445 SMB_discarded_messages_state state=tree fid_map=0 tid_map=2 pending_cmds=20 pipe_map=0 F zeek SMB2
#close XXXX-XX-XX-XX-XX-XX

Binary file not shown.

View file

@ -0,0 +1,18 @@
# @TEST-DOC: Pcap contains 100 file transfers (read requests), force BPF filtering such that the responses aren't seen and we have state growth. Verify a low SMB::max_pending_messages triggers, logs a weird and that script-land message state is reset.
# @TEST-EXEC: zeek -b -C -r $TRACES/smb/smb2_100_small_files.pcap -f 'src port not 445 or tcp[tcpflags] & (tcp-syn|tcp-fin|tcp-rst) != 0' %INPUT >out
# @TEST-EXEC: btest-diff weird.log
# @TEST-EXEC: btest-diff out
@load base/protocols/smb
redef SMB::max_pending_messages = 20;
event smb2_discarded_messages_state(c: connection, request: string) &priority=10
{
print "smb2_discarded_messages_state before", request, |c$smb_state$pending_cmds|;
}
event smb2_discarded_messages_state(c: connection, request: string) &priority=-10
{
print "smb2_discarded_messages_state after", request, |c$smb_state$pending_cmds|;
}