Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-47494

Structured logging of unit test result isn't human readable

XMLWordPrintableJSON

    • Type: Icon: Improvement Improvement
    • Resolution: Unresolved
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • Server Programmability

      After SERVER-46801, the result of unit test became a json object. The stack trace isn't readable even with mrlog. This made debugging unit tests much harder.

      $ ./build/ninja/mongo/db/repl/db_repl_coordinator_test --suite ReplCoordReconfigTest --filter StepdownShouldInterruptConfigWrite | mrlog
...
2020-04-13T05:20:00.799Z I  TEST     [main] Result{"suite":{"name":"ReplCoordReconfigTest","tests":1,"fails":1,"asserts":0,"time":{"durationMillis":150},"failures":[{"test":"StepdownShouldInterruptConfigWrite","type":"TestAssertionFailureException","error":"Expected ::mongo::Status::OK() == (status) (OK  == CurrentConfigNotCommittedYet Last committed optime from previous config ({ ts: Timestamp(1, 1), t: 1 }) is not committed in the current config.) @src/mongo/db/repl/replication_coordinator_impl_reconfig_test.cpp:1327","extra":"BACKTRACE: {\"backtrace\":[{\"a\":\"7F01679085F7\",\"b\":\"7F0167736000\",\"o\":\"1D25F7\",\"s\":\"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.587\",\"s+\":\"1E7\"},{\"a\":\"7F016790991A\",\"b\":\"7F0167736000\",\"o\":\"1D391A\",\"s\":\"_ZN5mongo15printStackTraceERNS_14StackTraceSinkE\",\"s+\":\"2A\"},{\"a\":\"7F0167909963\",\"b\":\"7F0167736000\",\"o\":\"1D3963\",\"s\":\"_ZN5mongo15printStackTraceERSo\",\"s+\":\"33\"},{\"a\":\"7F016B57E53D\",\"b\":\"7F016B539000\",\"o\":\"4553D\",\"s\":\"_ZN5mongo8unittest29TestAssertionFailureExceptionC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"9D\"},{\"a\":\"7F016B57E65F\",\"b\":\"7F016B539000\",\"o\":\"4565F\",\"s\":\"_ZN5mongo8unittest20TestAssertionFailureC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"F\"},{\"a\":\"56200B33424C\",\"b\":\"56200B218000\",\"o\":\"11C24C\",\"s\":\"_ZSt11make_uniqueIN5mongo8unittest20TestAssertionFailureEJRPKcRjNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENSt9_MakeUniqIT_E15__single_objectEDpOT0_\",\"s+\":\"7C\"},{\"a\":\"7F016B58BD68\",\"b\":\"7F016B539000\",\"o\":\"52D68\",\"s\":\"_ZN5mongo8unittest19ComparisonAssertionILNS0_12ComparisonOpE0EEC1INS_6StatusES5_EEPKcjNS_10StringDataES8_RKT_RKT0_\",\"s+\":\"138\"},{\"a\":\"56200B282096\",\"b\":\"56200B218000\",\"o\":\"6A096\",\"s\":\"_ZN5mongo4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWrite7_doTestEv.cold.1647\",\"s+\":\"29A\"},{\"a\":\"7F016B57D640\",\"b\":\"7F016B539000\",\"o\":\"44640\",\"s\":\"_ZN5mongo8unittest4Test3runEv\",\"s+\":\"20\"},{\"a\":\"56200B371CDD\",\"b\":\"56200B218000\",\"o\":\"159CDD\",\"s\":\"_ZNSt17_Function_handlerIFvvEZN5mongo8unittest4Test17RegistrationAgentINS1_4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWriteEEC4ENS1_10StringDataES9_S9_EUlvE_E9_M_invokeERKSt9_Any_data\",\"s+\":\"7D\"},{\"a\":\"7F016B57E9A3\",\"b\":\"7F016B539000\",\"o\":\"459A3\",\"s\":\"_ZN5mongo8unittest5Suite3runERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES9_i\",\"s+\":\"313\"},{\"a\":\"7F016B57FD92\",\"b\":\"7F016B539000\",\"o\":\"46D92\",\"s\":\"_ZN5mongo8unittest5Suite3runERKSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS8_EERKS8_SE_i\",\"s+\":\"3A2\"},{\"a\":\"7F016B66F59F\",\"b\":\"7F016B66B000\",\"o\":\"459F\",\"s\":\"main\",\"s+\":\"92F\"},{\"a\":\"7F0164E3B830\",\"b\":\"7F0164E1B000\",\"o\":\"20830\",\"s\":\"__libc_start_main\",\"s+\":\"F0\"},{\"a\":\"56200B2FA269\",\"b\":\"56200B218000\",\"o\":\"E2269\",\"s\":\"_start\",\"s+\":\"29\"}],\"processInfo\":{\"mongodbVersion\":\"unknown\",\"gitVersion\":\"none\",\"compiledModules\":[\"unknown\"],\"uname\":{\"sysname\":\"Linux\",\"release\":\"4.4.0-140-generic\",\"version\":\"#166-Ubuntu SMP Wed Nov 14 20:09:47 UTC 2018\",\"machine\":\"x86_64\"},\"somap\":[{\"b\":\"56200B218000\",\"elfType\":3,\"buildId\":\"6E76A7C1CF6FF905F272F9CC11EB4295D1CF3606\"},{\"b\":\"7F016B66B000\",\"path\":\"build/ninja/mongo/unittest/libunittest_main.so\",\"elfType\":3,\"buildId\":\"014B17A9191924CC013A651600DE8A9F6A53627D\"},{\"b\":\"7F016B539000\",\"path\":\"build/ninja/mongo/unittest/libunittest.so\",\"elfType\":3,\"buildId\":\"B818FC7F70ADB7689C57D6509590256035CE2439\"},{\"b\":\"7F0167736000\",\"path\":\"build/ninja/mongo/libbase.so\",\"elfType\":3,\"buildId\":\"A6D86EDBF5C498598467A96A3F5A845573069114\"},{\"b\":\"7F0164E1B000\",\"path\":\"/lib/x86_64-linux-gnu/libc.so.6\",\"elfType\":3,\"buildId\":\"1CA54A6E0D76188105B12E49FE6B8019BF08803A\"}]}}\n  Frame: {\"a\":\"7F01679085F7\",\"b\":\"7F0167736000\",\"o\":\"1D25F7\",\"s\":\"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.587\",\"s+\":\"1E7\"}\n  Frame: {\"a\":\"7F016790991A\",\"b\":\"7F0167736000\",\"o\":\"1D391A\",\"s\":\"_ZN5mongo15printStackTraceERNS_14StackTraceSinkE\",\"s+\":\"2A\"}\n  Frame: {\"a\":\"7F0167909963\",\"b\":\"7F0167736000\",\"o\":\"1D3963\",\"s\":\"_ZN5mongo15printStackTraceERSo\",\"s+\":\"33\"}\n  Frame: {\"a\":\"7F016B57E53D\",\"b\":\"7F016B539000\",\"o\":\"4553D\",\"s\":\"_ZN5mongo8unittest29TestAssertionFailureExceptionC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"9D\"}\n  Frame: {\"a\":\"7F016B57E65F\",\"b\":\"7F016B539000\",\"o\":\"4565F\",\"s\":\"_ZN5mongo8unittest20TestAssertionFailureC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"F\"}\n  Frame: {\"a\":\"56200B33424C\",\"b\":\"56200B218000\",\"o\":\"11C24C\",\"s\":\"_ZSt11make_uniqueIN5mongo8unittest20TestAssertionFailureEJRPKcRjNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENSt9_MakeUniqIT_E15__single_objectEDpOT0_\",\"s+\":\"7C\"}\n  Frame: {\"a\":\"7F016B58BD68\",\"b\":\"7F016B539000\",\"o\":\"52D68\",\"s\":\"_ZN5mongo8unittest19ComparisonAssertionILNS0_12ComparisonOpE0EEC1INS_6StatusES5_EEPKcjNS_10StringDataES8_RKT_RKT0_\",\"s+\":\"138\"}\n  Frame: {\"a\":\"56200B282096\",\"b\":\"56200B218000\",\"o\":\"6A096\",\"s\":\"_ZN5mongo4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWrite7_doTestEv.cold.1647\",\"s+\":\"29A\"}\n  Frame: {\"a\":\"7F016B57D640\",\"b\":\"7F016B539000\",\"o\":\"44640\",\"s\":\"_ZN5mongo8unittest4Test3runEv\",\"s+\":\"20\"}\n  Frame: {\"a\":\"56200B371CDD\",\"b\":\"56200B218000\",\"o\":\"159CDD\",\"s\":\"_ZNSt17_Function_handlerIFvvEZN5mongo8unittest4Test17RegistrationAgentINS1_4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWriteEEC4ENS1_10StringDataES9_S9_EUlvE_E9_M_invokeERKSt9_Any_data\",\"s+\":\"7D\"}\n  Frame: {\"a\":\"7F016B57E9A3\",\"b\":\"7F016B539000\",\"o\":\"459A3\",\"s\":\"_ZN5mongo8unittest5Suite3runERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES9_i\",\"s+\":\"313\"}\n  Frame: {\"a\":\"7F016B57FD92\",\"b\":\"7F016B539000\",\"o\":\"46D92\",\"s\":\"_ZN5mongo8unittest5Suite3runERKSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS8_EERKS8_SE_i\",\"s+\":\"3A2\"}\n  Frame: {\"a\":\"7F016B66F59F\",\"b\":\"7F016B66B000\",\"o\":\"459F\",\"s\":\"main\",\"s+\":\"92F\"}\n  Frame: {\"a\":\"7F0164E3B830\",\"b\":\"7F0164E1B000\",\"o\":\"20830\",\"s\":\"__libc_start_main\",\"s+\":\"F0\"}\n  Frame: {\"a\":\"56200B2FA269\",\"b\":\"56200B218000\",\"o\":\"E2269\",\"s\":\"_start\",\"s+\":\"29\"}"}]}}
2020-04-13T05:20:00.799Z I  TEST     [main] Totals{"totals":{"name":"TOTALS","tests":1,"fails":1,"asserts":0,"time":{"durationMillis":150},"failures":[]}}
2020-04-13T05:20:00.799Z I  TEST     [main] FAILURE{"failedTestsCount":1,"failedSuitesCount":1,"failedTests":["ReplCoordReconfigTest/StepdownShouldInterruptConfigWrite"]}

      The stack trace of a single task has the same issue.

      2020-04-13T05:20:00.798Z I  TEST     [main] FAIL{"test":"StepdownShouldInterruptConfigWrite","type":"TestAssertionFailureException","error":"Expected ::mongo::Status::OK() == (status) (OK  == CurrentConfigNotCommittedYet Last committed optime from previous config ({ ts: Timestamp(1, 1), t: 1 }) is not committed in the current config.) @src/mongo/db/repl/replication_coordinator_impl_reconfig_test.cpp:1327","extra":"BACKTRACE: {\"backtrace\":[{\"a\":\"7F01679085F7\",\"b\":\"7F0167736000\",\"o\":\"1D25F7\",\"s\":\"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.587\",\"s+\":\"1E7\"},{\"a\":\"7F016790991A\",\"b\":\"7F0167736000\",\"o\":\"1D391A\",\"s\":\"_ZN5mongo15printStackTraceERNS_14StackTraceSinkE\",\"s+\":\"2A\"},{\"a\":\"7F0167909963\",\"b\":\"7F0167736000\",\"o\":\"1D3963\",\"s\":\"_ZN5mongo15printStackTraceERSo\",\"s+\":\"33\"},{\"a\":\"7F016B57E53D\",\"b\":\"7F016B539000\",\"o\":\"4553D\",\"s\":\"_ZN5mongo8unittest29TestAssertionFailureExceptionC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"9D\"},{\"a\":\"7F016B57E65F\",\"b\":\"7F016B539000\",\"o\":\"4565F\",\"s\":\"_ZN5mongo8unittest20TestAssertionFailureC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"F\"},{\"a\":\"56200B33424C\",\"b\":\"56200B218000\",\"o\":\"11C24C\",\"s\":\"_ZSt11make_uniqueIN5mongo8unittest20TestAssertionFailureEJRPKcRjNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENSt9_MakeUniqIT_E15__single_objectEDpOT0_\",\"s+\":\"7C\"},{\"a\":\"7F016B58BD68\",\"b\":\"7F016B539000\",\"o\":\"52D68\",\"s\":\"_ZN5mongo8unittest19ComparisonAssertionILNS0_12ComparisonOpE0EEC1INS_6StatusES5_EEPKcjNS_10StringDataES8_RKT_RKT0_\",\"s+\":\"138\"},{\"a\":\"56200B282096\",\"b\":\"56200B218000\",\"o\":\"6A096\",\"s\":\"_ZN5mongo4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWrite7_doTestEv.cold.1647\",\"s+\":\"29A\"},{\"a\":\"7F016B57D640\",\"b\":\"7F016B539000\",\"o\":\"44640\",\"s\":\"_ZN5mongo8unittest4Test3runEv\",\"s+\":\"20\"},{\"a\":\"56200B371CDD\",\"b\":\"56200B218000\",\"o\":\"159CDD\",\"s\":\"_ZNSt17_Function_handlerIFvvEZN5mongo8unittest4Test17RegistrationAgentINS1_4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWriteEEC4ENS1_10StringDataES9_S9_EUlvE_E9_M_invokeERKSt9_Any_data\",\"s+\":\"7D\"},{\"a\":\"7F016B57E9A3\",\"b\":\"7F016B539000\",\"o\":\"459A3\",\"s\":\"_ZN5mongo8unittest5Suite3runERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES9_i\",\"s+\":\"313\"},{\"a\":\"7F016B57FD92\",\"b\":\"7F016B539000\",\"o\":\"46D92\",\"s\":\"_ZN5mongo8unittest5Suite3runERKSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS8_EERKS8_SE_i\",\"s+\":\"3A2\"},{\"a\":\"7F016B66F59F\",\"b\":\"7F016B66B000\",\"o\":\"459F\",\"s\":\"main\",\"s+\":\"92F\"},{\"a\":\"7F0164E3B830\",\"b\":\"7F0164E1B000\",\"o\":\"20830\",\"s\":\"__libc_start_main\",\"s+\":\"F0\"},{\"a\":\"56200B2FA269\",\"b\":\"56200B218000\",\"o\":\"E2269\",\"s\":\"_start\",\"s+\":\"29\"}],\"processInfo\":{\"mongodbVersion\":\"unknown\",\"gitVersion\":\"none\",\"compiledModules\":[\"unknown\"],\"uname\":{\"sysname\":\"Linux\",\"release\":\"4.4.0-140-generic\",\"version\":\"#166-Ubuntu SMP Wed Nov 14 20:09:47 UTC 2018\",\"machine\":\"x86_64\"},\"somap\":[{\"b\":\"56200B218000\",\"elfType\":3,\"buildId\":\"6E76A7C1CF6FF905F272F9CC11EB4295D1CF3606\"},{\"b\":\"7F016B66B000\",\"path\":\"build/ninja/mongo/unittest/libunittest_main.so\",\"elfType\":3,\"buildId\":\"014B17A9191924CC013A651600DE8A9F6A53627D\"},{\"b\":\"7F016B539000\",\"path\":\"build/ninja/mongo/unittest/libunittest.so\",\"elfType\":3,\"buildId\":\"B818FC7F70ADB7689C57D6509590256035CE2439\"},{\"b\":\"7F0167736000\",\"path\":\"build/ninja/mongo/libbase.so\",\"elfType\":3,\"buildId\":\"A6D86EDBF5C498598467A96A3F5A845573069114\"},{\"b\":\"7F0164E1B000\",\"path\":\"/lib/x86_64-linux-gnu/libc.so.6\",\"elfType\":3,\"buildId\":\"1CA54A6E0D76188105B12E49FE6B8019BF08803A\"}]}}\n  Frame: {\"a\":\"7F01679085F7\",\"b\":\"7F0167736000\",\"o\":\"1D25F7\",\"s\":\"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.587\",\"s+\":\"1E7\"}\n  Frame: {\"a\":\"7F016790991A\",\"b\":\"7F0167736000\",\"o\":\"1D391A\",\"s\":\"_ZN5mongo15printStackTraceERNS_14StackTraceSinkE\",\"s+\":\"2A\"}\n  Frame: {\"a\":\"7F0167909963\",\"b\":\"7F0167736000\",\"o\":\"1D3963\",\"s\":\"_ZN5mongo15printStackTraceERSo\",\"s+\":\"33\"}\n  Frame: {\"a\":\"7F016B57E53D\",\"b\":\"7F016B539000\",\"o\":\"4553D\",\"s\":\"_ZN5mongo8unittest29TestAssertionFailureExceptionC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"9D\"}\n  Frame: {\"a\":\"7F016B57E65F\",\"b\":\"7F016B539000\",\"o\":\"4565F\",\"s\":\"_ZN5mongo8unittest20TestAssertionFailureC2ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEjS9_\",\"s+\":\"F\"}\n  Frame: {\"a\":\"56200B33424C\",\"b\":\"56200B218000\",\"o\":\"11C24C\",\"s\":\"_ZSt11make_uniqueIN5mongo8unittest20TestAssertionFailureEJRPKcRjNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENSt9_MakeUniqIT_E15__single_objectEDpOT0_\",\"s+\":\"7C\"}\n  Frame: {\"a\":\"7F016B58BD68\",\"b\":\"7F016B539000\",\"o\":\"52D68\",\"s\":\"_ZN5mongo8unittest19ComparisonAssertionILNS0_12ComparisonOpE0EEC1INS_6StatusES5_EEPKcjNS_10StringDataES8_RKT_RKT0_\",\"s+\":\"138\"}\n  Frame: {\"a\":\"56200B282096\",\"b\":\"56200B218000\",\"o\":\"6A096\",\"s\":\"_ZN5mongo4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWrite7_doTestEv.cold.1647\",\"s+\":\"29A\"}\n  Frame: {\"a\":\"7F016B57D640\",\"b\":\"7F016B539000\",\"o\":\"44640\",\"s\":\"_ZN5mongo8unittest4Test3runEv\",\"s+\":\"20\"}\n  Frame: {\"a\":\"56200B371CDD\",\"b\":\"56200B218000\",\"o\":\"159CDD\",\"s\":\"_ZNSt17_Function_handlerIFvvEZN5mongo8unittest4Test17RegistrationAgentINS1_4repl12_GLOBAL__N_181UnitTest_SuiteNameReplCoordReconfigTestTestNameStepdownShouldInterruptConfigWriteEEC4ENS1_10StringDataES9_S9_EUlvE_E9_M_invokeERKSt9_Any_data\",\"s+\":\"7D\"}\n  Frame: {\"a\":\"7F016B57E9A3\",\"b\":\"7F016B539000\",\"o\":\"459A3\",\"s\":\"_ZN5mongo8unittest5Suite3runERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES9_i\",\"s+\":\"313\"}\n  Frame: {\"a\":\"7F016B57FD92\",\"b\":\"7F016B539000\",\"o\":\"46D92\",\"s\":\"_ZN5mongo8unittest5Suite3runERKSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS8_EERKS8_SE_i\",\"s+\":\"3A2\"}\n  Frame: {\"a\":\"7F016B66F59F\",\"b\":\"7F016B66B000\",\"o\":\"459F\",\"s\":\"main\",\"s+\":\"92F\"}\n  Frame: {\"a\":\"7F0164E3B830\",\"b\":\"7F0164E1B000\",\"o\":\"20830\",\"s\":\"__libc_start_main\",\"s+\":\"F0\"}\n  Frame: {\"a\":\"56200B2FA269\",\"b\":\"56200B218000\",\"o\":\"E2269\",\"s\":\"_start\",\"s+\":\"29\"}"}

            Assignee:
            Unassigned Unassigned
            Reporter:
            siyuan.zhou@mongodb.com Siyuan Zhou
            Votes:
            1 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated: