Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Crash 6.2.0 : Flare.cc: zeek::detail::bad_pipe_op #3682

Open
initconf opened this issue Apr 11, 2024 · 6 comments
Open

Crash 6.2.0 : Flare.cc: zeek::detail::bad_pipe_op #3682

initconf opened this issue Apr 11, 2024 · 6 comments
Assignees
@awelzel

Comments

@initconf
Copy link

I have been seeing intermittent crashes in 6.2.0 with the following coredump:

For reference:

(gdb) bt
#0  0x0000000803888bca in thr_kill () from /lib/libc.so.7
#1  0x0000000803886f94 in raise () from /lib/libc.so.7
#2  0x00000008037ff489 in abort () from /lib/libc.so.7
#3  0x0000000000cec2d1 in zeek::Reporter::FatalErrorWithCore (this=<optimized out>, fmt=<optimized out>) at /usr/local/src/zeek-6.0.1/src/Reporter.cc:154
#4  0x0000000000c8966f in zeek::detail::bad_pipe_op (which=0x4d1b9d "read", signal_safe=<optimized out>) at /usr/local/src/zeek-6.0.1/src/Flare.cc:76
#5  0x0000000000c896d5 in zeek::detail::Flare::Extinguish (this=0x8a4558ca4, signal_safe=false) at /usr/local/src/zeek-6.0.1/src/Flare.cc:153
#6  0x0000000000d9a04b in zeek::threading::MsgThread::Process (this=0x8a4558800) at /usr/local/src/zeek-6.0.1/src/threading/MsgThread.cc:517
#7  0x0000000000d16ed6 in zeek::run_state::detail::run_loop () at /usr/local/src/zeek-6.0.1/src/RunState.cc:349
#8  0x00000000007506c8 in main (argc=<optimized out>, argv=<optimized out>) at /usr/local/src/zeek-6.0.1/src/main.cc:102

I'll try to see how I can replicate it - so far different physical clusters have showing this crash - albeit very intermittent - I don't see a predictive pattern yet!
@leres
Copy link
Contributor

leres commented Apr 11, 2024

I'm seeing similar crashes with 6.0.3 (standalone):

(gdb) bt
#0  0x000000082e80841a in thr_kill () from /lib/libc.so.7
#1  0x000000082e781e64 in raise () from /lib/libc.so.7
#2  0x000000082e8326f9 in abort () from /lib/libc.so.7
#3  0x0000000000fb863f in zeek::Reporter::FatalErrorWithCore(char const*, ...) ()
#4  0x0000000000f5150a in zeek::detail::bad_pipe_op(char const*, bool) ()
#5  0x0000000000f51576 in zeek::detail::Flare::Extinguish(bool) ()
#6  0x000000000106c92b in zeek::threading::MsgThread::Process() ()
#7  0x0000000000fe46d6 in zeek::run_state::detail::run_loop() ()
#8  0x00000000012542f1 in main ()

Unfortunately I did not have debugging symbols enabled (I do now).

@timwoj
Copy link
Contributor

timwoj commented Apr 15, 2024

I'm seeing similar crashes with 6.0.3 (standalone):

Dang, I was really hoping this was something specific to 6.2.

@leres
Copy link
Contributor

leres commented May 5, 2024

I had my first crash since building with debugging symbols (RELWITHDEBINFO) but I'm not sure that it's related:

(gdb) bt
#0  0x000000082e63041a in ?? ()
#1  0x000000082e5a9e64 in ?? ()
#2  0x0000000000018d19 in ?? ()
#3  0xfd1399c053131912 in ?? ()
#4  0x00000008219cabe4 in ?? ()
#5  0x00000008376490a4 in ?? ()
#6  0x00000008219cac00 in ?? ()
#7  0x000000082e65a6f9 in ?? ()
#8  0x0000000832d3e000 in ?? ()
#9  0x000000082e6d61f0 in ?? ()
#10 0xffffffdf2e6d61f0 in ?? ()
#11 0xffffffffffffffff in ?? ()
#12 0x00000008ffffffff in ?? ()
#13 0x00000000006d6bf0 in ?? ()
#14 0x00000008219cace0 in ?? ()
#15 0x0000000000f7b1f1 in zeek::Reporter::FatalErrorWithCore (
    this=<optimized out>, fmt=<optimized out>)
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/Reporter.cc:154
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

The fatal error was:

May  5 01:37:14 fatal error: unexpected pipe read failure: Bad file descriptor

@leres
Copy link
Contributor

leres commented May 5, 2024

I lied, I see now I had crash a week ago that looks related to this problem:

(gdb) bt
#0  0x000000082caec41a in thr_kill () from /lib/libc.so.7
#1  0x000000082ca65e64 in raise () from /lib/libc.so.7
#2  0x000000082cb166f9 in abort () from /lib/libc.so.7
#3  0x0000000000f7b1f1 in zeek::Reporter::FatalErrorWithCore (
    this=<optimized out>, fmt=<optimized out>)
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/Reporter.cc:154
#4  0x0000000000f186cf in zeek::detail::bad_pipe_op (which=0x6d6bf0 "read", 
    signal_safe=<optimized out>)
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/Flare.cc:76
#5  0x0000000000f18735 in zeek::detail::Flare::Extinguish (this=0x870dbdca4, 
    signal_safe=false)
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/Flare.cc:153
#6  0x00000000010287fb in zeek::threading::MsgThread::Process (
    this=0x870dbd800)
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/threading/MsgThread.cc:517
#7  0x0000000000fa5906 in zeek::run_state::detail::run_loop ()
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/RunState.cc:349
#8  0x00000000011fe1de in main (argc=<optimized out>, argv=<optimized out>)
    at /wrkdirs/usr/ports/security/zeek/work/zeek-6.0.3/src/main.cc:102

And the log says:

May  5 01:37:14 fatal error: unexpected pipe read failure: Bad file descriptor

(The same error as today so maybe that was related but the stack got trashed...)

So maybe the process on the other end of the pipe is gone and EBADF should not be fatal?

Happy to make files available for analysis (note that the debugging symbol zeek is quite large...)

@awelzel
Copy link
Contributor

awelzel commented Jun 11, 2024

Can reproduce back to 4.0.9 with the following script. It happens instantaneously on 6.0+ likely due to the more efficient/aggressive IO loop.

The crux for the reproducer is the much lowered Threading::heartbeat_interval. From inspecting the code and (confirmed by the ASAN backtraces), the threading manager's heartbeat timer cleans and deletes a raw reader thread instance created by Exec::run, but that backend reader is also still in the list of IO sources to be processed during this loop iteration, causing the heap-use-after-free or double pipe close.

pipeout sees much traffic.

Abort

/opt/zeek-6.2/bin/zeek -C -i pipeout ./repo.zeek 
listening on pipeout

1718110403.605014 fatal error: unexpected pipe read failure: Bad file descriptor
Aborted (core dumped)

$ coredumpctl debug
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=140433290820480) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=140433290820480) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=140433290820480, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007fb928442476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007fb9284287f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x0000565513ec1bb8 in zeek::Reporter::FatalErrorWithCore (this=<optimized out>, fmt=fmt@entry=0x56551349ed80 "unexpected pipe %s failure: %s") at /home/awelzel/corelight-oss/zeek-release-6.2/src/Reporter.cc:140
#6  0x0000565513e448d5 in zeek::detail::bad_pipe_op (which=which@entry=0x5655134548e9 "read", signal_safe=signal_safe@entry=false) at /home/awelzel/corelight-oss/zeek-release-6.2/src/Flare.cc:69
#7  0x0000565513e44a2c in zeek::detail::Flare::Extinguish (this=this@entry=0x7fb922344724, signal_safe=signal_safe@entry=false) at /home/awelzel/corelight-oss/zeek-release-6.2/src/Flare.cc:139
#8  0x0000565513f8be94 in zeek::threading::MsgThread::Process (this=0x7fb922343c00) at /home/awelzel/corelight-oss/zeek-release-6.2/src/threading/MsgThread.cc:421
#9  0x0000565513ef4957 in zeek::run_state::detail::run_loop () at /home/awelzel/corelight-oss/zeek-release-6.2/src/RunState.cc:289
#10 0x0000565514168829 in main (argc=<optimized out>, argv=<optimized out>) at /home/awelzel/corelight-oss/zeek-release-6.2/src/main.cc:93

ASAN

# zeek -C -i af_packet::pipeout ./repo.zeek 
listening on pipeout

=================================================================
==3988038==ERROR: AddressSanitizer: heap-use-after-free on address 0x61f00004ecb9 at pc 0x561a15933723 bp 0x7ffd6869ff90 sp 0x7ffd6869ff80
READ of size 1 at 0x61f00004ecb9 thread T0
    #0 0x561a15933722 in zeek::iosource::IOSource::ImplementsProcessFd() const /home/awelzel/corelight-oss/zeek/src/include/zeek/iosource/IOSource.h:84
    #1 0x561a15933722 in zeek::run_state::detail::run_loop() /home/awelzel/corelight-oss/zeek/src/RunState.cc:286
    #2 0x561a162d74af in main /home/awelzel/corelight-oss/zeek/src/main.cc:93
    #3 0x7fe2daa29d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
    #4 0x7fe2daa29e3f in __libc_start_main_impl ../csu/libc-start.c:392
    #5 0x561a13d3d154 in _start (/home/awelzel/corelight-oss/zeek/build/src/zeek+0xca7154)

