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

Raised exceptions and extensive logging on proper client disconnect

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 4.4.2, 6.0.0, 5.0.10
    • Component/s: None
    • Labels:
    • ALL
    • Hide
      1. Start MongoDB server (ver. 5.0.10 or 6.0), set log level with commnad db.setLogLevel(0)
      2. Using mongosh (1.5.4) or mongo shell (5.0.10) just connect to the MongoDB server (e.g. mongosh --username admin --password password --port 12345)
      3. After connection is made to the server, simply disconnect using  command "exit".
      4. Check logs from MongoDB server where exceptions are logged together with huge backtrace

       

      Running "Community MongoDB edition" on Windows 10. MongoDB is run locally.

      Show
      Start MongoDB server (ver. 5.0.10 or 6.0), set log level with commnad db.setLogLevel(0) Using mongosh (1.5.4) or mongo shell (5.0.10) just connect to the MongoDB server (e.g. mongosh --username admin --password password --port 12345) After connection is made to the server, simply disconnect using  command "exit". Check logs from MongoDB server where exceptions are logged together with huge backtrace   Running "Community MongoDB edition" on Windows 10. MongoDB is run locally.

      Problem Statement/Rationale

      When client (mongosh or mongo shell) is properly ending connection to MongoDB server (using command exit) the "HostUnreachable" exception is thrown and logged together with huge backtrace information. This got worse - more logging - with version 5.0 and 6.0 (compared to 4.4.2).

      The problem seems to be general, because the same behavior is with mongosh and mongo shell.

      Expected Results

      On proper disconnect (no timeout, no network issues or any other issues) I would expect just simple message "Client disconnected" the same way it is when client connects (just message "Connection accepted").

      Actual Results

      Exception is thrown (why should be exception thrown on proper disconnect?) and huge amount of log (backtrace) information is generated - e.g.

      {"t":{"$date":"2022-08-11T12:23:13.065+02:00"},"s":"W",  "c":"-",        "id":23075,   "ctx":"conn5","msg":"DBException thrown","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}
      {"t":{"$date":"2022-08-11T12:23:13.066+02:00"},"s":"W",  "c":"-",        "id":23075,   "ctx":"conn2","msg":"DBException thrown","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection reset by peer"}}}
      {"t":{"$date":"2022-08-11T12:23:13.066+02:00"},"s":"W",  "c":"-",        "id":23075,   "ctx":"conn3","msg":"DBException thrown","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}
      {"t":{"$date":"2022-08-11T12:23:13.066+02:00"},"s":"W",  "c":"-",        "id":23075,   "ctx":"conn4","msg":"DBException thrown","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31380,   "ctx":"conn5","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"7FF68FDF0963","module":"mongod.exe","file":".../src/mongo/util/stacktrace_windows.cpp","line":321,"s":"mongo::`anonymous namespace'::printWindowsStackTraceImpl","s+":"43"},{"a":"7FF68FDFD86B","module":"mongod.exe","file":".../src/mongo/util/assert_util.cpp","line":86,"s":"mongo::DBException::traceIfNeeded","s+":"1CB"},{"a":"7FF68FE655F1","module":"mongod.exe","file":".../src/mongo/util/assert_util.h","line":152,"s":"mongo::AssertionException::AssertionException","s+":"41"},{"a":"7FF68FE50360","module":"mongod.exe","file":".../src/mongo/util/assert_util.h","line":183,"s":"mongo::error_details::ExceptionForImpl<6,mongo::ExceptionForCat<0>,mongo::ExceptionForCat<14> >::ExceptionForImpl<6,mongo::ExceptionForCat<0>,mongo::ExceptionForCat<14> >","s+":"40"},{"a":"7FF68FE6A46F","module":"mongod.exe","file":"Z:/data/mci/bf6ffa5cf5d9d0de72c13c6788749135/src/build/opt/mongo/base/error_codes.cpp","line":2230,"s":"mongo::error_details::throwExceptionForStatus","s+":"DF"},{"a":"7FF68FDFDA14","module":"mongod.exe","file":".../src/mongo/util/assert_util.cpp","line":260,"s":"mongo::uassertedWithLocation","s+":"184"},{"a":"7FF68E56E6D1","module":"mongod.exe","file":".../src/mongo/transport/service_state_machine.cpp","line":394,"s":"mongo::transport::ServiceStateMachine::Impl::sourceCallback","s+":"4F1"},{"a":"7FF68E5691FD","module":"mongod.exe","file":".../src/mongo/util/future_impl.h","line":250,"s":"mongo::future_details::call<<lambda_adee3533ad9aaebd514c253f861c99b3> &,mongo::StatusWith<mongo::Message> >","s+":"AD"},{"a":"7FF68E56AD46","module":"mongod.exe","file":".../src/mongo/util/future_impl.h","line":986,"s":"<lambda_71c7af3a1314ac8fa87ef8ca0e57d022>::operator()","s+":"56"},{"a":"7FF68E5698B0","module":"mongod.exe","file":".../src/mongo/util/future_impl.h","line":1193,"s":"mongo::future_details::FutureImpl<mongo::Message>::generalImpl<<lambda_3511eed2ba74e987471aa1dba7886515>,<lambda_71c7af3a1314ac8fa87ef8ca0e57d022>,<lambda_7bb8db0db7b00eed4c9c32637ebc8440> >","s+":"80"},{"a":"7FF68E56E847","module":"mongod.exe","file":".../src/mongo/transport/service_state_machine.cpp","line":321,"s":"mongo::transport::ServiceStateMachine::Impl::sourceMessage","s+":"157"},{"a":"7FF68E569FF6","module":"mongod.exe","file":".../src/mongo/util/future.h","line":1211,"s":"mongo::makeReadyFutureWith<<lambda_abaa6d044ac34b6d286cfbc6dd2101a2>,0>","s+":"36"},{"a":"7FF68E56EAA2","module":"mongod.exe","file":".../src/mongo/transport/service_state_machine.cpp","line":570,"s":"mongo::transport::ServiceStateMachine::Impl::startNewLoop","s+":"62"},{"a":"7FF68E56B9BA","module":"mongod.exe","file":".../src/mongo/util/functional.h","line":154,"s":"`mongo::unique_function<void __cdecl(mongo::Status)>::makeImpl<<lambda_c6b349ee357260a796ff8e9aa04c91e0> >'::`2'::SpecificImpl::call","s+":"6A"},{"a":"7FF68FAD8747","module":"mongod.exe","file":".../src/mongo/util/functional.h","line":154,"s":"`mongo::unique_function<void __cdecl(mongo::Status)>::makeImpl<<lambda_f6fe401c5262fec9b8f8213c1ce091a0> >'::`2'::SpecificImpl::call","s+":"47"},{"a":"7FF68FAD86CB","module":"mongod.exe","file":".../src/mongo/util/functional.h","line":154,"s":"`mongo::unique_function<void __cdecl(void)>::makeImpl<<lambda_00027e990a0ecbb312a62eb8601f0a9b> >'::`2'::SpecificImpl::call","s+":"2B"},{"a":"7FF68FAD80D9","module":"mongod.exe","file":".../src/mongo/transport/service_executor_synchronous.cpp","line":132,"s":"<lambda_f9db7de3fc63d9ea9f1724897a3de362>::operator()","s+":"D9"},{"a":"7FF68FAD7132","module":"mongod.exe","file":"C:/Program Files (x86)/Microsoft Visual Studio/2019/Professional/VC/Tools/MSVC/14.29.30133/include/thread","line":55,"s":"std::thread::_Invoke<std::tuple<<lambda_8cebf4d190f9c1ee7cff12dbc09aadbe> >,0>","s+":"32"},{"a":"7FFB24251BB2","module":"ucrtbase.dll","s":"configthreadlocale","s+":"92"},{"a":"7FFB24657034","module":"KERNEL32.DLL","s":"BaseThreadInitThunk","s+":"14"}]}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FDF0963","module":"mongod.exe","file":".../src/mongo/util/stacktrace_windows.cpp","line":321,"s":"mongo::`anonymous namespace'::printWindowsStackTraceImpl","s+":"43"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FDFD86B","module":"mongod.exe","file":".../src/mongo/util/assert_util.cpp","line":86,"s":"mongo::DBException::traceIfNeeded","s+":"1CB"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FE655F1","module":"mongod.exe","file":".../src/mongo/util/assert_util.h","line":152,"s":"mongo::AssertionException::AssertionException","s+":"41"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FE50360","module":"mongod.exe","file":".../src/mongo/util/assert_util.h","line":183,"s":"mongo::error_details::ExceptionForImpl<6,mongo::ExceptionForCat<0>,mongo::ExceptionForCat<14> >::ExceptionForImpl<6,mongo::ExceptionForCat<0>,mongo::ExceptionForCat<14> >","s+":"40"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FE6A46F","module":"mongod.exe","file":"Z:/data/mci/bf6ffa5cf5d9d0de72c13c6788749135/src/build/opt/mongo/base/error_codes.cpp","line":2230,"s":"mongo::error_details::throwExceptionForStatus","s+":"DF"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FDFDA14","module":"mongod.exe","file":".../src/mongo/util/assert_util.cpp","line":260,"s":"mongo::uassertedWithLocation","s+":"184"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E56E6D1","module":"mongod.exe","file":".../src/mongo/transport/service_state_machine.cpp","line":394,"s":"mongo::transport::ServiceStateMachine::Impl::sourceCallback","s+":"4F1"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E5691FD","module":"mongod.exe","file":".../src/mongo/util/future_impl.h","line":250,"s":"mongo::future_details::call<<lambda_adee3533ad9aaebd514c253f861c99b3> &,mongo::StatusWith<mongo::Message> >","s+":"AD"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E56AD46","module":"mongod.exe","file":".../src/mongo/util/future_impl.h","line":986,"s":"<lambda_71c7af3a1314ac8fa87ef8ca0e57d022>::operator()","s+":"56"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E5698B0","module":"mongod.exe","file":".../src/mongo/util/future_impl.h","line":1193,"s":"mongo::future_details::FutureImpl<mongo::Message>::generalImpl<<lambda_3511eed2ba74e987471aa1dba7886515>,<lambda_71c7af3a1314ac8fa87ef8ca0e57d022>,<lambda_7bb8db0db7b00eed4c9c32637ebc8440> >","s+":"80"}}}
      {"t":{"$date":"2022-08-11T12:23:13.204+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E56E847","module":"mongod.exe","file":".../src/mongo/transport/service_state_machine.cpp","line":321,"s":"mongo::transport::ServiceStateMachine::Impl::sourceMessage","s+":"157"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E569FF6","module":"mongod.exe","file":".../src/mongo/util/future.h","line":1211,"s":"mongo::makeReadyFutureWith<<lambda_abaa6d044ac34b6d286cfbc6dd2101a2>,0>","s+":"36"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E56EAA2","module":"mongod.exe","file":".../src/mongo/transport/service_state_machine.cpp","line":570,"s":"mongo::transport::ServiceStateMachine::Impl::startNewLoop","s+":"62"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68E56B9BA","module":"mongod.exe","file":".../src/mongo/util/functional.h","line":154,"s":"`mongo::unique_function<void __cdecl(mongo::Status)>::makeImpl<<lambda_c6b349ee357260a796ff8e9aa04c91e0> >'::`2'::SpecificImpl::call","s+":"6A"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FAD8747","module":"mongod.exe","file":".../src/mongo/util/functional.h","line":154,"s":"`mongo::unique_function<void __cdecl(mongo::Status)>::makeImpl<<lambda_f6fe401c5262fec9b8f8213c1ce091a0> >'::`2'::SpecificImpl::call","s+":"47"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FAD86CB","module":"mongod.exe","file":".../src/mongo/util/functional.h","line":154,"s":"`mongo::unique_function<void __cdecl(void)>::makeImpl<<lambda_00027e990a0ecbb312a62eb8601f0a9b> >'::`2'::SpecificImpl::call","s+":"2B"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FAD80D9","module":"mongod.exe","file":".../src/mongo/transport/service_executor_synchronous.cpp","line":132,"s":"<lambda_f9db7de3fc63d9ea9f1724897a3de362>::operator()","s+":"D9"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FF68FAD7132","module":"mongod.exe","file":"C:/Program Files (x86)/Microsoft Visual Studio/2019/Professional/VC/Tools/MSVC/14.29.30133/include/thread","line":55,"s":"std::thread::_Invoke<std::tuple<<lambda_8cebf4d190f9c1ee7cff12dbc09aadbe> >,0>","s+":"32"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FFB24251BB2","module":"ucrtbase.dll","s":"configthreadlocale","s+":"92"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"I",  "c":"CONTROL",  "id":31445,   "ctx":"conn5","msg":"Frame","attr":{"frame":{"a":"7FFB24657034","module":"KERNEL32.DLL","s":"BaseThreadInitThunk","s+":"14"}}}
      {"t":{"$date":"2022-08-11T12:23:13.205+02:00"},"s":"W",  "c":"-",        "id":23075,   "ctx":"conn5","msg":"DBException thrown","attr":{"error":{"code":6,"codeName":"HostUnreachable","errmsg":"Connection closed by peer"}}}

      Running Mongo 5.0 and 6.0 and verbose level 0 and going through all the steps in "Steps to Reproduce" it generates 245 kB log file. Just client connecting and immediately disconnecting, no other actions.

      This is a problem, because when there are some mongosh scripts running (e.g. zabbix monitoring) then Mongo creates a huge log file just overnight filled with backtraces of those 'disconnect exceptions'.

       

      Additional Notes

      All following files are just logs from "steps to reproduce" - connecting and disconnecting to MongoDB. The Mongo server started on version 4.4.2 and then was upgraded to 5.0 and 6.0.

      Files attached:
      MongoDBLog4.4.2.mongosh.txt (64kB) - connecting with mongosh to MongoDB 4.4.2
      MongoDBLog5.0.mongosh.txt (258kB)- the same, just connecting to MongoDB 5.0.10
      MongoDBLog6.0.mongosh.txt (245kB)- the same, just connecting to MongoDB 6.0
      MongoDBLog6.0.MongoShell.txt (143kB)- connecting with mongo shell to MongoDB 6.0

        1. MongoDBLog4.4.2.mongosh.txt
          63 kB
        2. MongoDBLog5.0.mongosh.txt
          258 kB
        3. MongoDBLog6.0.mongosh.txt
          244 kB
        4. MongoDBLog6.0.MongoShell.txt
          142 kB

            Assignee:
            chris.kelly@mongodb.com Chris Kelly
            Reporter:
            svope Petr S
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: