[SERVER-68727] Raised exceptions and extensive logging on proper client disconnect Created: 11/Aug/22  Updated: 18/Aug/22  Resolved: 18/Aug/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 4.4.2, 6.0.0, 5.0.10
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Petr S Assignee: Chris Kelly
Resolution: Done Votes: 0
Labels: exception, log
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File MongoDBLog4.4.2.mongosh.txt     Text File MongoDBLog5.0.mongosh.txt     Text File MongoDBLog6.0.MongoShell.txt     Text File MongoDBLog6.0.mongosh.txt    
Operating System: ALL
Steps To Reproduce:
  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.

Participants:

 Description   

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



 Comments   
Comment by Petr S [ 16/Aug/22 ]

Hi Chris,

 

yes, the traceAllExceptions: true was exactly the problem. 

Thanks for the help!

 

Regards,

 

Petr

Comment by Chris Kelly [ 16/Aug/22 ]

Hello,

Thanks for your report. I was initially unable to reproduce this on multiple versions of mongosh, mongodb, and operating systems. However, I noticed in your logs you are explicitly passing in traceAllExceptions: true in your configuration which I found replicates your issue. This is primarily used for debugging. Just getting rid of that should solve your issue.

Let me know if this resolves the problem for you!

Christopher

Generated at Thu Feb 08 06:11:34 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.