TIMEOUT: lldb-shell :: Settings/TestCxxFrameFormatRecursive.test on Linux

[pfusik]

This test fails and it looks unrelated to my change in RISC-V target:

https://lab.llvm.org/buildbot/#/builders/59/builds/18799
https://lab.llvm.org/buildbot/#/builders/162/builds/23810
https://buildkite.com/llvm-project/github-pull-requests/builds/186443#_

[llvmbot]

@llvm/issue-subscribers-infrastructure

Author: Piotr Fusik (pfusik)

This test fails and it looks unrelated to my change in RISC-V target:

https://lab.llvm.org/buildbot/#/builders/59/builds/18799
https://lab.llvm.org/buildbot/#/builders/162/builds/23810
https://buildkite.com/llvm-project/github-pull-requests/builds/186443#_

[llvmbot]

@llvm/issue-subscribers-lldb

Author: Piotr Fusik (pfusik)

This test fails and it looks unrelated to my change in RISC-V target:

https://lab.llvm.org/buildbot/#/builders/59/builds/18799
https://lab.llvm.org/buildbot/#/builders/162/builds/23810
https://buildkite.com/llvm-project/github-pull-requests/builds/186443#_

[DavidSpickett]

Has failed on different changes too:
https://lab.llvm.org/buildbot/#/builders/59/builds/18797
https://lab.llvm.org/buildbot/#/builders/162/builds/23827
https://lab.llvm.org/buildbot/#/builders/162/builds/23824
https://lab.llvm.org/buildbot/#/builders/162/builds/23819
https://lab.llvm.org/buildbot/#/builders/162/builds/23814

You get the point, this is definitely flaky and it seems to have started sometime in the last couple of days.

[DavidSpickett]

@Michael137 as the author of the test. Do you see anything in the last couple of days that might cause this?

Any of the Mac OS bots seeing the same timeouts?

In the meantime I'll look through recent changes too.

[DavidSpickett]

It reproduces locally after a few runs, I should be able to bisect this.

[Michael137]

Hmmm it's not the most robust of tests I suppose. I XFAILed it because it causes an infinite recursion. I guess on some systems this just manifests as a hang. On my local system it blows the stack and crashes pretty quickly. I guess we can keep it XFAILed on linux for now. I do want to fix this at some point but it's a bit more work than I have time for at the moment

[DavidSpickett]

Bisect points to 6760857.

Which is trying to prevent a race condition so unless it's caused a deadlock in doing so, I guess that FormatEntity::Entry is larger than a single pointer which means larger stack frames which means stack exhaustion becomes random memory corruption instead.

(lldb) thread backtrace -c 40
* thread #1, name = 'lldb', stop reason = signal SIGSTOP
  * frame #0: 0x0000ffffb0769f64 libc.so.6`futex_wait(private=0, expected=2, futex_word=0x0000ffffb088bb10) at futex-internal.h:146:13
    frame #1: 0x0000ffffb0769f50 libc.so.6`__GI___lll_lock_wait_private(futex=0x0000ffffb088bb10) at lowlevellock.c:34:7
    frame #2: 0x0000ffffb077e770 libc.so.6`__libc_calloc(n=<unavailable>, elem_size=<unavailable>) at malloc.c:3650:5
    frame #3: 0x0000ffffb6b3b58c liblldb.so.21.0git`createTable(unsigned int) + 32
    frame #4: 0x0000ffffb6b3bb08 liblldb.so.21.0git`llvm::StringMapImpl::RehashTable(unsigned int) + 108
    frame #5: 0x0000ffffb66993c0 liblldb.so.21.0git`std::pair<llvm::StringMapIterator<char const*>, bool> llvm::StringMap<char const*, llvm::BumpPtrAllocatorImpl<llvm::MallocAllocator, 4096ul, 4096ul, 1ul>>::try
_emplace_with_hash<char const*>(llvm::StringRef, unsigned int, char const*&&) + 264
    frame #6: 0x0000ffffb6698428 liblldb.so.21.0git`Pool::GetConstCStringWithStringRef(llvm::StringRef) + 288
    frame #7: 0x0000ffffb669889c liblldb.so.21.0git`lldb_private::ConstString::SetString(llvm::StringRef) + 160
    frame #8: 0x0000ffffb66a5c78 liblldb.so.21.0git`lldb_private::FileSpec::SetFile(llvm::StringRef, llvm::sys::path::Style) + 1060
    frame #9: 0x0000ffffb669e3b0 liblldb.so.21.0git`lldb_private::Diagnostics::CreateUniqueDirectory() + 176
    frame #10: 0x0000ffffb669e18c liblldb.so.21.0git`lldb_private::Diagnostics::Dump(llvm::raw_ostream&) + 36
    frame #11: 0x0000ffffb6b840a8 liblldb.so.21.0git`llvm::sys::RunSignalHandlers() + 56
    frame #12: 0x0000ffffb6b867c0 liblldb.so.21.0git`SignalHandler(int, siginfo_t*, void*) + 396
    frame #13: 0x0000ffffbc40d598 [vdso]`__kernel_rt_sigreturn
    frame #14: 0x0000ffffb077c030 libc.so.6`_int_malloc(av=0x0000ffffb088bb10, bytes=136) at malloc.c:3771:1
    frame #15: 0x0000ffffb077d6cc libc.so.6`__GI___libc_malloc(bytes=136) at malloc.c:3329:12
    frame #16: 0x0000ffffb09743ac libstdc++.so.6`operator new(unsigned long) + 28
    frame #17: 0x0000ffffb61f5e68 liblldb.so.21.0git`llvm::SmallVectorImpl<std::vector<lldb_private::FormatEntity::Entry, std::allocator<lldb_private::FormatEntity::Entry>>>::operator=(llvm::SmallVectorImpl<std:
