Loading...

XML

Word

Printable

JSON

Type: Improvement
Resolution: Fixed
Priority: Major - P3
Fix Version/s: 2.13.0.beta1
Affects Version/s: None
Component/s: Tests
Labels:
- no-changelog

Backwards Compatibility:
Fully Compatible

We have a recurring failure in Evergreen that looks like this:

[2020-04-22 02:34:08.243] + echo Preparing the test suite
[2020-04-22 02:34:08.243] + bundle exec rake spec:prepare
[2020-04-22 02:34:08.500] [mongo] Warning: No private key present, creating unsigned gem.
[2020-04-22 02:34:12.574] rake aborted!
[2020-04-22 02:34:12.574] Mongo::Error::SocketTimeoutError: Errno::ETIMEDOUT: Connection timed out - Took more than 3 seconds to receive data (for 127.0.0.1:27017 (no TLS)) (on localhost:27017)
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:340:in `rescue in map_exceptions'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:336:in `map_exceptions'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:129:in `read'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/protocol/message.rb:205:in `deserialize'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:155:in `block (2 levels) in deliver'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_common.rb:66:in `add_server_diagnostics'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:152:in `block in deliver'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connectable.rb:83:in `ensure_connected'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:145:in `deliver'
[2020-04-22 02:34:12.574] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection.rb:416:in `deliver'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:135:in `dispatch'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:58:in `block in dispatch_message'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_pool.rb:577:in `with_connection'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server.rb:424:in `with_connection'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:55:in `dispatch_message'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:50:in `get_result'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:29:in `block (3 levels) in do_execute'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:87:in `add_server_diagnostics'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:28:in `block (2 levels) in do_execute'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:43:in `add_error_labels'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:27:in `block in do_execute'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:73:in `unpin_maybe'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:26:in `do_execute'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:38:in `execute'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/op_msg_or_command.rb:27:in `execute'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/auth/user/view.rb:53:in `block in create'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/client.rb:966:in `with_session'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/auth/user/view.rb:47:in `create'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/spec/support/spec_setup.rb:48:in `create_user'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/spec/support/spec_setup.rb:15:in `run'
[2020-04-22 02:34:12.575] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/Rakefile:34:in `block (2 levels) in <top (required)>'
[2020/04/22 02:34:12.576] [egos:E 2020-04-22T02:34:12.576000]
[2020-04-22 02:34:12.576] Caused by:
[2020-04-22 02:34:12.576] Errno::ETIMEDOUT: Connection timed out - Took more than 3 seconds to receive data
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:282:in `rescue in read_from_socket'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:240:in `read_from_socket'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:130:in `block in read'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:338:in `map_exceptions'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:129:in `read'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/protocol/message.rb:205:in `deserialize'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:155:in `block (2 levels) in deliver'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_common.rb:66:in `add_server_diagnostics'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:152:in `block in deliver'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connectable.rb:83:in `ensure_connected'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:145:in `deliver'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection.rb:416:in `deliver'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:135:in `dispatch'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:58:in `block in dispatch_message'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_pool.rb:577:in `with_connection'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server.rb:424:in `with_connection'
[2020-04-22 02:34:12.576] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:55:in `dispatch_message'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:50:in `get_result'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:29:in `block (3 levels) in do_execute'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:87:in `add_server_diagnostics'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:28:in `block (2 levels) in do_execute'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:43:in `add_error_labels'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:27:in `block in do_execute'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:73:in `unpin_maybe'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:26:in `do_execute'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:38:in `execute'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/op_msg_or_command.rb:27:in `execute'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/auth/user/view.rb:53:in `block in create'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/client.rb:966:in `with_session'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/auth/user/view.rb:47:in `create'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/spec/support/spec_setup.rb:48:in `create_user'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/spec/support/spec_setup.rb:15:in `run'
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/Rakefile:34:in `block (2 levels) in <top (required)>'
[2020/04/22 02:34:12.578] [egos:E 2020-04-22T02:34:12.577849]
[2020-04-22 02:34:12.577] Caused by:
[2020-04-22 02:34:12.577] IO::EAGAINWaitReadable: Resource temporarily unavailable - read would block
[2020-04-22 02:34:12.577] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:246:in `read_from_socket'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:130:in `block in read'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:338:in `map_exceptions'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/socket.rb:129:in `read'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/protocol/message.rb:205:in `deserialize'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:155:in `block (2 levels) in deliver'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_common.rb:66:in `add_server_diagnostics'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:152:in `block in deliver'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connectable.rb:83:in `ensure_connected'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:145:in `deliver'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection.rb:416:in `deliver'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_base.rb:135:in `dispatch'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:58:in `block in dispatch_message'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server/connection_pool.rb:577:in `with_connection'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/server.rb:424:in `with_connection'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:55:in `dispatch_message'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:50:in `get_result'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:29:in `block (3 levels) in do_execute'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:87:in `add_server_diagnostics'
[2020-04-22 02:34:12.578] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:28:in `block (2 levels) in do_execute'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:43:in `add_error_labels'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:27:in `block in do_execute'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/response_handling.rb:73:in `unpin_maybe'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:26:in `do_execute'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/executable.rb:38:in `execute'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/operation/shared/op_msg_or_command.rb:27:in `execute'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/auth/user/view.rb:53:in `block in create'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/client.rb:966:in `with_session'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/lib/mongo/auth/user/view.rb:47:in `create'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/spec/support/spec_setup.rb:48:in `create_user'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/spec/support/spec_setup.rb:15:in `run'
[2020-04-22 02:34:12.579] /data/mci/06022b2124e1a6fe436675a2e2be4d55/src/Rakefile:34:in `block (2 levels) in <top (required)>'
[2020-04-22 02:34:12.579] Tasks: TOP => spec:prepare
[2020-04-22 02:34:12.579] (See full trace by running task with --trace)
[2020-04-22 02:34:12.581] D, [2020-04-22T02:34:09.565675 #23998] DEBUG -- : MONGODB | EVENT: #<TopologyOpening topology=Unknown[]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.565729 #23998] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.565894 #23998] DEBUG -- : MONGODB | EVENT: #<TopologyChanged prev=Unknown[] new=Unknown[localhost:27017]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.565921 #23998] DEBUG -- : MONGODB | Topology type 'Unknown' changed to type 'Unknown'.
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.566059 #23998] DEBUG -- : MONGODB | EVENT: #<ServerOpening address=localhost:27017 topology=Unknown[localhost:27017]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.566083 #23998] DEBUG -- : MONGODB | Server localhost:27017 initializing.
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.566196 #23998] DEBUG -- : MONGODB | Waiting for up to 5.00 seconds for servers to be scanned: #<Cluster topology=Unknown[localhost:27017] servers=[#<Server address=localhost:27017 UNKNOWN>]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.567616 #23998] DEBUG -- : MONGODB | EVENT: #<ServerDescriptionChanged address=localhost:27017 topology=Single[localhost:27017] prev=#<Mongo::Server:Description:0x5360 config={} average_round_trip_time=> new=#<Mongo::Server:Description:0x5340 config={"ismaster"=>true, "maxBsonObjectSize"=>16777216, "maxMessageSizeBytes"=>48000000, "maxWriteBatchSize"=>100000, "localTime"=>2020-04-22 02:34:09.567 UTC, "logicalSessionTimeoutMinutes"=>30, "connectionId"=>5, "minWireVersion"=>0, "maxWireVersion"=>8, "readOnly"=>false, "ok"=>1.0} average_round_trip_time=0.00111481>>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.567658 #23998] DEBUG -- : MONGODB | Server description for localhost:27017 changed from 'unknown' to 'standalone'.
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.567779 #23998] DEBUG -- : MONGODB | EVENT: #<TopologyChanged prev=Unknown[localhost:27017] new=Single[localhost:27017]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.567804 #23998] DEBUG -- : MONGODB | Topology type 'Unknown' changed to type 'Single'.
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.568231 #23998] DEBUG -- : MONGODB | EVENT: #<ServerClosed address=localhost:27017 topology=Single[localhost:27017]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.568256 #23998] DEBUG -- : MONGODB | Server localhost:27017 connection closed.
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.568283 #23998] DEBUG -- : MONGODB | EVENT: #<TopologyClosed topology=Single[localhost:27017]>
[2020-04-22 02:34:12.582] D, [2020-04-22T02:34:09.568302 #23998] DEBUG -- : MONGODB | Topology type 'single' closed.
[2020-04-22 02:34:12.583] D, [2020-04-22T02:34:09.568631 #23998] DEBUG -- : MONGODB | Waiting for up to 30.00 seconds for servers to be scanned: #<Cluster topology=Single[localhost:27017] servers=[#<Server address=localhost:27017 UNKNOWN>]>
[2020/04/22 02:34:12.589] Command failed: command encountered problem: error waiting on process 'cdc19dee-75df-4db9-8ad3-d0917f7a6828': exit status 1
[2020/04/22 02:34:12.590] Task completed - FAILURE.

It appears that the client is successful in selecting a server but timed out the user creation read.

On the server side I see:

2020-04-22T02:33:46.960+0000 I  NETWORK  [listener] Listening on /tmp/mongodb-27017.sock
2020-04-22T02:33:46.960+0000 I  NETWORK  [listener] Listening on 127.0.0.1
2020-04-22T02:33:46.960+0000 I  NETWORK  [listener] waiting for connections on port 27017
2020-04-22T02:33:46.960+0000 I  CONTROL  [LogicalSessionCacheReap] Sessions collection is not set up; waiting until next sessions reap interval: config.system.sessions does not exist
2020-04-22T02:33:46.960+0000 I  STORAGE  [LogicalSessionCacheRefresh] createCollection: config.system.sessions with provided UUID: c0157f0f-2b3c-456e-83e6-35f2835f622b and options: { uuid: UUID("c0157f0f-2b3c-456e-83e6-35f2835f622b") }
2020-04-22T02:33:46.963+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60516 #1 (1 connection now open)
2020-04-22T02:33:46.963+0000 I  NETWORK  [conn1] received client metadata from 127.0.0.1:60516 conn1: { driver: { name: "PyMongo", version: "3.6.1" }, os: { type: "Linux", name: "Red Hat Enterprise Linux Server 7.0 Maipo", architecture: "x86_64", version: "3.10.0-327.22.2.el7.x86_64" }, platform: "CPython 2.7.5.final.0", application: { name: "mlaunch v1.5.5" } }
2020-04-22T02:33:46.964+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60518 #2 (2 connections now open)
2020-04-22T02:33:46.964+0000 I  NETWORK  [conn2] received client metadata from 127.0.0.1:60518 conn2: { driver: { name: "PyMongo", version: "3.6.1" }, os: { type: "Linux", name: "Red Hat Enterprise Linux Server 7.0 Maipo", architecture: "x86_64", version: "3.10.0-327.22.2.el7.x86_64" }, platform: "CPython 2.7.5.final.0", application: { name: "mlaunch v1.5.5" } }
2020-04-22T02:33:46.965+0000 I  NETWORK  [conn2] end connection 127.0.0.1:60518 (1 connection now open)
2020-04-22T02:33:46.966+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60520 #3 (2 connections now open)
2020-04-22T02:33:46.966+0000 I  NETWORK  [conn3] received client metadata from 127.0.0.1:60520 conn3: { driver: { name: "PyMongo", version: "3.6.1" }, os: { type: "Linux", name: "Red Hat Enterprise Linux Server 7.0 Maipo", architecture: "x86_64", version: "3.10.0-327.22.2.el7.x86_64" }, platform: "CPython 2.7.5.final.0", application: { name: "mlaunch v1.5.5" } }
2020-04-22T02:33:46.966+0000 I  NETWORK  [conn1] end connection 127.0.0.1:60516 (1 connection now open)
2020-04-22T02:33:46.967+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60522 #4 (2 connections now open)
2020-04-22T02:33:46.967+0000 I  NETWORK  [conn4] received client metadata from 127.0.0.1:60522 conn4: { driver: { name: "PyMongo", version: "3.6.1" }, os: { type: "Linux", name: "Red Hat Enterprise Linux Server 7.0 Maipo", architecture: "x86_64", version: "3.10.0-327.22.2.el7.x86_64" }, platform: "CPython 2.7.5.final.0", application: { name: "mlaunch v1.5.5" } }
2020-04-22T02:33:46.968+0000 I  NETWORK  [conn4] end connection 127.0.0.1:60522 (1 connection now open)
2020-04-22T02:33:46.968+0000 I  NETWORK  [conn3] end connection 127.0.0.1:60520 (0 connections now open)
2020-04-22T02:33:46.971+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: done building index _id_ on ns config.system.sessions
2020-04-22T02:33:46.980+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: starting on config.system.sessions properties: { v: 2, key: { lastUse: 1 }, name: "lsidTTLIndex", ns: "config.system.sessions", expireAfterSeconds: 1800 } using method: Hybrid
2020-04-22T02:33:46.980+0000 I  INDEX    [LogicalSessionCacheRefresh] build may temporarily use up to 200 megabytes of RAM
2020-04-22T02:33:46.980+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: collection scan done. scanned 0 total records in 0 seconds
2020-04-22T02:33:46.980+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: inserted 0 keys from external sorter into index in 0 seconds
2020-04-22T02:33:46.982+0000 I  INDEX    [LogicalSessionCacheRefresh] index build: done building index lsidTTLIndex on ns config.system.sessions
2020-04-22T02:34:09.566+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60632 #5 (1 connection now open)
2020-04-22T02:34:09.567+0000 I  NETWORK  [conn5] received client metadata from 127.0.0.1:60632 conn5: { driver: { name: "mongo-ruby-driver", version: "2.12.0.rc0" }, os: { type: "linux", name: "linux-gnu", architecture: "x86_64" }, platform: "2.7.0, x86_64-linux, x86_64-pc-linux-gnu" }
2020-04-22T02:34:09.568+0000 I  NETWORK  [conn5] end connection 127.0.0.1:60632 (0 connections now open)
2020-04-22T02:34:09.568+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60634 #6 (1 connection now open)
2020-04-22T02:34:09.569+0000 I  NETWORK  [conn6] received client metadata from 127.0.0.1:60634 conn6: { driver: { name: "mongo-ruby-driver", version: "2.12.0.rc0" }, os: { type: "linux", name: "linux-gnu", architecture: "x86_64" }, platform: "2.7.0, x86_64-linux, x86_64-pc-linux-gnu" }
2020-04-22T02:34:09.569+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60636 #7 (2 connections now open)
2020-04-22T02:34:09.570+0000 I  NETWORK  [conn7] received client metadata from 127.0.0.1:60636 conn7: { driver: { name: "mongo-ruby-driver", version: "2.12.0.rc0" }, os: { type: "linux", name: "linux-gnu", architecture: "x86_64" }, platform: "2.7.0, x86_64-linux, x86_64-pc-linux-gnu" }
2020-04-22T02:34:09.611+0000 I  SHARDING [conn7] Marking collection admin.system.users as collection version: <unsharded>
2020-04-22T02:34:09.611+0000 I  STORAGE  [conn7] createCollection: admin.system.users with generated UUID: 643f8197-d6b4-4a71-b7c2-8d4e3f879f2a and options: {}
2020-04-22T02:34:12.576+0000 I  NETWORK  [conn6] end connection 127.0.0.1:60634 (1 connection now open)
2020-04-22T02:34:12.577+0000 I  NETWORK  [listener] connection accepted from 127.0.0.1:60638 #8 (2 connections now open)
2020-04-22T02:34:12.577+0000 I  NETWORK  [conn8] received client metadata from 127.0.0.1:60638 conn8: { driver: { name: "mongo-ruby-driver", version: "2.12.0.rc0" }, os: { type: "linux", name: "linux-gnu", architecture: "x86_64" }, platform: "2.7.0, x86_64-linux, x86_64-pc-linux-gnu" }
2020-04-22T02:34:12.580+0000 I  NETWORK  [conn8] end connection 127.0.0.1:60638 (1 connection now open)

Possible offender:

2020-04-22T02:34:09.611+0000 I  STORAGE  [conn7] createCollection: admin.system.users with generated UUID: 643f8197-d6b4-4a71-b7c2-8d4e3f879f2a and options: {}

Note that server was successful in creating other collections earlier but they were in local database, not admin.

As a first step maybe increasing the socket timeout to 10 seconds while running spec:prepare would do the trick. We already special case server selection timeout to 30 seconds for the setup request for largely similar reasons, to give the server more time to do whatever it is that it is doing during bootstrap.

links to

mongo-ruby-driver #1930: RUBY-2237 try increasing setup timeouts for fle and/or rhel

Assignee:: Oleg Pudeyev (Inactive)

Reporter:: Oleg Pudeyev (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Created:: Apr 22 2020 02:52:59 AM UTC

Updated:: Oct 28 2023 11:12:28 AM UTC

Resolved:: May 27 2020 06:59:05 PM UTC

Details

Description

Attachments

Issue Links

Activity

People

Dates