Streamline backtrace output |
|||
Issue descriptionWhen 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.
,
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.
,
Aug 3 2017
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. :)
,
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
,
Aug 9 2017
,
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
,
Aug 10 2017
|
|||
►
Sign in to add a comment |
|||
Comment 1 by scottmg@chromium.org
, Aug 3 2017