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

Backtraces printed as strings not objects after switch to structured logging

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Critical - P2 Critical - P2
    • 4.3.4
    • Affects Version/s: None
    • Component/s: None
    • None
    • Fully Compatible
    • ALL
    • Dev Tools 2020-02-24

      I ran into this because I needed to symbolize a backtrace, and noticed that I had to unescape the JSON before I could use mongosymb.py.

      The backtrace looks like this in the log output: 

      [js_test:test_stacked_migration_cleanup] 2020-02-19T15:55:27.230-0500 d15520| {"t":{"$date":"2020-02-19T15:55:27.229-0500"},"s":"F", "c":"-",       "id":0,"ctx":"range-deleter","msg":"{}","attr":{"message":"Got signal: 11 (Segmentation fault).\nBACKTRACE: {\"backtrace\":[{\"a\":\"7F3DF29C6C45\",\"b\":\"7F3DF2824000\",\"o\":\"1A2C45\",\"s\":\"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.575\",\"s+\":\"1E5\"},{\"a\":\"7F3DF29C835A\",\"b\":\"7F3DF2824000\",\"o\":\"1A435A\",\"s\":\"_ZN5mongo15printStackTraceERNS_14StackTraceSinkE\",\"s+\":\"2A\"},{\"a\":\"7F3DF29C83A3\",\"b\":\"7F3DF2824000\",\"o\":\"1A43A3\",\"s\":\"_ZN5mongo15printStackTraceERSo\",\"s+\":\"33\"},{\"a\":\"7F3DF29C57FC\",\"b\":\"7F3DF2824000\",\"o\":\"1A17FC\",\"s\":\"_ZN5mongo12_GLOBAL__N_123printSignalAndBacktraceEi\",\"s+\":\"AC\"},{\"a\":\"7F3DF29C59F7\",\"b\":\"7F3DF2824000\",\"o\":\"1A19F7\",\"s\":\"_ZN5mongo12_GLOBAL__N_124abruptQuitWithAddrSignalEiP9siginfo_tPv\",\"s+\":\"107\"},{\"a\":\"7F3DF034D890\",\"b\":\"7F3DF033B000\",\"o\":\"12890\",\"s\":\"funlockfile\",\"s+\":\"50\"},{\"a\":\"7F3DF4854EDA\",\"b\":\"7F3DF484E000\",\"o\":\"6EDA\",\"s\":\"_ZN5mongo12_GLOBAL__N_121loopbackBuildResponseEPNS_16OperationContextEPNS_9LastErrorERNS_7MessageE\",\"s+\":\"4A\"},{\"a\":\"7F3DF48559C8\",\"b\":\"7F3DF484E000\",\"o\":\"79C8\",\"s\":\"_ZN5mongo14DBDirectClient4callERNS_7MessageES2_bPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE\",\"s+\":\"38\"},{\"a\":\"7F3DF3860AB8\",\"b\":\"7F3DF3846000\",\"o\":\"1AAB8\",\"s\":\"_ZN5mongo12DBClientBase20runCommandWithTargetENS_12OpMsgRequestE\",\"s+\":\"208\"},{\"a\":\"7F3DF644B4CF\",\"b\":\"7F3DF6365000\",\"o\":\"E64CF\",\"s\":\"_ZN5mongo12DBClientBase10runCommandENS_12OpMsgRequestE\",\"s+\":\"7F\"},{\"a\":\"7F3DF6450193\",\"b\":\"7F3DF6365000\",\"o\":\"EB193\",\"s\":\"_ZN5mongo19PersistentTaskStoreINS_17RangeDeletionTaskEE6removeEPNS_16OperationContextENS_5QueryERKNS_19WriteConcernOptionsE\",\"s+\":\"2E3\"},{\"a\":\"7F3DF6446F49\",\"b\":\"7F3DF6365000\",\"o\":\"E1F49\",\"s\":\"_ZN5mongo13migrationutil30deleteRangeDeletionTaskLocallyEPNS_16OperationContextERKNS_4UUIDERKNS_19WriteConcernOptionsE\",\"s+\":\"119\"},{\"a\":\"7F3DF6450616\",\"b\":\"7F3DF6365000\",\"o\":\"EB616\",\"s\":\"_ZN5mongo14future_details10statusCallIRZZZNS_14ExecutorFutureIvE12wrapCBHelperIFNS_6StatusES5_EEEDaONS_15unique_functionIT_EEENUlDpOT_E_clIJS5_EEENS_6FutureINS0_17UnwrappedTypeImplIDTclfp_spcl7forwardIDtfp_EEfp_EEEE4typeEEESD_ENUlS5_E_clES5_EUlvE_JNS0_8FakeVoidEEEEDaOS8_DpOT0_\",\"s+\":\"226\"},{\"a\":\"7F3DF64507E8\",\"b\":\"7F3DF6365000\",\"o\":\"EB7E8\",\"s\":\"_ZZN5mongo15unique_functionIFvNS_6StatusEEE8makeImplIZZNS_14ExecutorFutureIvE12wrapCBHelperIFS1_S1_EEEDaONS0_IT_EEENUlDpOT_E_clIJS1_EEENS_6FutureINS_14future_details17UnwrappedTypeImplIDTclfp_spcl7forwardIDtfp_EEfp_EEEE4typeEEESE_EUlS1_E_EEDaOS9_EN12SpecificImpl4callEOS1_\",\"s+\":\"C8\"},{\"a\":\"7F3DF5778644\",\"b\":\"7F3DF5774000\",\"o\":\"4644\",\"s\":\"_ZZN5mongo15unique_functionIFvRKNS_8executor12TaskExecutor12CallbackArgsEEE8makeImplIZNS2_8scheduleENS0_IFvNS_6StatusEEEEEUlS5_E_EEDaOT_EN12SpecificImpl4callES5_\",\"s+\":\"44\"},{\"a\":\"7F3DF57F87B1\",\"b\":\"7F3DF57E3000\",\"o\":\"157B1\",\"s\":\"_ZN5mongo8executor22ThreadPoolTaskExecutor11runCallbackESt10shared_ptrINS1_13CallbackStateEE\",\"s+\":\"121\"},{\"a\":\"7F3DF57F8E22\",\"b\":\"7F3DF57E3000\",\"o\":\"15E22\",\"s\":\"_ZZN5mongo15unique_functionIFvNS_6StatusEEE8makeImplIZNS_8executor22ThreadPoolTaskExecutor23scheduleIntoPool_inlockEPNSt7__cxx114listISt10shared_ptrINS6_13CallbackStateEESaISB_EEERKSt14_List_iteratorISB_ESI_St11unique_lockINS_5LatchEEEUlT_E1_EEDaOSM_EN12SpecificImpl4callEOS1_\",\"s+\":\"A2\"},{\"a\":\"7F3DF444CEF0\",\"b\":\"7F3DF4442000\",\"o\":\"AEF0\",\"s\":\"_ZN5mongo10ThreadPool10_doOneTaskEPSt11unique_lockINS_5LatchEE\",\"s+\":\"140\"},{\"a\":\"7F3DF444F59C\",\"b\":\"7F3DF4442000\",\"o\":\"D59C\",\"s\":\"_ZN5mongo10ThreadPool13_consumeTasksEv\",\"s+\":\"8C\"},{\"a\":\"7F3DF445060D\",\"b\":\"7F3DF4442000\",\"o\":\"E60D\",\"s\":\"_ZN5mongo10ThreadPool17_workerThreadBodyEPS0_RKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE\",\"s+\":\"ED\"},{\"a\":\"7F3DF4450883\",\"b\":\"7F3DF4442000\",\"o\":\"E883\",\"s\":\"_ZNSt6thread11_State_implINS_8_InvokerISt5tupleIJZN5mongo4stdx6threadC4IZNS3_10ThreadPool25_startWorkerThread_inlockEvEUlvE2_JELi0EEET_DpOT0_EUlvE_EEEEE6_M_runEv\",\"s+\":\"53\"},{\"a\":\"7F3DF4453F7F\",\"b\":\"7F3DF4442000\",\"o\":\"11F7F\",\"s\":\"execute_native_thread_routine\",\"s+\":\"F\"},{\"a\":\"7F3DF03426DB\",\"b\":\"7F3DF033B000\",\"o\":\"76DB\",\"s\":\"start_thread\",\"s+\":\"DB\"},{\"a\":\"7F3DF006B88F\",\"b\":\"7F3DEFF4A000\",\"o\":\"12188F\",\"s\":\"clone\",\"s+\":\"3F\"}],\"processInfo\":{\"mongodbVersion\":\"4.3.0-3454-gb740205\",\"gitVersion\":\"b7402058cd8457551faf11bb2256f8d99f627ccd\",\"compiledModules\":[],\"uname\":{\"sysname\":\"Linux\",\"release\":\"4.15.0-74-generic\",\"version\":\"#84-Ubuntu SMP Thu Dec 19 08:06:28 UTC 2019\",\"machine\":\"x86_64\"},\"somap\":[{\"b\":\"7F3DF6365000\",\"path\":\"build/opt/mongo/db/s/libsharding_runtime_d.so\",\"elfType\":3,\"buildId\":\"C4E5F899C8DA3D48D6C3CCBD0CF4D4821380BDF9\"},{\"b\":\"7F3DF57E3000\",\"path\":\"build/opt/mongo/executor/libthread_pool_task_executor.so\",\"elfType\":3,\"buildId\":\"082A0024CFD0BFB5ED09E126FBE5596E11AC7E53\"},{\"b\":\"7F3DF5774000\",\"path\":\"build/opt/mongo/executor/libtask_executor_interface.so\",\"elfType\":3,\"buildId\":\"F84018B1D45D9DF7E6D6F3E428C69CB98B164B28\"},{\"b\":\"7F3DF484E000\",\"path\":\"build/opt/mongo/db/libdbdirectclient.so\",\"elfType\":3,\"buildId\":\"A53EA6EB52A3B1556E61DF10CC9F66D3CD5BF52E\"},{\"b\":\"7F3DF4442000\",\"path\":\"build/opt/mongo/util/concurrency/libthread_pool.so\",\"elfType\":3,\"buildId\":\"698A8CD0D421A67615C480ED12EEBC5F99A0C053\"},{\"b\":\"7F3DF3846000\",\"path\":\"build/opt/mongo/client/libclientdriver_minimal.so\",\"elfType\":3,\"buildId\":\"7CE5C2F32A789126C0387E2ECE42D77F92A3F00B\"},{\"b\":\"7F3DF2824000\",\"path\":\"build/opt/mongo/libbase.so\",\"elfType\":3,\"buildId\":\"47C665C3004E1D9A665C595750A783FA738FEB7C\"},{\"b\":\"7F3DF033B000\",\"path\":\"/lib/x86_64-linux-gnu/libpthread.so.0\",\"elfType\":3,\"buildId\":\"28C6AADE70B2D40D1F0F3D0A1A0CAD1AB816448F\"},{\"b\":\"7F3DEFF4A000\",\"path\":\"/lib/x86_64-linux-gnu/libc.so.6\",\"elfType\":3,\"buildId\":\"B417C0BA7CC5CF06D1D1BED6652CEDB9253C60D0\"}]}}\n  Frame: {\"a\":\"7F3DF29C6C45\",\"b\":\"7F3DF2824000\",\"o\":\"1A2C45\",\"s\":\"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.575\",\"s+\":\"1E5\"}\n  Frame: {\"a\":\"7F3DF29C835A\",\"b\":\"7F3DF2824000\",\"o\":\"1A435A\",\"s\":\"_ZN5mongo15printStackTraceERNS_14StackTraceSinkE\",\"s+\":\"2A\"}\n  Frame: {\"a\":\"7F3DF29C83A3\",\"b\":\"7F3DF2824000\",\"o\":\"1A43A3\",\"s\":\"_ZN5mongo15printStackTraceERSo\",\"s+\":\"33\"}\n  Frame: {\"a\":\"7F3DF29C57FC\",\"b\":\"7F3DF2824000\",\"o\":\"1A17FC\",\"s\":\"_ZN5mongo12_GLOBAL__N_123printSignalAndBacktraceEi\",\"s+\":\"AC\"}\n  Frame: {\"a\":\"7F3DF29C59F7\",\"b\":\"7F3DF2824000\",\"o\":\"1A19F7\",\"s\":\"_ZN5mongo12_GLOBAL__N_124abruptQuitWithAddrSignalEiP9siginfo_tPv\",\"s+\":\"107\"}\n  Frame: {\"a\":\"7F3DF034D890\",\"b\":\"7F3DF033B000\",\"o\":\"12890\",\"s\":\"funlockfile\",\"s+\":\"50\"}\n  Frame: {\"a\":\"7F3DF4854EDA\",\"b\":\"7F3DF484E000\",\"o\":\"6EDA\",\"s\":\"_ZN5mongo12_GLOBAL__N_121loopbackBuildResponseEPNS_16OperationContextEPNS_9LastErrorERNS_7MessageE\",\"s+\":\"4A\"}\n  Frame: {\"a\":\"7F3DF48559C8\",\"b\":\"7F3DF484E000\",\"o\":\"79C8\",\"s\":\"_ZN5mongo14DBDirectClient4callERNS_7MessageES2_bPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE\",\"s+\":\"38\"}\n  Frame: {\"a\":\"7F3DF3860AB8\",\"b\":\"7F3DF3846000\",\"o\":\"1AAB8\",\"s\":\"_ZN5mongo12DBClientBase20runCommandWithTargetENS_12OpMsgRequestE\",\"s+\":\"208\"}\n  Frame: {\"a\":\"7F3DF644B4CF\",\"b\":\"7F3DF6365000\",\"o\":\"E64CF\",\"s\":\"_ZN5mongo12DBClientBase10runCommandENS_12OpMsgRequestE\",\"s+\":\"7F\"}\n  Frame: {\"a\":\"7F3DF6450193\",\"b\":\"7F3DF6365000\",\"o\":\"EB193\",\"s\":\"_ZN5mongo19PersistentTaskStoreINS_17RangeDeletionTaskEE6removeEPNS_16OperationContextENS_5QueryERKNS_19WriteConcernOptionsE\",\"s+\":\"2E3\"}\n  Frame: {\"a\":\"7F3DF6446F49\",\"b\":\"7F3DF6365000\",\"o\":\"E1F49\",\"s\":\"_ZN5mongo13migrationutil30deleteRangeDeletionTaskLocallyEPNS_16OperationContextERKNS_4UUIDERKNS_19WriteConcernOptionsE\",\"s+\":\"119\"}\n  Frame: {\"a\":\"7F3DF6450616\",\"b\":\"7F3DF6365000\",\"o\":\"EB616\",\"s\":\"_ZN5mongo14future_details10statusCallIRZZZNS_14ExecutorFutureIvE12wrapCBHelperIFNS_6StatusES5_EEEDaONS_15unique_functionIT_EEENUlDpOT_E_clIJS5_EEENS_6FutureINS0_17UnwrappedTypeImplIDTclfp_spcl7forwardIDtfp_EEfp_EEEE4typeEEESD_ENUlS5_E_clES5_EUlvE_JNS0_8FakeVoidEEEEDaOS8_DpOT0_\",\"s+\":\"226\"}\n  Frame: {\"a\":\"7F3DF64507E8\",\"b\":\"7F3DF6365000\",\"o\":\"EB7E8\",\"s\":\"_ZZN5mongo15unique_functionIFvNS_6StatusEEE8makeImplIZZNS_14ExecutorFutureIvE12wrapCBHelperIFS1_S1_EEEDaONS0_IT_EEENUlDpOT_E_clIJS1_EEENS_6FutureINS_14future_details17UnwrappedTypeImplIDTclfp_spcl7forwardIDtfp_EEfp_EEEE4typeEEESE_EUlS1_E_EEDaOS9_EN12SpecificImpl4callEOS1_\",\"s+\":\"C8\"}\n  Frame: {\"a\":\"7F3DF5778644\",\"b\":\"7F3DF5774000\",\"o\":\"4644\",\"s\":\"_ZZN5mongo15unique_functionIFvRKNS_8executor12TaskExecutor12CallbackArgsEEE8makeImplIZNS2_8scheduleENS0_IFvNS_6StatusEEEEEUlS5_E_EEDaOT_EN12SpecificImpl4callES5_\",\"s+\":\"44\"}\n  Frame: {\"a\":\"7F3DF57F87B1\",\"b\":\"7F3DF57E3000\",\"o\":\"157B1\",\"s\":\"_ZN5mongo8executor22ThreadPoolTaskExecutor11runCallbackESt10shared_ptrINS1_13CallbackStateEE\",\"s+\":\"121\"}\n  Frame: {\"a\":\"7F3DF57F8E22\",\"b\":\"7F3DF57E3000\",\"o\":\"15E22\",\"s\":\"_ZZN5mongo15unique_functionIFvNS_6StatusEEE8makeImplIZNS_8executor22ThreadPoolTaskExecutor23scheduleIntoPool_inlockEPNSt7__cxx114listISt10shared_ptrINS6_13CallbackStateEESaISB_EEERKSt14_List_iteratorISB_ESI_St11unique_lockINS_5LatchEEEUlT_E1_EEDaOSM_EN12SpecificImpl4callEOS1_\",\"s+\":\"A2\"}\n  Frame: {\"a\":\"7F3DF444CEF0\",\"b\":\"7F3DF4442000\",\"o\":\"AEF0\",\"s\":\"_ZN5mongo10ThreadPool10_doOneTaskEPSt11unique_lockINS_5LatchEE\",\"s+\":\"140\"}\n  Frame: {\"a\":\"7F3DF444F59C\",\"b\":\"7F
      

      This particular backtrace was printed due to a segfault; I believe this log line is emitted here.

            Assignee:
            billy.donahue@mongodb.com Billy Donahue
            Reporter:
            esha.maharishi@mongodb.com Esha Maharishi (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: