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

logd() fails with invalid format string

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.8.0
    • Affects Version/s: None
    • Component/s: Logging
    • None
    • Fully Compatible
    • ALL
    • Security 2020-09-07, Security 2020-09-21

      I have the code to log a string.

                      logd("XXX reply to {}", request.toString());
      

      It prints out the correct message but also an error message.

      2020-07-31T04:59:55.024Z I  -        [thread1] XXX reply to { replSetHeartbeat: "mySet", configVersion: 1, configTerm: -1, hbv: 1, from: "node1:12345", fromId: 1, term: 0, primaryId: -1 }
      2020-07-31T04:59:55.025Z I  -        [thread1] Exception during log, message not written to stream{"exception":{"code":8,"codeName":"UnknownError","errmsg":"Caught std::exception of type fmt::v6::format_error: invalid format string"}}
      

      The "invalid format string" occurs multiple times in the codebase, but I managed to pinpoint this one. By adding std::abort() before it, I got the stack trace to this point.

       /home/syzhou/10gen/macbook-copy/src/mongo/util/stacktrace_posix.cpp:263:21: LibunwindStepIteration
       /home/syzhou/10gen/macbook-copy/src/mongo/util/stacktrace_posix.cpp:434:36: mongo::stack_trace_detail::(anonymous namespace)::printStackTraceImpl(mongo::stack_trace_detail::(anonymous namespace)::Options const&, mongo::StackTraceSink*) [clone .constprop.627]
       /home/syzhou/10gen/macbook-copy/src/mongo/util/stacktrace_posix.cpp:485:44: mongo::printStackTrace()
       /home/syzhou/10gen/macbook-copy/src/mongo/util/signal_handlers_synchronous.cpp:262:28: abruptQuit
       /home/syzhou/10gen/macbook-copy/src/mongo/util/signal_handlers_synchronous.cpp:296:15: mongo::(anonymous namespace)::abruptQuitAction(int, siginfo_t*, void*)
       ??:0:0: ??
       /build/glibc-LK5gWL/glibc-2.23/signal/../sysdeps/unix/sysv/linux/raise.c:54:0: gsignal
       /build/glibc-LK5gWL/glibc-2.23/stdlib/abort.c:89:0: abort
       /home/syzhou/10gen/macbook-copy/src/third_party/fmt/dist/include/fmt/format.h:2561:19: char const* fmt::v6::internal::parse_arg_id<char, fmt::v6::internal::id_adapter<fmt::v6::format_handler<fmt::v6::arg_formatter<fmt::v6::buffer_range<char> >, char, fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >&, char> >(char const*, char const*, fmt::v6::internal::id_adapter<fmt::v6::format_handler<fmt::v6::arg_formatter<fmt::v6::buffer_range<char> >, char, fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >&, char>&&)
       /home/syzhou/10gen/macbook-copy/src/third_party/fmt/dist/include/fmt/format.h:2823:29: void fmt::v6::internal::parse_format_string<false, char, fmt::v6::format_handler<fmt::v6::arg_formatter<fmt::v6::buffer_range<char> >, char, fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >&>(fmt::v6::basic_string_view<char>, fmt::v6::format_handler<fmt::v6::arg_formatter<fmt::v6::buffer_range<char> >, char, fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >&)
       /home/syzhou/10gen/macbook-copy/src/third_party/fmt/dist/include/fmt/format.h:3450:41: fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char>::iterator fmt::v6::vformat_to<fmt::v6::arg_formatter<fmt::v6::buffer_range<char> >, char, fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >(fmt::v6::arg_formatter<fmt::v6::buffer_range<char> >::range, fmt::v6::basic_string_view<char>, fmt::v6::basic_format_args<fmt::v6::basic_format_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >, fmt::v6::internal::locale_ref)
       /home/syzhou/10gen/macbook-copy/src/third_party/fmt/dist/include/fmt/format.h:3570:44: fmt::v6::buffer_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char>::iterator fmt::v6::internal::vformat_to<char>(fmt::v6::internal::buffer<char>&, fmt::v6::basic_string_view<char>, fmt::v6::basic_format_args<fmt::v6::buffer_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >)
       /home/syzhou/10gen/macbook-copy/src/third_party/fmt/dist/include/fmt/format.h:3578:32: fmt::v6::buffer_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char>::iterator fmt::v6::vformat_to<fmt::v6::basic_string_view<char>, char, 0>(fmt::v6::internal::buffer<char>&, fmt::v6::basic_string_view<char> const&, fmt::v6::basic_format_args<fmt::v6::buffer_context<std::back_insert_iterator<fmt::v6::internal::buffer<char> >, char> >)
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/plain_formatter.cpp:161:98: mongo::logv2::PlainFormatter::operator()(boost::log::v2_mt_posix::record_view const&, fmt::v6::basic_memory_buffer<char, 500ul, std::allocator<char> >&) const
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/plain_formatter.cpp:180:15: mongo::logv2::PlainFormatter::operator()(boost::log::v2_mt_posix::record_view const&, boost::log::v2_mt_posix::basic_formatting_ostream<char, std::char_traits<char>, std::allocator<char> >&) const
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/detail/light_function.hpp:476:18: boost::log::v2_mt_posix::aux::light_function<void (boost::log::v2_mt_posix::record_view const&, boost::log::v2_mt_posix::expressions::aux::stream_ref<boost::log::v2_mt_posix::basic_formatting_ostream<char, std::char_traits<char>, std::allocator<char> > >)>::operator()(boost::log::v2_mt_posix::record_view const&, boost::log::v2_mt_posix::expressions::aux::stream_ref<boost::log::v2_mt_posix::basic_formatting_ostream<char, std::char_traits<char>, std::allocator<char> > >) const
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/expressions/formatter.hpp:445:9: boost::log::v2_mt_posix::basic_formatter<char>::operator()(boost::log::v2_mt_posix::record_view const&, boost::log::v2_mt_posix::basic_formatting_ostream<char, std::char_traits<char>, std::allocator<char> >&) const
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/sinks/basic_sink_frontend.hpp:458:13: void boost::log::v2_mt_posix::sinks::basic_formatting_sink_frontend<char>::feed_record<boost::log::v2_mt_posix::aux::fake_mutex, mongo::logv2::LogCaptureBackend>(boost::log::v2_mt_posix::record_view const&, boost::log::v2_mt_posix::aux::fake_mutex&, mongo::logv2::LogCaptureBackend&)
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/sinks/basic_sink_frontend.hpp:507:9: bool boost::log::v2_mt_posix::sinks::basic_formatting_sink_frontend<char>::try_feed_record<boost::recursive_mutex, mongo::logv2::LogCaptureBackend>(boost::log::v2_mt_posix::record_view const&, boost::recursive_mutex&, mongo::logv2::LogCaptureBackend&)
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/sinks/sync_frontend.hpp:161:42: boost::log::v2_mt_posix::sinks::synchronous_sink<mongo::logv2::LogCaptureBackend>::try_consume(boost::log::v2_mt_posix::record_view const&)
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/libs/log/src/core.cpp:704:43: boost::log::v2_mt_posix::core::push_record_move(boost::log::v2_mt_posix::record&)
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/core/core.hpp:310:25: boost::log::v2_mt_posix::core::push_record(boost::log::v2_mt_posix::record&&)
       /home/syzhou/10gen/macbook-copy/src/third_party/boost-1.70.0/boost/log/sources/basic_logger.hpp:267:29: boost::log::v2_mt_posix::sources::basic_logger<char, mongo::logv2::LogSource, boost::log::v2_mt_posix::sources::single_thread_model>::push_record_unlocked(boost::log::v2_mt_posix::record&&)
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/log_source.h:105:35: mongo::logv2::LogSource::push_record(boost::log::v2_mt_posix::record&&)
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/log_detail.cpp:162:27: mongo::logv2::detail::doLogImpl(int, mongo::logv2::LogSeverity const&, mongo::logv2::LogOptions const&, mongo::StringData, mongo::logv2::TypeErasedAttributeStorage const&)
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/log_detail.cpp:178:14: mongo::logv2::detail::doUnstructuredLogImpl(mongo::logv2::LogSeverity const&, mongo::logv2::LogOptions const&, mongo::StringData, mongo::logv2::TypeErasedAttributeStorage const&)
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/log_debug.h:54:34: void mongo::logv2::logd_detail::logd<0ul, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >(std::integer_sequence<unsigned long, 0ul>, mongo::StringData, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)
       /home/syzhou/10gen/macbook-copy/src/mongo/logv2/log_debug.h:69:29: void mongo::logd<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >(mongo::StringData, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)
       /home/syzhou/10gen/macbook-copy/src/mongo/db/repl/mock_fixture.cpp:80:21: mongo::repl::Mock::replyInLoop()
       /home/syzhou/10gen/macbook-copy/src/mongo/db/repl/mock_fixture.h:98:51: mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}::operator()() const
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/bits/invoke.h:60:36: void std::__invoke_impl<void, mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}>(std::__invoke_other, mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}&&)
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/bits/invoke.h:95:40: std::__invoke_result<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}>::type std::__invoke<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}>(std::__invoke_result&&, (mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}&&)...)
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/tuple:1678:27: _ZSt12__apply_implIZN5mongo4repl4MockC4EPNS0_8executor20NetworkInterfaceMockEEUlvE_St5tupleIJEEJEEDcOT_OT0_St16integer_sequenceImJXspT1_EEE
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/tuple:1687:31: _ZSt5applyIZN5mongo4repl4MockC4EPNS0_8executor20NetworkInterfaceMockEEUlvE_St5tupleIJEEEDcOT_OT0_
       /home/syzhou/10gen/macbook-copy/src/mongo/stdx/thread.h:186:36: mongo::stdx::thread::thread<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}, , 0>(mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1})::{lambda()#1}::operator()()
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/bits/invoke.h:60:36: mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1} std::__invoke_impl<void, mongo::stdx::thread::thread<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}, , 0>(mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1})::{lambda()#1}>(std::__invoke_other, mongo::stdx::thread::thread<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}, , 0>(mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1})::{lambda()#1}&&)
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/bits/invoke.h:95:40: _ZSt8__invokeIZN5mongo4stdx6threadC4IZNS0_4repl4MockC4EPNS0_8executor20NetworkInterfaceMockEEUlvE_JELi0EEET_DpOT0_EUlvE_JEENSt15__invoke_resultISA_JDpSB_EE4typeEOSA_SD_
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/thread:234:26: decltype (__invoke((_S_declval<0ul>)())) std::thread::_Invoker<std::tuple<mongo::stdx::thread::thread<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}, , 0>(mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1})::{lambda()#1}> >::_M_invoke<0ul>(std::_Index_tuple<0ul>)
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/thread:243:31: std::thread::_Invoker<std::tuple<mongo::stdx::thread::thread<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}, , 0>(mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1})::{lambda()#1}> >::operator()()
       /opt/mongodbtoolchain/stow/gcc-v3.kGx/include/c++/8.2.0/thread:186:13: std::thread::_State_impl<std::thread::_Invoker<std::tuple<mongo::stdx::thread::thread<mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1}, , 0>(mongo::repl::Mock::Mock(mongo::executor::NetworkInterfaceMock*)::{lambda()#1})::{lambda()#1}> > >::_M_run()
       /data/mci/b9412281d36abf103ba1d48814ad21fd/toolchain-builder/tmp/build-gcc-v3.sh-pve/build/x86_64-mongodb-linux/libstdc++-v3/src/c++11/../../../../../src/combined/libstdc++-v3/src/c++11/thread.cc:80:18: execute_native_thread_routine
       ??:0:0: start_thread
       /build/glibc-LK5gWL/glibc-2.23/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:109:0: clone
      

      I tried to get a minimal reproduction but failed. Constructing the log message and passing it to logd() works as expected.

            Assignee:
            mark.benvenuto@mongodb.com Mark Benvenuto
            Reporter:
            siyuan.zhou@mongodb.com Siyuan Zhou
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: