Mirror/zeek
1
0
Fork 0
mirror of https://github.com/zeek/zeek.git synced 2025-10-02 14:48:21 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 2

Merge remote-tracking branch 'origin/topic/awelzel/1705-http-pending-requests'

Browse source 
* origin/topic/awelzel/1705-http-pending-requests:
  http: Prevent request/response de-synchronization and unbounded state growth
This commit is contained in:
Arne Welzel 2023-09-01 11:53:55 +02:00
commit 14a2c02f9d
15 changed files with 137 additions and 3 deletions
Download patch file Download diff file Expand all files Collapse all files

16
CHANGES
View file

@ -1,3 +1,19 @@
6.1.0-dev.358 | 2023-09-01 11:53:55 +0200
* GH-1705: http: Prevent request/response de-synchronization and unbounded state growth (Arne Welzel, Corelight)
When http_reply events are received before http_request events, either
through faking traffic or possible re-ordering, it is possible to trigger
unbounded state growth due to later http_requests never being matched
again with responses.
Prevent this by synchronizing request/response counters when late
requests come in.
Also forcefully flush pending requests when http_replies are never
observed either due to the analyzer having been disabled or because
half-duplex traffic.
6.1.0-dev.356 | 2023-08-30 11:24:51 +0200
* testing/external: Exclude telemetry.log from baselines (Arne Welzel, Corelight)

5
NEWS
View file

@ -82,6 +82,11 @@ Changed Functionality
anymore. Previously, broadcast packets originating from a likely server port
resulted in 255.255.255.255 being the originator in ``conn.log``.
- When too many HTTP requests are pending, Zeek will now log them at once and
reset request/response correlation instead of running into unbounded state
growth. This behavior is configurable via a new option ``HTTP::max_pending_requests``.
The default is ``100``.
Removed Functionality
---------------------

2
VERSION
View file

@ -1 +1 @@
6.1.0-dev.356
6.1.0-dev.358

2
scripts/base/frameworks/notice/weird.zeek
View file

@ -144,7 +144,9 @@ export {
["FTP_password_too_long"] = ACTION_LOG_PER_CONN,
["HTTP_bad_chunk_size"] = ACTION_LOG,
["HTTP_chunked_transfer_for_multipart_message"] = ACTION_LOG,
["HTTP_excessive_pipelining"] = ACTION_LOG,
["HTTP_overlapping_messages"] = ACTION_LOG,
["HTTP_response_before_request"] = ACTION_LOG,
["unknown_HTTP_method"] = ACTION_LOG,
["HTTP_version_mismatch"] = ACTION_LOG,
["ident_request_addendum"] = ACTION_LOG,

47
scripts/base/protocols/http/main.zeek
View file

@ -133,6 +133,12 @@ export {
## HTTP finalization hook. Remaining HTTP info may get logged when it's called.
global finalize_http: Conn::RemovalHook;
## Only allow that many pending requests on a single connection.
## If this number is exceeded, all pending requests are flushed
## out and request/response tracking reset to prevent unbounded
## state growth.
option max_pending_requests = 100;
}
# Add the http state tracking fields to the connection record.
@ -205,6 +211,47 @@ event http_request(c: connection, method: string, original_URI: string,
Conn::register_removal_hook(c, finalize_http);
}
# Request/response tracking exists to account for HTTP pipelining.
# It fails if more responses have been seen than requests. If that
# happens, just fast-forward current_request such that the next
# response matches the in-flight request.
if ( c$http_state$current_request < c$http_state$current_response )
{
Reporter::conn_weird("HTTP_response_before_request", c);
c$http_state$current_request = c$http_state$current_response;
}
# Too many requests are pending for which we have not yet observed a
# reply. This might be due to excessive HTTP pipelining, one-sided
# traffic capture, or the responder side of the HTTP analyzer having
# been disabled. In any case, we simply log out all pending requests
# to make room for a new one. Any matching of pipelined requests and
# responses is most likely totally off anyhow.
if ( max_pending_requests > 0 && |c$http_state$pending| > max_pending_requests )
{
Reporter::conn_weird("HTTP_excessive_pipelining", c);
if ( c$http_state$current_response == 0 )
++c$http_state$current_response;
while ( c$http_state$current_response < c$http_state$current_request )
{
local cr = c$http_state$current_response;
if ( cr in c$http_state$pending )
{
Log::write(HTTP::LOG, c$http_state$pending[cr]);
delete c$http_state$pending[cr];
}
else
{
# The above should have been true...
# Reporter::error(fmt("Expected pending request at %d", cr));
}
++c$http_state$current_response;
}
}
++c$http_state$current_request;
set_state(c, T);

3
testing/btest/Baseline/plugins.hooks/output
View file

@ -559,6 +559,7 @@
0.000000 MetaHookPost CallFunction(Option::set_change_handler, <frame>, (HTTP::http_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>, (HTTP::max_files_orig, 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>, (HTTP::max_files_resp, 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>, (HTTP::max_pending_requests, 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>, (HTTP::proxy_headers, 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>, (Input::default_mode, 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>, (Input::default_reader, 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>
@ -2185,6 +2186,7 @@
0.000000 MetaHookPre CallFunction(Option::set_change_handler, <frame>, (HTTP::http_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>, (HTTP::max_files_orig, 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>, (HTTP::max_files_resp, 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>, (HTTP::max_pending_requests, 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>, (HTTP::proxy_headers, 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>, (Input::default_mode, 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>, (Input::default_reader, 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))
@ -3810,6 +3812,7 @@
0.000000 | HookCallFunction Option::set_change_handler(HTTP::http_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(HTTP::max_files_orig, 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(HTTP::max_files_resp, 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(HTTP::max_pending_requests, 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(HTTP::proxy_headers, 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(Input::default_mode, 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(Input::default_reader, 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)

4
testing/btest/Baseline/scripts.base.protocols.http.http-09-content-length-confusion/http.log
View file

@ -7,6 +7,6 @@
#open XXXX-XX-XX-XX-XX-XX
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p trans_depth method host uri referrer version user_agent origin request_body_len response_body_len status_code status_msg info_code info_msg tags username password proxied orig_fuids orig_filenames orig_mime_types resp_fuids resp_filenames resp_mime_types
#types time string addr port addr port count string string string string string string string count count count string count string set[enum] string string set[string] vector[string] vector[string] vector[string] vector[string] vector[string] vector[string]
XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 127.0.0.1 46982 127.0.0.1 80 1 GET - / - 1.1 - - 0 0 200 OK - - (empty) - - - - - - - - -
XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 127.0.0.1 46982 127.0.0.1 80 2 - - - - 0.9 - - 0 19 0 <empty> - - (empty) - - - - - - F7s8014qOBt9Gyy3w7 - text/plain
XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 127.0.0.1 46982 127.0.0.1 80 1 - - - - 1.1 - - 0 0 200 OK - - (empty) - - - - - - - - -
XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 127.0.0.1 46982 127.0.0.1 80 2 GET - / - 0.9 - - 0 19 0 <empty> - - (empty) - - - - - - F7s8014qOBt9Gyy3w7 - text/plain
#close XXXX-XX-XX-XX-XX-XX

1
testing/btest/Baseline/scripts.base.protocols.http.http-09-content-length-confusion/weird.log
View file

@ -8,5 +8,6 @@
#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 46982 127.0.0.1 80 http_09_reply_before_request - F zeek HTTP
XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 127.0.0.1 46982 127.0.0.1 80 HTTP_response_before_request - F zeek -
XXXXXXXXXX.XXXXXX CHhAvVGS1DHFjwGM9 127.0.0.1 46982 127.0.0.1 80 HTTP_version_mismatch - F zeek HTTP
#close XXXX-XX-XX-XX-XX-XX

17
testing/btest/Baseline/scripts.base.protocols.http.http-desynched/http.log Normal file
View file

@ -0,0 +1,17 @@
### 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 http
#open XXXX-XX-XX-XX-XX-XX
#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p trans_depth method host uri referrer version user_agent origin request_body_len response_body_len status_code status_msg info_code info_msg tags username password proxied orig_fuids orig_filenames orig_mime_types resp_fuids resp_filenames resp_mime_types
#types time string addr port addr port count string string string string string string string count count count string count string set[enum] string string set[string] vector[string] vector[string] vector[string] vector[string] vector[string] vector[string]
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 1 GET localhost:8080 / - 1.1 python-requests/2.31.0 - 0 19 200 OK - - (empty) - - - - - - FlUDto3MxYxQV9pVnf - text/html
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 2 - - - - 1.1 - - 0 19 200 OK - - (empty) - - - - - - F7ynSw2U0QnJcw9Qth - text/html
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 3 - - - - 1.1 - - 0 19 200 OK - - (empty) - - - - - - FeY8eU1T8QwTaI0456 - text/html
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 4 GET localhost:8080 / - 1.1 python-requests/2.31.0 - 0 19 200 OK - - (empty) - - - - - - FfzjgM2OnUfAX9LnAd - text/html
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 5 GET localhost:8080 / - 1.1 python-requests/2.31.0 - 0 19 200 OK - - (empty) - - - - - - FtPJJF1xSxzd8blV4g - text/html
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 6 GET localhost:8080 / - 1.1 python-requests/2.31.0 - 0 19 200 OK - - (empty) - - - - - - FkCd8G2tsvSm17YOj6 - text/html
XXXXXXXXXX.XXXXXX ClEkJM2Vm5giqnMf4h 127.0.0.1 50170 127.0.0.1 8080 7 GET localhost:8080 / - 1.1 python-requests/2.31.0 - 0 19 200 OK - - (empty) - - - - - - FSa22J3bRk1Qv0hkE1 - text/html
#close XXXX-XX-XX-XX-XX-XX

4
testing/btest/Baseline/scripts.base.protocols.http.http-pending-state-growth/out Normal file
View file

@ -0,0 +1,4 @@
### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
http_state pending, 100
total http.log lines
1000

11
testing/btest/Baseline/scripts.base.protocols.http.http-pending-state-growth/weird.log Normal file
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 ::1 44730 ::1 80 HTTP_excessive_pipelining - F zeek -
#close XXXX-XX-XX-XX-XX-XX

BIN
testing/btest/Traces/http/1000-requests-one-dropped-response.pcap.gz Normal file
View file

Binary file not shown.

BIN
testing/btest/Traces/http/http-desync-request-response-5.pcap Normal file
View file

Binary file not shown.

13
testing/btest/scripts/base/protocols/http/http-desynched.zeek Normal file
View file

@ -0,0 +1,13 @@
# @TEST-DOC: 5 HTTP requests, the first one is responded to with 3 HTTP responses.
#
# @TEST-EXEC: zeek -b -r $TRACES/http/http-desync-request-response-5.pcap %INPUT
# @TEST-EXEC: btest-diff http.log
@load base/protocols/http
# mime type is irrelevant to this test, so filter it out
event zeek_init()
{
Log::remove_default_filter(HTTP::LOG);
Log::add_filter(HTTP::LOG, [$name="less-mime-types", $exclude=set("mime_type")]);
}

15
testing/btest/scripts/base/protocols/http/http-pending-state-growth.zeek Normal file
View file

@ -0,0 +1,15 @@
# @TEST-DOC: Pcap has a gap for the server side. This previously caused unbounded state growth in c$http_state$pending.
#
# @TEST-EXEC: zcat <$TRACES/http/1000-requests-one-dropped-response.pcap.gz | zeek -C -b -r - %INPUT >out
# @TEST-EXEC: echo "total http.log lines" >>out
# @TEST-EXEC: grep -v '^#' http.log | wc -l | sed 's/ //g' >>out
# @TEST-EXEC: btest-diff out
# @TEST-EXEC: btest-diff weird.log
@load base/protocols/http
event connection_state_remove(c: connection)
{
if ( c?$http_state )
print "http_state pending", |c$http_state$pending|;
}