0x61f00004ecb9 is located 57 bytes inside of 3176-byte region [0x61f00004ec80,0x61f00004f8e8)
freed by thread T0 here:
    #0 0x7fe2e10b724f in operator delete(void*, unsigned long) ../../../../src/libsanitizer/asan/asan_new_delete.cpp:172
    #1 0x561a14f0cb31 in zeek::input::reader::detail::Raw::~Raw() /home/awelzel/corelight-oss/zeek/src/input/readers/raw/Raw.cc:60
    #2 0x561a15b59d58 in zeek::threading::Manager::SendHeartbeats() /home/awelzel/corelight-oss/zeek/src/threading/Manager.cc:117
    #3 0x561a15b5a0b8 in zeek::threading::detail::HeartbeatTimer::Dispatch(double, bool) /home/awelzel/corelight-oss/zeek/src/threading/Manager.cc:19
    #4 0x561a159bf4f0 in zeek::detail::TimerMgr::DoAdvance(double, int) /home/awelzel/corelight-oss/zeek/src/Timer.cc:137
    #5 0x561a159bf754 in zeek::detail::TimerMgr::Advance(double, int) /home/awelzel/corelight-oss/zeek/src/Timer.cc:85
    #6 0x561a15931613 in zeek::run_state::detail::expire_timers() /home/awelzel/corelight-oss/zeek/src/RunState.cc:221
    #7 0x561a15931949 in zeek::run_state::detail::dispatch_packet(zeek::Packet*, zeek::iosource::PktSrc*) /home/awelzel/corelight-oss/zeek/src/RunState.cc:240
    #8 0x561a14f367c4 in zeek::iosource::PktSrc::Process() /home/awelzel/corelight-oss/zeek/src/iosource/PktSrc.cc:120
    #9 0x561a15933755 in zeek::run_state::detail::run_loop() /home/awelzel/corelight-oss/zeek/src/RunState.cc:289
    #10 0x561a162d74af in main /home/awelzel/corelight-oss/zeek/src/main.cc:93
    #11 0x7fe2daa29d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58

