New issue
Advanced search Search tips

Issue 752255 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Aug 2017
Components:
EstimatedDays: ----
NextAction: ----
OS: Fuchsia
Pri: 3
Type: Bug



Sign in to add a comment

Streamline backtrace output

Project Member Reported by w...@chromium.org, Aug 3 2017

Issue description

When a CHECK fires StackTrace::Print emits sufficient information for the test-runner script to symbolize the stack.  We then print both the un-symbolized, and the symbolized, stacks.

We should print a single stack, interleaving the symbolized and unsymbolized output, for better readability. The unsymbolized lines should also be stripped of the Fuchsia pre-amble.


 
Can you paste an example? I think we shouldn't hide unsymbolized in the test runner (if that's what you're proposing?) if only so that our output looks the same as Magenta team's if we're posting crashes upstream.

Comment 2 by w...@chromium.org, Aug 3 2017

An example would be:

[00005.149] 03210.03237>
[3:742779696:0803/191641.478302:5148505:ERROR:broker_posix.cc(40)] Recvmsg
error: I/O error (5)
[00005.209] 03210.03237>
[3:742779696:0803/191641.527152:5197349:FATAL:mojo_test_base.cc(138)] Check
failed: WaitForSignals(mp, MOJO_HANDLE_SIGNAL_READABLE) == MOJO_RESULT_OK
(9 vs. 0)
[00005.209] 03210.03237> #00 0x7dc9266de5e0
app:/system/mojo_system_unittestswZ++0x8c25e0
[00005.209] 03210.03237> #01 0x7dc9263f054c
app:/system/mojo_system_unittestswZ++0x5d454c
[00005.209] 03210.03237> #02 0x7dc9263e8c0a
app:/system/mojo_system_unittestswZ++0x5ccc0a
[00005.209] 03210.03237> #03 0x7dc9267e825e
app:/system/mojo_system_unittestswZ++0x9cc25e
[00005.209] 03210.03237> #04 0x7dc9267e8ec0
app:/system/mojo_system_unittestswZ++0x9ccec0
[00005.209] 03210.03237> #05 0x7dc926033951
app:/system/mojo_system_unittestswZ++0x217951
[00005.209] 03210.03237> #06 0x7dc926033d5f
app:/system/mojo_system_unittestswZ++0x217d5f
[00005.209] 03210.03237> #07 0x7dc926033c8f
app:/system/mojo_system_unittestswZ++0x217c8f
[00005.209] 03210.03237> #08 0x7dc926033c25
app:/system/mojo_system_unittestswZ++0x217c25
[00005.209] 03210.03237> #09 0x7dc926033b64
app:/system/mojo_system_unittestswZ++0x217b64
[00005.209] 03210.03237> #10 0x7dc9260cb53c
app:/system/mojo_system_unittestswZ++0x2af53c
[00005.209] 03210.03237> #11 0x7dc9267f0b3b
app:/system/mojo_system_unittestswZ++0x9d4b3b
[00005.209] 03210.03237> #12 0x7dc9267f0a3b
app:/system/mojo_system_unittestswZ++0x9d4a3b
[00005.209] 03210.03237> #13 0x7dc9267f08ea
app:/system/mojo_system_unittestswZ++0x9d48ea
[00005.209] 03210.03237> #14 0x7dc92602e3b9
app:/system/mojo_system_unittestswZ++0x2123b9
[00005.209] 03210.03237> #15 0x7dc9267fc005
app:/system/mojo_system_unittestswZ++0x9e0005
[00005.209] 03210.03237> #16 0x7dc9266eccaa
app:/system/mojo_system_unittestswZ++0x8d0caa
[00005.209] 03210.03237> #17 0x7dc92617925d
app:/system/mojo_system_unittestswZ++0x35d25d
[00005.209] 03210.03237> #18 0x7dc9261791a4
app:/system/mojo_system_unittestswZ++0x35d1a4
[00005.209] 03210.03237> #19 0x7dc926179155
app:/system/mojo_system_unittestswZ++0x35d155
[00005.209] 03210.03237> #20 0x7dc92617906c
app:/system/mojo_system_unittestswZ++0x35d06c
[00005.209] 03210.03237> #21 0x7dc92670010d
app:/system/mojo_system_unittestswZ++0x8e410d
[00005.209] 03210.03237> #22 0x7dc9266f97f7
app:/system/mojo_system_unittestswZ++0x8dd7f7
[00005.209] 03210.03237> #23 0x7dc9266f9665
app:/system/mojo_system_unittestswZ++0x8dd665
[00005.209] 03210.03237> #24 0x7dc926178d27
app:/system/mojo_system_unittestswZ++0x35cd27
[00005.209] 03210.03237> #25 0x57d099c213ce libc.so+0x1c3ce
[00005.209] 03210.03237> #26 end
----- start symbolized stack
#00: StackTrace at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/debug/stack_trace_fuchsia.cc:170
#01: StackTrace at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/debug/stack_trace.cc:199
#02: ~LogMessage at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/logging.cc:?
#03: mojo::edk::test::MojoTestBase::ReadMessageWithHandles(unsigned int,
unsigned int*, unsigned int) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/test/mojo_test_base.cc:?
#04: mojo::edk::test::MojoTestBase::ReadMessage(unsigned int) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/test/mojo_test_base.cc:175
#05: mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture::Main(unsigned int) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/system/message_unittest.cc:?
#06: void base::internal::FunctorTraits<void (mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture::*)(unsigned int),
void>::Invoke<mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture*, unsigned int>(void
(mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture::*)(unsigned int),
mojo::edk::(anonymous namespace)::ReceiveMessageNoHandles_MainFixture*&&,
unsigned int&&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:196
#07: void base::internal::InvokeHelper<false, void>::MakeItSo<void
(mojo::edk::(anonymous namespace)::ReceiveMessageNoHandles_MainFixture::*
const&)(unsigned int), mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture*, unsigned int>(void
(mojo::edk::(anonymous namespace)::ReceiveMessageNoHandles_MainFixture::*
const&)(unsigned int), mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture*&&, unsigned int&&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:265
#08: void base::internal::Invoker<base::internal::BindState<void
(mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture::*)(unsigned int),
base::internal::UnretainedWrapper<mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture> >, void (unsigned
int)>::RunImpl<void (mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture::* const&)(unsigned int),
std::__1::tuple<base::internal::UnretainedWrapper<mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture> > const&, 0ul>(void
(mojo::edk::(anonymous namespace)::ReceiveMessageNoHandles_MainFixture::*
const&)(unsigned int),
std::__1::tuple<base::internal::UnretainedWrapper<mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture> > const&,
base::IndexSequence<0ul>, unsigned int&&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:340
#09: base::internal::Invoker<base::internal::BindState<void
(mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture::*)(unsigned int),
base::internal::UnretainedWrapper<mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandles_MainFixture> >, void (unsigned
int)>::Run(base::internal::BindStateBase*, unsigned int&&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:319
#10: base::Callback<void (unsigned int), (base::internal::CopyMode)1,
(base::internal::RepeatMode)1>::Run(unsigned int) const & at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/callback.h:80
#11: operator() at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/test/multiprocess_test_helper.cc:252
#12: int mojo::edk::test::(anonymous
namespace)::RunClientFunction<mojo::edk::test::MultiprocessTestHelper::RunClientTestMain(base::Callback<void
(unsigned int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>
const&)::$_1>(mojo::edk::test::MultiprocessTestHelper::RunClientTestMain(base::Callback<void
(unsigned int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>
const&)::$_1, bool) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/test/multiprocess_test_helper.cc:62
#13:
mojo::edk::test::MultiprocessTestHelper::RunClientTestMain(base::Callback<void
(unsigned int), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>
const&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/test/multiprocess_test_helper.cc:249
#14: mojo::edk::(anonymous
namespace)::ReceiveMessageNoHandlesTestChildMain() at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/system/message_unittest.cc:236
#15:
multi_process_function_list::InvokeChildProcessTest(std::__1::basic_string<char,
std::__1::char_traits<char>, std::__1::allocator<char> > const&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../testing/multiprocess_func_list.cc:51
#16: base::TestSuite::Run() at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/test/test_suite.cc:265
#17: int base::internal::FunctorTraits<int (base::TestSuite::*)(),
void>::Invoke<base::TestSuite*>(int (base::TestSuite::*)(),
base::TestSuite*&&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:196
#18: int base::internal::InvokeHelper<false, int>::MakeItSo<int
(base::TestSuite::* const&)(), base::TestSuite*>(int (base::TestSuite::*
const&)(), base::TestSuite*&&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:265
#19: int base::internal::Invoker<base::internal::BindState<int
(base::TestSuite::*)(), base::internal::UnretainedWrapper<base::TestSuite>

std::__1::tuple<base::internal::UnretainedWrapper<base::TestSuite> >
const&, 0ul>(int (base::TestSuite::* const&)(),
std::__1::tuple<base::internal::UnretainedWrapper<base::TestSuite> >
const&, base::IndexSequence<0ul>) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:340
#20: base::internal::Invoker<base::internal::BindState<int
(base::TestSuite::*)(), base::internal::UnretainedWrapper<base::TestSuite>

/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/bind_internal.h:319
#21: base::Callback<int (), (base::internal::CopyMode)1,
(base::internal::RepeatMode)1>::Run() const & at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/callback.h:80
#22: base::(anonymous
namespace)::LaunchUnitTestsInternal(base::Callback<int (),
(base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&,
unsigned long, int, bool, base::Callback<void (),
(base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/test/launcher/unit_test_launcher.cc:216
#23: base::LaunchUnitTests(int, char**, base::Callback<int (),
(base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/test/launcher/unit_test_launcher.cc:462
#24: main at
/usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../mojo/edk/test/run_all_unittests.cc:46
#25: ?? ??:0
----- end symbolized stack
[00005.209] 03210.03237>
[00005.234] 03127.03154> ../../mojo/edk/test/mojo_test_base.h:71: Failure
[00005.235] 03127.03154>       Expected: 0
[00005.235] 03127.03154> To be equal to:
RunTestClientAndGetExitCode(client_name, handler)
[00005.235] 03127.03154>       Which is: 1
[00005.249] 03127.03154> [  FAILED  ]
MessageTest.SerializeDynamicallySizedMessage (508 ms)
[00005.251] 03127.03154> [----------] 1 test from MessageTest (521 ms total)
[00005.251] 03127.03154>
[00005.251] 03127.03154> [----------] Global test environment tear-down
[00005.252] 03127.03154> [==========] 1 test from 1 test case ran. (530 ms
total)
[00005.253] 03127.03154> [  PASSED  ] 0 tests.
[00005.253] 03127.03154> [  FAILED  ] 1 test, listed below:
[00005.256] 03127.03154> [  FAILED  ]
MessageTest.SerializeDynamicallySizedMessage
[00005.256] 03127.03154>
[00005.256] 03127.03154>  1 FAILED TEST
[00005.425] 02943.02978> [1/1] MessageTest.SerializeDynamicallySizedMessage
(508 ms)
[00005.428] 02943.02978> 1 test failed:
[00005.431] 02943.02978>     MessageTest.SerializeDynamicallySizedMessage
(../../mojo/edk/system/message_unittest.cc:250)
[00005.450] 02943.02978> Tests took 1 seconds.

There are two main issues with this output for debugging/diagnostic
purposes:
1. The template expansions result in stupidly long lines; I'll talk to
dcheng@ about his idea of having the symbolizer suppress defaulted template
params.
2. Listing both unsymbolized and then symbolized stacks means you have to
scroll-back a long way to see what actually triggered the crash, which is
pretty painful.  We could potentially add a command-line option to override
the default StackTrace depth to capture, for the developer debugging case,
as a mitigation to that, though.
Yeah, it's especially bad in mojo & bind code what with all the template gunk, and after 78 col wrapping (or whatever crbug does). :(

I sort of like the dump from crashlogger in e.g. https://bugs.chromium.org/p/chromium/issues/detail?id=751350 ; it'd be a bit weird to just drop the bt# lines from that... but I guess OK.

It's also very slightly useful to see "libc" followed by "base_unittests" in the initial trace, as compared with the symbolized jumble.

Anyway... yah, I'll be quiet. Feel free to improve. :)
Project Member

Comment 4 by bugdroid1@chromium.org, Aug 9 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/6180470e5764765eaf830bc989d4449e9959f5bd

commit 6180470e5764765eaf830bc989d4449e9959f5bd
Author: Wez <wez@chromium.org>
Date: Wed Aug 09 21:11:40 2017

Fix StackTrace symbol entry string handling under Fuchsia.

Bug:  752255 
Change-Id: I840cd990acb4475847d68ca59c34a307ce0307c5
Reviewed-on: https://chromium-review.googlesource.com/604639
Reviewed-by: Kevin Marshall <kmarshall@chromium.org>
Commit-Queue: Wez <wez@chromium.org>
Cr-Commit-Position: refs/heads/master@{#493138}
[modify] https://crrev.com/6180470e5764765eaf830bc989d4449e9959f5bd/base/debug/stack_trace_fuchsia.cc

Comment 5 by w...@chromium.org, Aug 9 2017

Status: Started (was: Assigned)
Project Member

Comment 6 by bugdroid1@chromium.org, Aug 10 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8d8c30870f07f9d2c047259888c2933fc74140b0

commit 8d8c30870f07f9d2c047259888c2933fc74140b0
Author: Wez <wez@chromium.org>
Date: Thu Aug 10 01:46:50 2017

Only output a single unified stack for backtraces.

Previously in-app backtraces would emit lines of the form:

<frame#> <absolute-PC> <binary>+<relative-PC>
#00 0x147788a0eb50 app:/system/ipc_tests+0x901b50

and these would be followed by test_runner-generated lines of the form:

<frame#>: <function> at <filename>:<line-number>
#00: StackTrace at /usr/local/google/home/wez/Projects/git-cr-fuchsia/src/out/gnDebug/../../base/debug/stack_trace_fuchsia.cc:170

with ?? substituted for elements which cannot be symbolized.

This CL has raw backtraces consumed by the test_runner script, with same
symbolized output as shown above, and a fall-back to the form:

<frame#> <binary>+<relative-PC>

for the case of unresolvable symbols.

Bug:  752255 
Change-Id: I53e2c415a42ea1d49471a2e9b177cca47b1639a3
Reviewed-on: https://chromium-review.googlesource.com/604640
Reviewed-by: Kevin Marshall <kmarshall@chromium.org>
Reviewed-by: Scott Graham <scottmg@chromium.org>
Commit-Queue: Wez <wez@chromium.org>
Cr-Commit-Position: refs/heads/master@{#493217}
[modify] https://crrev.com/8d8c30870f07f9d2c047259888c2933fc74140b0/build/fuchsia/test_runner.py

Comment 7 by w...@chromium.org, Aug 10 2017

Status: Fixed (was: Started)

Sign in to add a comment