[SERVER-22427] Add additional diagnostics to "Operation timed out" errors returned from NetworkInterfaceASIO Created: 01/Feb/16  Updated: 08/Jan/24  Resolved: 21/Apr/16

Status: Closed
Project: Core Server
Component/s: Diagnostics, Networking
Affects Version/s: 3.2.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Spencer Brody (Inactive) Assignee: Kaloian Manassiev
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-22273 Mongos not work correctly Closed
related to SERVER-22392 "Operation timed out" when enableShar... Closed
Operating System: ALL
Sprint: Platforms 10 (02/19/16)
Participants:

 Description   

We've had a few reports from the field of users getting back "Operation timed out" errors (see SERVER-22392 and SERVER-22273 for some examples of this). This message is only returned by NetworkInterfaceASIO when a remote command scheduled through it times out. When that happens though, it's just about impossible to figure out what the actual root cause is. We need a better way to diagnose issues of this type. At the very least it would be nice to know what the name of the command being run was, to whom it was sent, and what the timeout that was exceeded actually was.



 Comments   
Comment by Kaloian Manassiev [ 21/Apr/16 ]

NetworkInterfaceASIO already has the capability to trace the lifetime of outgoing requests throughout the logs and this can be enabled at log level 2. This is an example of a successful request:

2016-04-15T23:00:42.608+0000 D ASIO     [conn1] startCommand: RemoteCommand 250 -- target:ip-10-33-187-85:20765 db:config expDate:2016-04-15T23:01:12.608+0000 cmd:{ count: "chunks", query: { ns: "foo.bar" }, readConcern: { level: "majority", afterOpTime: { ts: Timestamp 1460761242000|3, t: 2 } }, maxTimeMS: 30000 }
2016-04-15T23:00:42.608+0000 D ASIO     [NetworkInterfaceASIO-ShardRegistry-0] Starting asynchronous command 250 on host ip-10-33-187-85:20765
2016-04-15T23:00:42.608+0000 D ASIO     [NetworkInterfaceASIO-ShardRegistry-0] Request 250 finished with response: { waitedMS: 0, n: 0, ok: 1.0 }

Similar messages are available for tracing errors and timeouts.

Based on discussion with the team we decided that this is a reasonable tradeoff between log verbosity and diagnostic capability, so I am closing the ticket as Works As Designed.

Comment by Grant Ridder [ 04/Apr/16 ]

For what its worth, i had this issue and did a rolling restart of the config servers and that fixed it
Using mongodb 3.2.1 and a config server replica set

Comment by Ali Hallaji [ 27/Feb/16 ]

I installed mongodb version 3.2.3 After some bug on mongodb version 3.2.1 , but It is very unstable.
My previous issue is SERVER-22273, And now I same problem.
issue: Mongos don't return any thing from some mongos(some mongos is ok pretty), and It show this message:

2016-02-27T12:36:19.633+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Operation 483 timed out.
2016-02-27T12:36:19.633+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Failed to execute command: RemoteCommand 483 – target:bnd-db01:37017 db:config expDate:2016-02-27T12:36:19.632+0330 cmd:{ find: "shards", readConcern: { level: "majority", afterOpTime:

{ ts: Timestamp 1456495056000|1, t: 14 }

}, maxTimeMS: 30000 } reason: ExceededTimeLimit: Operation timed out
2016-02-27T12:36:19.633+0330 D EXECUTOR [NetworkInterfaceASIO-ShardRegistry-0] Received remote response: ExceededTimeLimit: Operation timed out
2016-02-27T12:36:19.633+0330 D - [Balancer] User Assertion: 50:could not get updated shard list from config server due to ExceededTimeLimit: Operation timed out
2016-02-27T12:36:19.633+0330 W - [Balancer] DBException thrown :: caused by :: 50 could not get updated shard list from config server due to ExceededTimeLimit: Operation timed out
2016-02-27T12:36:19.638+0330 I - [Balancer]
0xc2e0e2 0xc2e023 0xbb7177 0x68a786 0xbb73bc 0xbb745c 0xaf3630 0xa2b406 0xbbb7d0 0x7fb6e5512a40 0x7fb6e4d2f182 0x7fb6e4a5c47d
----- BEGIN BACKTRACE -----
{"backtrace":[

{"b":"400000","o":"82E0E2","s":"_ZN5mongo15printStackTraceERSo"}

,

{"b":"400000","o":"82E023","s":"_ZN5mongo15printStackTraceEv"}

,

{"b":"400000","o":"7B7177","s":"_ZN5mongo11DBException13traceIfNeededERKS0_"}

,

{"b":"400000","o":"28A786","s":"_ZN5mongo11DBExceptionC1ERKSsi"}

,

{"b":"400000","o":"7B73BC","s":"_ZN5mongo9uassertedEiPKc"}

,

{"b":"400000","o":"7B745C"}

,

{"b":"400000","o":"6F3630","s":"_ZN5mongo13ShardRegistry6reloadEPNS_16OperationContextE"}

,

{"b":"400000","o":"62B406","s":"_ZN5mongo8Balancer3runEv"}

,

{"b":"400000","o":"7BB7D0","s":"_ZN5mongo13BackgroundJob7jobBodyEv"}

,

{"b":"7FB6E5461000","o":"B1A40"}

,

{"b":"7FB6E4D27000","o":"8182"}

,

{"b":"7FB6E4962000","o":"FA47D","s":"clone"}

],"processInfo":{ "mongodbVersion" : "3.2.3", "gitVersion" : "b326ba837cf6f49d65c2f85e1b70f6f31ece7937", "compiledModules" : [], "uname" :

{ "sysname" : "Linux", "release" : "3.19.0-25-generic", "version" : "#26~14.04.1-Ubuntu SMP Fri Jul 24 21:16:20 UTC 2015", "machine" : "x86_64" }

, "somap" : [

{ "elfType" : 2, "b" : "400000", "buildId" : "F3CD9A4A42D67CAB44ECCD39D8D1CF8BF49EC0DE" }

,

{ "b" : "7FFF5777F000", "elfType" : 3, "buildId" : "01005E92EA3C0C1527396B65C7412468298D0813" }

,

{ "b" : "7FB6E5F4C000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "A20EFFEC993A8441FA17F2079F923CBD04079E19" }

,

{ "b" : "7FB6E5B71000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "F000D29917E9B6E94A35A8F02E5C62846E5916BC" }

,

{ "b" : "7FB6E5969000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "92FCF41EFE012D6186E31A59AD05BDBB487769AB" }

,

{ "b" : "7FB6E5765000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "C1AE4CB7195D337A77A3C689051DABAA3980CA0C" }

,

{ "b" : "7FB6E5461000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3, "buildId" : "4BF6F7ADD8244AD86008E6BF40D90F8873892197" }

,

{ "b" : "7FB6E515B000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "1D76B71E905CB867B27CEF230FCB20F01A3178F5" }

,

{ "b" : "7FB6E4F45000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "8D0AA71411580EE6C08809695C3984769F25725B" }

,

{ "b" : "7FB6E4D27000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "9318E8AF0BFBE444731BB0461202EF57F7C39542" }

,

{ "b" : "7FB6E4962000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "30C94DC66A1FE95180C3D68D2B89E576D5AE213C" }

,

{ "b" : "7FB6E61AB000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9F00581AB3C73E3AEA35995A0C50D24D59A01D47" }

] }}
mongos(_ZN5mongo15printStackTraceERSo+0x32) [0xc2e0e2]
mongos(_ZN5mongo15printStackTraceEv+0x63) [0xc2e023]
mongos(ZN5mongo11DBException13traceIfNeededERKS0+0x117) [0xbb7177]
mongos(_ZN5mongo11DBExceptionC1ERKSsi+0x46) [0x68a786]
mongos(_ZN5mongo9uassertedEiPKc+0x10C) [0xbb73bc]
mongos(+0x7B745C) [0xbb745c]
mongos(_ZN5mongo13ShardRegistry6reloadEPNS_16OperationContextE+0x570) [0xaf3630]
mongos(_ZN5mongo8Balancer3runEv+0x206) [0xa2b406]
mongos(_ZN5mongo13BackgroundJob7jobBodyEv+0x160) [0xbbb7d0]
libstdc++.so.6(+0xB1A40) [0x7fb6e5512a40]
libpthread.so.0(+0x8182) [0x7fb6e4d2f182]
libc.so.6(clone+0x6D) [0x7fb6e4a5c47d]
----- END BACKTRACE -----
2016-02-27T12:36:19.638+0330 I SHARDING [Balancer] caught exception while doing balance: could not get updated shard list from config server due to ExceededTimeLimit: Operation timed out
2016-02-27T12:36:19.638+0330 D SHARDING [Balancer] *** End of balancing round
2016-02-27T12:36:19.638+0330 I SHARDING [Balancer] about to log metadata event into actionlog: { _id: "db04-bnd-srv-2016-02-27T12:36:19.638+0330-56d1670b7298a3915011e20b", server: "db04-bnd-srv", clientAddr: "", time: new Date(1456563979638), what: "balancer.round", ns: "", details:

{ executionTimeMillis: 30084, errorOccured: true, errmsg: "could not get updated shard list from config server due to ExceededTimeLimit: Operation timed out" }

}

other issue:
2016-02-27T12:25:25.320+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Failed to connect to bnd-db03:27018 - HostUnreachable: End of file
2016-02-27T12:25:25.320+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Failed to execute command: RemoteCommand 54 – target:bnd-db03:27018 db:admin cmd:

{ isMaster: 1 }

reason: HostUnreachable: End of file
2016-02-27T12:25:25.320+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Failed to get connection from pool for request 53: HostUnreachable: End of file
2016-02-27T12:25:25.320+0330 D EXECUTOR [NetworkInterfaceASIO-ShardRegistry-0] Received remote response: HostUnreachable: End of file
2016-02-27T12:25:25.320+0330 D NETWORK [Balancer] Marking host bnd-db03:27018 as failed
2016-02-27T12:25:25.320+0330 D - [Balancer] User Assertion: 6:End of file
2016-02-27T12:25:25.320+0330 W - [Balancer] DBException thrown :: caused by :: 6 End of file
2016-02-27T12:25:25.326+0330 I - [Balancer]
0xc2e0e2 0xc2e023 0xbb7177 0x68a786 0xbb73bc 0xbb745c 0xa29057 0xa29393 0xa2b274 0xbbb7d0 0x7fb6e5512a40 0x7fb6e4d2f182 0x7fb6e4a5c47d
----- BEGIN BACKTRACE -----
{"backtrace":[

{"b":"400000","o":"82E0E2","s":"_ZN5mongo15printStackTraceERSo"}

,

{"b":"400000","o":"82E023","s":"_ZN5mongo15printStackTraceEv"}

,

{"b":"400000","o":"7B7177","s":"_ZN5mongo11DBException13traceIfNeededERKS0_"}

,

{"b":"400000","o":"28A786","s":"_ZN5mongo11DBExceptionC1ERKSsi"}

,

{"b":"400000","o":"7B73BC","s":"_ZN5mongo9uassertedEiPKc"}

,

{"b":"400000","o":"7B745C"}

,

{"b":"400000","o":"629057","s":"_ZN5mongo8Balancer10_checkOIDsEPNS_16OperationContextE"}

,

{"b":"400000","o":"629393","s":"_ZN5mongo8Balancer5_initEPNS_16OperationContextE"}

,

{"b":"400000","o":"62B274","s":"_ZN5mongo8Balancer3runEv"}

,

{"b":"400000","o":"7BB7D0","s":"_ZN5mongo13BackgroundJob7jobBodyEv"}

,

{"b":"7FB6E5461000","o":"B1A40"}

,

{"b":"7FB6E4D27000","o":"8182"}

,

{"b":"7FB6E4962000","o":"FA47D","s":"clone"}

],"processInfo":{ "mongodbVersion" : "3.2.3", "gitVersion" : "b326ba837cf6f49d65c2f85e1b70f6f31ece7937", "compiledModules" : [], "uname" :

{ "sysname" : "Linux", "release" : "3.19.0-25-generic", "version" : "#26~14.04.1-Ubuntu SMP Fri Jul 24 21:16:20 UTC 2015", "machine" : "x86_64" }

, "somap" : [

{ "elfType" : 2, "b" : "400000", "buildId" : "F3CD9A4A42D67CAB44ECCD39D8D1CF8BF49EC0DE" }

,

{ "b" : "7FFF5777F000", "elfType" : 3, "buildId" : "01005E92EA3C0C1527396B65C7412468298D0813" }

,

{ "b" : "7FB6E5F4C000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "A20EFFEC993A8441FA17F2079F923CBD04079E19" }

,

{ "b" : "7FB6E5B71000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "F000D29917E9B6E94A35A8F02E5C62846E5916BC" }

,

{ "b" : "7FB6E5969000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "92FCF41EFE012D6186E31A59AD05BDBB487769AB" }

,

{ "b" : "7FB6E5765000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "C1AE4CB7195D337A77A3C689051DABAA3980CA0C" }

,

{ "b" : "7FB6E5461000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3, "buildId" : "4BF6F7ADD8244AD86008E6BF40D90F8873892197" }

,

{ "b" : "7FB6E515B000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "1D76B71E905CB867B27CEF230FCB20F01A3178F5" }

,

{ "b" : "7FB6E4F45000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "8D0AA71411580EE6C08809695C3984769F25725B" }

,

{ "b" : "7FB6E4D27000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "9318E8AF0BFBE444731BB0461202EF57F7C39542" }

,

{ "b" : "7FB6E4962000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "30C94DC66A1FE95180C3D68D2B89E576D5AE213C" }

,

{ "b" : "7FB6E61AB000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9F00581AB3C73E3AEA35995A0C50D24D59A01D47" }

] }}
mongos(_ZN5mongo15printStackTraceERSo+0x32) [0xc2e0e2]
mongos(_ZN5mongo15printStackTraceEv+0x63) [0xc2e023]
mongos(ZN5mongo11DBException13traceIfNeededERKS0+0x117) [0xbb7177]
mongos(_ZN5mongo11DBExceptionC1ERKSsi+0x46) [0x68a786]
mongos(_ZN5mongo9uassertedEiPKc+0x10C) [0xbb73bc]
mongos(+0x7B745C) [0xbb745c]
mongos(_ZN5mongo8Balancer10_checkOIDsEPNS_16OperationContextE+0x9E7) [0xa29057]
mongos(_ZN5mongo8Balancer5_initEPNS_16OperationContextE+0xB3) [0xa29393]
mongos(_ZN5mongo8Balancer3runEv+0x74) [0xa2b274]
mongos(_ZN5mongo13BackgroundJob7jobBodyEv+0x160) [0xbbb7d0]
libstdc++.so.6(+0xB1A40) [0x7fb6e5512a40]
libpthread.so.0(+0x8182) [0x7fb6e4d2f182]
libc.so.6(clone+0x6D) [0x7fb6e4a5c47d]
----- END BACKTRACE -----
2016-02-27T12:25:25.326+0330 W SHARDING [Balancer] could not initialize balancer, please check that all shards and config servers are up: End of file
2016-02-27T12:25:25.326+0330 I SHARDING [Balancer] will retry to initialize balancer in one minute
2016-02-27T12:25:25.326+0330 I ASIO [NetworkInterfaceASIO-TaskExecutorPool-1-0] Successfully connected to thr-cfg01:37017

other:
2016-02-27T12:25:48.063+0330 D NETWORK [conn4] Socket recv() conn closed? 127.0.0.1:47521
2016-02-27T12:25:48.063+0330 W - [conn4] DBException thrown :: caused by :: 9001 socket exception [CLOSED] for 127.0.0.1:47521
2016-02-27T12:25:48.070+0330 I - [conn4]
0xc2e0e2 0xc2e023 0xbb7177 0xbe339f 0xbe412b 0xbe4141 0xbe419d 0xbd8781 0xbdaeff 0x7fb6e4d2f182 0x7fb6e4a5c47d
----- BEGIN BACKTRACE -----
{"backtrace":[

{"b":"400000","o":"82E0E2","s":"_ZN5mongo15printStackTraceERSo"}

,

{"b":"400000","o":"82E023","s":"_ZN5mongo15printStackTraceEv"}

,

{"b":"400000","o":"7B7177","s":"_ZN5mongo11DBException13traceIfNeededERKS0_"}

,

{"b":"400000","o":"7E339F","s":"_ZN5mongo6Socket15handleRecvErrorEii"}

,

{"b":"400000","o":"7E412B","s":"_ZN5mongo6Socket5_recvEPci"}

,

{"b":"400000","o":"7E4141","s":"_ZN5mongo6Socket11unsafe_recvEPci"}

,

{"b":"400000","o":"7E419D","s":"_ZN5mongo6Socket4recvEPci"}

,

{"b":"400000","o":"7D8781","s":"_ZN5mongo13MessagingPort4recvERNS_7MessageE"}

,

{"b":"400000","o":"7DAEFF","s":"_ZN5mongo17PortMessageServer17handleIncomingMsgEPv"}

,

{"b":"7FB6E4D27000","o":"8182"}

,

{"b":"7FB6E4962000","o":"FA47D","s":"clone"}

],"processInfo":{ "mongodbVersion" : "3.2.3", "gitVersion" : "b326ba837cf6f49d65c2f85e1b70f6f31ece7937", "compiledModules" : [], "uname" :

{ "sysname" : "Linux", "release" : "3.19.0-25-generic", "version" : "#26~14.04.1-Ubuntu SMP Fri Jul 24 21:16:20 UTC 2015", "machine" : "x86_64" }

, "somap" : [

{ "elfType" : 2, "b" : "400000", "buildId" : "F3CD9A4A42D67CAB44ECCD39D8D1CF8BF49EC0DE" }

,

{ "b" : "7FFF5777F000", "elfType" : 3, "buildId" : "01005E92EA3C0C1527396B65C7412468298D0813" }

,

{ "b" : "7FB6E5F4C000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "A20EFFEC993A8441FA17F2079F923CBD04079E19" }

,

{ "b" : "7FB6E5B71000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "F000D29917E9B6E94A35A8F02E5C62846E5916BC" }

,

{ "b" : "7FB6E5969000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "92FCF41EFE012D6186E31A59AD05BDBB487769AB" }

,

{ "b" : "7FB6E5765000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "C1AE4CB7195D337A77A3C689051DABAA3980CA0C" }

,

{ "b" : "7FB6E5461000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3, "buildId" : "4BF6F7ADD8244AD86008E6BF40D90F8873892197" }

,

{ "b" : "7FB6E515B000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "1D76B71E905CB867B27CEF230FCB20F01A3178F5" }

,

{ "b" : "7FB6E4F45000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "8D0AA71411580EE6C08809695C3984769F25725B" }

,

{ "b" : "7FB6E4D27000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "9318E8AF0BFBE444731BB0461202EF57F7C39542" }

,

{ "b" : "7FB6E4962000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "30C94DC66A1FE95180C3D68D2B89E576D5AE213C" }

,

{ "b" : "7FB6E61AB000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9F00581AB3C73E3AEA35995A0C50D24D59A01D47" }

] }}
mongos(_ZN5mongo15printStackTraceERSo+0x32) [0xc2e0e2]
mongos(_ZN5mongo15printStackTraceEv+0x63) [0xc2e023]
mongos(ZN5mongo11DBException13traceIfNeededERKS0+0x117) [0xbb7177]
mongos(_ZN5mongo6Socket15handleRecvErrorEii+0xA0F) [0xbe339f]
mongos(_ZN5mongo6Socket5_recvEPci+0x6B) [0xbe412b]
mongos(_ZN5mongo6Socket11unsafe_recvEPci+0x11) [0xbe4141]
mongos(_ZN5mongo6Socket4recvEPci+0x3D) [0xbe419d]
mongos(_ZN5mongo13MessagingPort4recvERNS_7MessageE+0x51) [0xbd8781]
mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x24F) [0xbdaeff]
libpthread.so.0(+0x8182) [0x7fb6e4d2f182]
libc.so.6(clone+0x6D) [0x7fb6e4a5c47d]
----- END BACKTRACE -----
2016-02-27T12:25:48.070+0330 D NETWORK [conn4] SocketException: remote: 127.0.0.1:47521 error: 9001 socket exception [CLOSED] server [127.0.0.1:47521]

other:
2016-02-27T12:27:36.738+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Operation 241 timed out.
2016-02-27T12:27:36.738+0330 D ASIO [NetworkInterfaceASIO-ShardRegistry-0] Failed to execute command: RemoteCommand 241 – target:bnd-db01:37017 db:config expDate:2016-02-27T12:27:36.737+0330 cmd:{ find: "shards", readConcern: { level: "majority", afterOpTime:

{ ts: Timestamp 1456495056000|1, t: 14 }

}, maxTimeMS: 30000 } reason: ExceededTimeLimit: Operation timed out
2016-02-27T12:27:36.738+0330 D EXECUTOR [NetworkInterfaceASIO-ShardRegistry-0] Received remote response: ExceededTimeLimit: Operation timed out
2016-02-27T12:27:36.738+0330 D - [Balancer] User Assertion: 50:could not get updated shard list from config server due to ExceededTimeLimit: Operation timed out
2016-02-27T12:27:36.738+0330 W - [Balancer] DBException thrown :: caused by :: 50 could not get updated shard list from config server due to ExceededTimeLimit: Operation timed out
2016-02-27T12:27:36.743+0330 I - [Balancer]
0xc2e0e2 0xc2e023 0xbb7177 0x68a786 0xbb73bc 0xbb745c 0xaf3630 0xa2b406 0xbbb7d0 0x7fb6e5512a40 0x7fb6e4d2f182 0x7fb6e4a5c47d

And configsvr status:
iran_cfg:PRIMARY> rs.status()
{
"set" : "iran_cfg",
"date" : ISODate("2016-02-27T09:40:05.489Z"),
"myState" : 1,
"term" : NumberLong(1),
"configsvr" : true,
"heartbeatIntervalMillis" : NumberLong(2000),
"members" : [
{
"_id" : 0,
"name" : "thr-cfg01:37017",
"health" : 1,
"state" : 1,
"stateStr" : "PRIMARY",
"uptime" : 63710,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"electionTime" : Timestamp(1456506350, 1),
"electionDate" : ISODate("2016-02-26T17:05:50Z"),
"configVersion" : 1,
"self" : true
},
{
"_id" : 1,
"name" : "thr-cfg02:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 59666,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:03.901Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:05.322Z"),
"pingMs" : NumberLong(0),
"syncingTo" : "thr-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 2,
"name" : "thr-cfg04:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 59666,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:03.726Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.945Z"),
"pingMs" : NumberLong(0),
"syncingTo" : "thr-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 3,
"name" : "thr-cfg03:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 59666,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:03.571Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.996Z"),
"pingMs" : NumberLong(0),
"syncingTo" : "thr-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 4,
"name" : "ifn-cfg01:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 47473,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:04.249Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.620Z"),
"pingMs" : NumberLong(10),
"syncingTo" : "thr-cfg04:37017",
"configVersion" : 1
},
{
"_id" : 5,
"name" : "ifn-cfg02:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 47474,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:03.568Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.560Z"),
"pingMs" : NumberLong(10),
"syncingTo" : "thr-cfg03:37017",
"configVersion" : 1
},
{
"_id" : 6,
"name" : "ifn-cfg03:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 47473,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:04.745Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.764Z"),
"pingMs" : NumberLong(12),
"syncingTo" : "thr-cfg04:37017",
"configVersion" : 1
},
{
"_id" : 7,
"name" : "ifn-cfg04:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 47473,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:04.654Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.615Z"),
"pingMs" : NumberLong(10),
"syncingTo" : "thr-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 8,
"name" : "mhd-cfg01:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 46676,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:05.474Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.352Z"),
"pingMs" : NumberLong(170),
"syncingTo" : "thr-cfg02:37017",
"configVersion" : 1
},
{
"_id" : 9,
"name" : "mhd-cfg02:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 46676,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:05.303Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:03.374Z"),
"pingMs" : NumberLong(177),
"syncingTo" : "mhd-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 10,
"name" : "mhd-cfg03:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 46676,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:04.793Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:04.692Z"),
"pingMs" : NumberLong(175),
"syncingTo" : "mhd-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 11,
"name" : "mhd-cfg04:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 46676,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:05.427Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:05.089Z"),
"pingMs" : NumberLong(180),
"syncingTo" : "mhd-cfg01:37017",
"configVersion" : 1
},
{
"_id" : 12,
"name" : "bnd-db01:37017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 3477,
"optime" :

{ "ts" : Timestamp(1456566002, 1), "t" : NumberLong(1) }

,
"optimeDate" : ISODate("2016-02-27T09:40:02Z"),
"lastHeartbeat" : ISODate("2016-02-27T09:40:05.062Z"),
"lastHeartbeatRecv" : ISODate("2016-02-27T09:40:05.111Z"),
"pingMs" : NumberLong(75),
"syncingTo" : "ifn-cfg01:37017",
"configVersion" : 1
}
],
"ok" : 1
}

and configsvr conf:
{
"_id" : "iran_cfg",
"version" : 1,
"configsvr" : true,
"protocolVersion" : NumberLong(1),
"members" : [
{
"_id" : 0,
"host" : "thr-cfg01:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 5,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 1,
"host" : "thr-cfg02:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 4,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 2,
"host" : "thr-cfg04:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 3,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 3,
"host" : "thr-cfg03:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 4,
"host" : "ifn-cfg01:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 1,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 5,
"host" : "ifn-cfg02:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 6,
"host" : "ifn-cfg03:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 7,
"host" : "ifn-cfg04:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 8,
"host" : "mhd-cfg01:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 2,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 9,
"host" : "mhd-cfg02:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 10,
"host" : "mhd-cfg03:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 11,
"host" : "mhd-cfg04:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
},
{
"_id" : 12,
"host" : "bnd-db01:37017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 0,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 0
}
],
"settings" : {
"chainingAllowed" : true,
"heartbeatIntervalMillis" : 2000,
"heartbeatTimeoutSecs" : 10,
"electionTimeoutMillis" : 10000,
"getLastErrorModes" : {

},
"getLastErrorDefaults" :

{ "w" : 1, "wtimeout" : 0 }

}
}

Sorry for long log.

Comment by Githook User [ 24/Feb/16 ]

Author:

{u'name': u'Esha Maharishi', u'email': u'esha.maharishi@mongodb.come'}

Message: SERVER-22427 add logging for 'Operation timed out' errors
Branch: master
https://github.com/mongodb/mongo/commit/241bcd889e3b5923e96844eebd380f044737a5ff

Generated at Thu Feb 08 04:00:23 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.