previously allocated by thread T0 here:
    #0 0x7fe2e10b61e7 in operator new(unsigned long) ../../../../src/libsanitizer/asan/asan_new_delete.cpp:99
    #1 0x561a14f13a85 in zeek::input::reader::detail::Raw::Instantiate(zeek::input::ReaderFrontend*) /home/awelzel/corelight-oss/zeek/src/include/zeek/input/readers/raw/Raw.h:29
    #2 0x561a14eab370 in zeek::input::Manager::CreateBackend(zeek::input::ReaderFrontend*, zeek::EnumVal*) /home/awelzel/corelight-oss/zeek/src/input/Manager.cc:187
    #3 0x561a14ee88b3 in zeek::input::ReaderFrontend::ReaderFrontend(zeek::input::ReaderBackend::ReaderInfo const&, zeek::EnumVal*) /home/awelzel/corelight-oss/zeek/src/input/ReaderFrontend.cc:36
    #4 0x561a14eae9ee in zeek::input::Manager::CreateStream(zeek::input::Manager::Stream*, zeek::RecordVal*) /home/awelzel/corelight-oss/zeek/src/input/Manager.cc:252
    #5 0x561a14eb7c3d in zeek::input::Manager::CreateEventStream(zeek::RecordVal*) /home/awelzel/corelight-oss/zeek/src/input/Manager.cc:377
    #6 0x561a15765183 in zeek::BifFunc::Input::__create_event_stream_bif(zeek::detail::Frame*, std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > > const*) /home/awelzel/corelight-oss/zeek/src/input/input.bif:27
    #7 0x561a15721e5f in zeek::detail::BuiltinFunc::Invoke(std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >*, zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Func.cc:739
    #8 0x561a1569327b in zeek::detail::CallExpr::Eval(zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Expr.cc:4116
    #9 0x561a1597765f in zeek::detail::ReturnStmt::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1404
    #10 0x561a1597b787 in zeek::detail::StmtList::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1439
    #11 0x561a1572c2a8 in zeek::detail::ScriptFunc::Invoke(std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >*, zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Func.cc:386
    #12 0x561a1569327b in zeek::detail::CallExpr::Eval(zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Expr.cc:4116
    #13 0x561a1597a61c in zeek::detail::ExprStmt::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:389
    #14 0x561a1597b787 in zeek::detail::StmtList::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1439
    #15 0x561a1572c2a8 in zeek::detail::ScriptFunc::Invoke(std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >*, zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Func.cc:386
    #16 0x561a1569327b in zeek::detail::CallExpr::Eval(zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Expr.cc:4116
    #17 0x561a15683120 in zeek::detail::AssignExpr::Eval(zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Expr.cc:2401
    #18 0x561a15675e78 in zeek::detail::UnaryExpr::Eval(zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Expr.cc:541
    #19 0x561a1597765f in zeek::detail::ReturnStmt::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1404
    #20 0x561a1597a95e in zeek::detail::IfStmt::DoExec(zeek::detail::Frame*, zeek::Val*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:455
    #21 0x561a1597a6a4 in zeek::detail::ExprStmt::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:392
    #22 0x561a1597b787 in zeek::detail::StmtList::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1439
    #23 0x561a1572c2a8 in zeek::detail::ScriptFunc::Invoke(std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >*, zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Func.cc:386
    #24 0x561a1569327b in zeek::detail::CallExpr::Eval(zeek::detail::Frame*) const /home/awelzel/corelight-oss/zeek/src/Expr.cc:4116
    #25 0x561a159c51a5 in zeek::detail::trigger::Trigger::Eval() /home/awelzel/corelight-oss/zeek/src/Trigger.cc:245
    #26 0x561a159c8537 in zeek::detail::trigger::Trigger::Trigger(std::shared_ptr<zeek::detail::WhenInfo>, std::unordered_set<zeek::detail::ID const*, std::hash<zeek::detail::ID const*>, std::equal_to<zeek::detail::ID const*>, std::allocator<zeek::detail::ID const*> > const&, std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >, double, zeek::detail::Frame*, zeek::detail::Location const*) /home/awelzel/corelight-oss/zeek/src/Trigger.cc:141
    #27 0x561a159adef9 in zeek::IntrusivePtr<zeek::detail::trigger::Trigger> zeek::make_intrusive<zeek::detail::trigger::Trigger, std::shared_ptr<zeek::detail::WhenInfo>&, std::unordered_set<zeek::detail::ID const*, std::hash<zeek::detail::ID const*>, std::equal_to<zeek::detail::ID const*>, std::allocator<zeek::detail::ID const*> > const&, std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >&, double&, zeek::detail::Frame*&, zeek::detail::Location*&>(std::shared_ptr<zeek::detail::WhenInfo>&, std::unordered_set<zeek::detail::ID const*, std::hash<zeek::detail::ID const*>, std::equal_to<zeek::detail::ID const*>, std::allocator<zeek::detail::ID const*> > const&, std::vector<zeek::IntrusivePtr<zeek::Val>, std::allocator<zeek::IntrusivePtr<zeek::Val> > >&, double&, zeek::detail::Frame*&, zeek::detail::Location*&) /home/awelzel/corelight-oss/zeek/src/include/zeek/IntrusivePtr.h:179
    #28 0x561a159a6be4 in zeek::detail::WhenStmt::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1967
    #29 0x561a1597b787 in zeek::detail::StmtList::Exec(zeek::detail::Frame*, zeek::detail::StmtFlowType&) /home/awelzel/corelight-oss/zeek/src/Stmt.cc:1439

SUMMARY: AddressSanitizer: heap-use-after-free /home/awelzel/corelight-oss/zeek/src/include/zeek/iosource/IOSource.h:84 in zeek::iosource::IOSource::ImplementsProcessFd() const

Reproducer

# repo.zeek
@load base/utils/exec

redef Threading::heartbeat_interval = 0.001sec;

event run_it()
        {
        local cmd = fmt("sleep %f && date", rand(200) / 10000.0);
        # print network_time(), "run_it", cmd;
        when [cmd] ( local r = Exec::run([$cmd=cmd]) ) {
                # print "done", r;
        }


        local sleep_for = double_to_interval(rand(100) / 10000.0);
        schedule sleep_for { run_it() };
        }

event zeek_init()
        {
        schedule 0.01sec { run_it() };
        }

@awelzel
Copy link
Contributor

awelzel commented Jun 11, 2024

I don't quite know how to fix this yet, but I'll assign myself for now.

@awelzel awelzel self-assigned this Jun 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@awelzel awelzel

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@leres @awelzel @timwoj @initconf