From f050d96503b9d551543b0503e32c51de5c500aa8 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Tue, 2 Jul 2024 12:12:15 +0200 Subject: [PATCH] threading/Manager: Warn if threads are added after termination The core.file-analyzer-violation test showed that it's possible to create new threads (log writers) when Zeek is in the process of terminating. This can result in the IO manager's deconstructor deleting IO sources for threads that are still running. This is sort of a scripting issue, so for now log a reporter warning when it happens to have a bit of a bread-crumb what might be going on. In the future it might make sense to plug APIs with zeek_is_terminating(). --- src/threading/Manager.cc | 9 +++++++++ src/threading/Manager.h | 1 + .../Baseline/core.file-analyzer-violation/.stderr | 2 ++ .../core.file-analyzer-violation/files.log | 1 + testing/btest/core/file-analyzer-violation.zeek | 14 ++++++++++++++ 5 files changed, 27 insertions(+) create mode 100644 testing/btest/Baseline/core.file-analyzer-violation/.stderr diff --git a/src/threading/Manager.cc b/src/threading/Manager.cc index 9bcdc925f4..5620a0bf80 100644 --- a/src/threading/Manager.cc +++ b/src/threading/Manager.cc @@ -28,6 +28,7 @@ Manager::Manager() { did_process = true; next_beat = 0; terminating = false; + terminated = false; } Manager::~Manager() { @@ -61,10 +62,18 @@ void Manager::Terminate() { all_threads.clear(); msg_threads.clear(); terminating = false; + terminated = true; } void Manager::AddThread(BasicThread* thread) { DBG_LOG(DBG_THREADING, "Adding thread %s ...", thread->Name()); + + // This can happen when log writers or other threads are + // created during the shutdown phase and results in unclean + // shutdowns. + if ( terminated ) + reporter->Warning("Thread %s added after threading manager terminated", thread->Name()); + all_threads.push_back(thread); if ( ! heartbeat_timer_running ) diff --git a/src/threading/Manager.h b/src/threading/Manager.h index 875e35290a..b075e6a70d 100644 --- a/src/threading/Manager.h +++ b/src/threading/Manager.h @@ -146,6 +146,7 @@ private: bool did_process; // True if the last Process() found some work to do. double next_beat; // Timestamp when the next heartbeat will be sent. bool terminating; // True if we are in Terminate(). + bool terminated; // True if Terminate() finished. msg_stats_list stats; diff --git a/testing/btest/Baseline/core.file-analyzer-violation/.stderr b/testing/btest/Baseline/core.file-analyzer-violation/.stderr new file mode 100644 index 0000000000..e3f6131b1d --- /dev/null +++ b/testing/btest/Baseline/core.file-analyzer-violation/.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. +received termination signal diff --git a/testing/btest/Baseline/core.file-analyzer-violation/files.log b/testing/btest/Baseline/core.file-analyzer-violation/files.log index abef87d6a6..3b26732673 100644 --- a/testing/btest/Baseline/core.file-analyzer-violation/files.log +++ b/testing/btest/Baseline/core.file-analyzer-violation/files.log @@ -8,3 +8,4 @@ #fields ts fuid uid id.orig_h id.orig_p id.resp_h id.resp_p source depth analyzers mime_type filename duration local_orig is_orig seen_bytes total_bytes missing_bytes overflow_bytes timedout parent_fuid #types time string string addr port addr port string count set[string] string string interval bool bool count count count count bool string XXXXXXXXXX.XXXXXX FKPuH630Tmj6UQUMP7 - - - - - ./myfile.exe 0 PE application/x-dosexec - 0.000000 - - 64 - 0 0 F - +#close XXXX-XX-XX-XX-XX-XX diff --git a/testing/btest/core/file-analyzer-violation.zeek b/testing/btest/core/file-analyzer-violation.zeek index 6d73d2bfb6..70757bc8d2 100644 --- a/testing/btest/core/file-analyzer-violation.zeek +++ b/testing/btest/core/file-analyzer-violation.zeek @@ -1,20 +1,34 @@ # @TEST-DOC: Verify analyzer_violation_info is raised for an invalid PE file. # @TEST-EXEC: zeek -b %INPUT +# @TEST-EXEC: btest-diff .stderr # @TEST-EXEC: btest-diff .stdout # @TEST-EXEC: btest-diff files.log @load base/frameworks/files @load base/files/pe +redef exit_only_after_terminate = T; + event analyzer_violation_info(tag: AllAnalyzers::Tag, info: AnalyzerViolationInfo) { print tag, info$reason, info$f$id, cat(info$f$info$analyzers); + terminate(); + } + +event force_terminate() + { + if ( zeek_is_terminating() ) + return; + + Reporter::error("force_terminate called - timeout?"); + terminate(); } event zeek_init() { local source: string = "./myfile.exe"; Input::add_analysis([$source=source, $name=source]); + schedule 10sec { force_terminate() }; } # This file triggers a binpac exception for PE that is reported through