:vector<lldb_private::FormatEntity::Entry, std::allocator<lldb_private::FormatEntity::Entry>>> const&) + 628
    frame #18: 0x0000ffffb61f5bc4 liblldb.so.21.0git`lldb_private::FormatEntity::Entry::Entry(lldb_private::FormatEntity::Entry const&) + 268
    frame #19: 0x0000ffffb64f41c8 liblldb.so.21.0git`lldb_private::OptionValue::GetFormatEntityValue() const + 68
    frame #20: 0x0000ffffb63ff9d8 liblldb.so.21.0git`std::optional<lldb_private::FormatEntity::Entry> lldb_private::OptionValue::GetValueAs<lldb_private::FormatEntity::Entry, true>() const + 36
    frame #21: 0x0000ffffb63f165c liblldb.so.21.0git`lldb_private::FormatEntity::Entry lldb_private::Properties::GetPropertyAtIndexAs<lldb_private::FormatEntity::Entry>(unsigned int, lldb_private::FormatEntity::
Entry, lldb_private::ExecutionContext const*) const + 76
    frame #22: 0x0000ffffb67dd3f0 liblldb.so.21.0git`lldb_private::CPlusPlusLanguage::GetFunctionNameFormat() const + 88
    frame #23: 0x0000ffffb6415c5c liblldb.so.21.0git`FormatFunctionNameForLanguage(lldb_private::Stream&, lldb_private::ExecutionContext const*, lldb_private::SymbolContext const*) + 116
    frame #24: 0x0000ffffb64125c8 liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 1412
    frame #25: 0x0000ffffb64129bc liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 2424
    frame #26: 0x0000ffffb6415c94 liblldb.so.21.0git`FormatFunctionNameForLanguage(lldb_private::Stream&, lldb_private::ExecutionContext const*, lldb_private::SymbolContext const*) + 172
    frame #27: 0x0000ffffb64125c8 liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 1412
    frame #28: 0x0000ffffb64129bc liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 2424
    frame #29: 0x0000ffffb6415c94 liblldb.so.21.0git`FormatFunctionNameForLanguage(lldb_private::Stream&, lldb_private::ExecutionContext const*, lldb_private::SymbolContext const*) + 172
    frame #30: 0x0000ffffb64125c8 liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 1412
    frame #31: 0x0000ffffb64129bc liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 2424
    frame #32: 0x0000ffffb6415c94 liblldb.so.21.0git`FormatFunctionNameForLanguage(lldb_private::Stream&, lldb_private::ExecutionContext const*, lldb_private::SymbolContext const*) + 172
    frame #33: 0x0000ffffb64125c8 liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 1412
    frame #34: 0x0000ffffb64129bc liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 2424
    frame #35: 0x0000ffffb6415c94 liblldb.so.21.0git`FormatFunctionNameForLanguage(lldb_private::Stream&, lldb_private::ExecutionContext const*, lldb_private::SymbolContext const*) + 172
    frame #36: 0x0000ffffb64125c8 liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 1412
    frame #37: 0x0000ffffb64129bc liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 2424
    frame #38: 0x0000ffffb6415c94 liblldb.so.21.0git`FormatFunctionNameForLanguage(lldb_private::Stream&, lldb_private::ExecutionContext const*, lldb_private::SymbolContext const*) + 172
    frame #39: 0x0000ffffb64125c8 liblldb.so.21.0git`lldb_private::FormatEntity::Format(lldb_private::FormatEntity::Entry const&, lldb_private::Stream&, lldb_private::SymbolContext const*, lldb_private::Executio
nContext const*, lldb_private::Address const*, lldb_private::ValueObject*, bool, bool) + 1412

(lldb) thread list
Process 2640943 stopped
* thread #1: tid = 2640943, 0x0000ffffb0769f64 libc.so.6`futex_wait(private=0, expected=2, futex_word=0x0000ffffb088bb10) at futex-internal.h:146:13, name = 'lldb', stop reason = signal SIGSTOP
  thread #2: tid = 2640945, 0x0000ffffb07cbf4c libc.so.6`__ppoll(fds=0x0000ffffa8000b70, nfds=1, timeout=<unavailable>, sigmask=0x0000000000000000) at ppoll.c:42:10, name = 'lldb', stop reason = signal SIGSTOP
  thread #3: tid = 2640946, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31ae280) at futex
-internal.c:57:12, name = 'dbg.evt-handler', stop reason = signal SIGSTOP
  thread #4: tid = 2640947, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at futex
-internal.c:57:12, name = 'llvm-worker-0', stop reason = signal SIGSTOP
  thread #5: tid = 2640948, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at futex
-internal.c:57:12, name = 'llvm-worker-1', stop reason = signal SIGSTOP
  thread #6: tid = 2640949, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at futex
-internal.c:57:12, name = 'llvm-worker-2', stop reason = signal SIGSTOP
  thread #7: tid = 2640950, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at futex
-internal.c:57:12, name = 'llvm-worker-3', stop reason = signal SIGSTOP
  thread #8: tid = 2640951, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at futex
-internal.c:57:12, name = 'llvm-worker-4', stop reason = signal SIGSTOP
  thread #9: tid = 2640952, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at futex
-internal.c:57:12, name = 'llvm-worker-5', stop reason = signal SIGSTOP
  thread #10: tid = 2640953, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at fute
x-internal.c:57:12, name = 'llvm-worker-6', stop reason = signal SIGSTOP
  thread #11: tid = 2640954, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a6518) at fute
x-internal.c:57:12, name = 'llvm-worker-7', stop reason = signal SIGSTOP
  thread #12: tid = 2640956, 0x0000ffffb07a6800 libc.so.6`__GI___wait4(pid=<unavailable>, stat_loc=0x0000ffff8afde630, options=0, usage=0x0000000000000000) at wait4.c:30:10, name = '4(pid=2640955)>', stop reason
 = signal SIGSTOP
  thread #13: tid = 2640957, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac1e765e4) at fute
x-internal.c:57:12, name = 'b-remote.async>', stop reason = signal SIGSTOP
  thread #14: tid = 2640963, 0x0000ffffb0769de8 libc.so.6`__futex_abstimed_wait_common64(private=<unavailable>, cancel=true, abstime=0x0000000000000000, op=393, expected=0, futex_word=0x0000aaaac31a2940) at fute
x-internal.c:57:12, name = 'intern-state', stop reason = signal SIGSTOP
  thread #15: tid = 2640964, 0x0000ffffb07cea98 libc.so.6`__GI___select(nfds=10, readfds=0x0000ffff897ade00, writefds=0x0000000000000000, exceptfds=0x0000000000000000, timeout=0x0000ffff897adcf0) at select.c:69:
11, name = '.process.stdio>', stop reason = signal SIGSTOP

Looks like we got a signal after recursing a lot:

    frame #10: 0x0000ffffb669e18c liblldb.so.21.0git`lldb_private::Diagnostics::Dump(llvm::raw_ostream&) + 36
    frame #11: 0x0000ffffb6b840a8 liblldb.so.21.0git`llvm::sys::RunSignalHandlers() + 56
    frame #12: 0x0000ffffb6b867c0 liblldb.so.21.0git`SignalHandler(int, siginfo_t*, void*) + 396
    frame #13: 0x0000ffffbc40d598 [vdso]`__kernel_rt_sigreturn
    frame #14: 0x0000ffffb077c030 libc.so.6`_int_malloc(av=0x0000ffffb088bb10, bytes=136) at malloc.c:3771:1
    frame #15: 0x0000ffffb077d6cc libc.so.6`__GI___libc_malloc(bytes=136) at malloc.c:3329:12
    frame #16: 0x0000ffffb09743ac libstdc++.so.6`operator new(unsigned long) + 28
    frame #17: 0x0000ffffb61f5e68 liblldb.so.21.0git`llvm::SmallVectorImpl<std::vector<lldb_private::FormatEntity::Entry, std::allocator<lldb_private::FormatEntity::Entry>>>::operator=(llvm::SmallVectorImpl<std:
:vector<lldb_private::FormatEntity::Entry, std::allocator<lldb_private::FormatEntity::Entry>>> const&) + 628
    frame #18: 0x0000ffffb61f5bc4 liblldb.so.21.0git`lldb_private::FormatEntity::Entry::Entry(lldb_private::FormatEntity::Entry const&) + 268

Then tried to crash and dump diagnostics but that deadlocks, probably because the stack pointer is somehow in the heap? 😆

(lldb) register read sp
      sp = 0x0000aaaac1c88760
(lldb) memory region 0x0000aaaac1c88760
[0x0000aaaac1bcb000-0x0000aaaac3318000) rw- [heap]
(lldb) memory region --all
<...>
[0x0000aaaac1bcb000-0x0000aaaac3318000) rw- [heap]
<...>
[0x0000ffffc43f9000-0x0000ffffc4bf9000) rw- [stack]
[0x0000ffffc4bf9000-0xffffffffffffffff) ---

So yeah this can stay disabled until/if you fix the issue causing the recursion.

That it crashes "nicely" on Mac is mostly luck.

[DavidSpickett]

This has been dealt with. Thanks for the report @pfusik !