[SERVER-21400] Insert takes 90 seconds when first config server (SCCC) is in TCP blackhole from mongos triggering autosplit Created: 10/Nov/15  Updated: 20/Nov/15  Resolved: 20/Nov/15

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.2.0-rc2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Max Hirschhorn Assignee: Unassigned
Resolution: Won't Fix Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File autosplit_during_config_server_blackhole.js     Text File test_output.log    
Issue Links:
Duplicate
duplicates SERVER-21293 Loading config data when CSRS member ... Closed
Operating System: ALL
Steps To Reproduce:

python buildscripts/resmoke.py --executor sharding_legacy autosplit_during_config_server_blackhole.js

Sprint: Sharding C (11/20/15), Sharding D (12/11/15)
Participants:

 Description   

Tests the scenario when the first config server discards all messages from the mongos, but not the shards. Note that this doesn't prevent the autosplit from succeeding. When the following sequence of events happen, mongos will try and send 3 messages to the first config server, each of which trigger a socket timeout after 30 seconds:

  1. Initialize the sharded cluster
  2. Enable sharding on the "test" database
  3. Create a sharded collection called "server16690" with shard key {_id: 1}
  4. Configure the mongobridge corresponding to the first config server to discard messages from the mongos
  5. Configure the mongobridges corresponding to the other config servers to delay messages from the mongos
  6. Insert a few documents into the test.server16690 collection to trigger an autosplit

[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.743-0500 Starting write operations on the sharded collection
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.746-0500 Write operation 1 of 10 took 2 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.748-0500 Write operation 2 of 10 took 2 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.750-0500 Write operation 3 of 10 took 2 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.753-0500 Write operation 4 of 10 took 2 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.050-0500 Write operation 5 of 10 took 90336 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.051-0500 Write operation 6 of 10 took 1 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.052-0500 Write operation 7 of 10 took 1 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.053-0500 Write operation 8 of 10 took 0 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.053-0500 Write operation 9 of 10 took 1 milliseconds
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.054-0500 Write operation 10 of 10 took 1 milliseconds

[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.821-0500 b20015| 2015-11-10T14:48:22.701-0500 I BRIDGE   [thread2] Received "discardMessagesFrom" command with arguments { discardMessagesFrom: 1.0, $forBridge: true, host: "hanamizu:20020", loss: 1.0 } from <unknown>
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.835-0500 s20020| 2015-11-10T14:48:22.715-0500 D SHARDING [conn2] about to initiate autosplit: ns: test.server16690, shard: shard0000, lastmod: 1|0||56424a065de2814f99135918, min: { _id: MinKey }, max: { _id: MaxKey } dataWritten: 229 splitThreshold: 921
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.766-0500 b20011| 2015-11-10T14:48:22.716-0500 I BRIDGE   [thread6] Received "splitChunk" command with arguments { splitChunk: "test.server16690", keyPattern: { _id: 1.0 }, min: { _id: MinKey }, max: { _id: MaxKey }, from: "shard0000", splitKeys: [ { _id: ObjectId('56424a0680361f45a8fe3e74') }, { _id: ObjectId('56424a0680361f45a8fe3e78') } ], configdb: "hanamizu:20015,hanamizu:20017,hanamizu:20019", shardVersion: [ Timestamp 1000|0, ObjectId('56424a065de2814f99135918') ], epoch: ObjectId('56424a065de2814f99135918') } from hanamizu:20020
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.836-0500 b20015| 2015-11-10T14:48:22.749-0500 I BRIDGE   [thread5] Received "ns" command with arguments { ns: "test.server16690" } from hanamizu:20020
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:22.836-0500 b20015| 2015-11-10T14:48:22.749-0500 I BRIDGE   [thread5] Discarding "ns" command with arguments { ns: "test.server16690" } from hanamizu:20020
...
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.749-0500 s20020| 2015-11-10T14:48:52.748-0500 I NETWORK  [conn2] Socket recv() timeout  127.0.1.1:20015
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.749-0500 s20020| 2015-11-10T14:48:52.749-0500 I NETWORK  [conn2] SocketException: remote: 127.0.1.1:20015 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:20015]
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.749-0500 s20020| 2015-11-10T14:48:52.749-0500 I NETWORK  [conn2] DBClientCursor::init call() failed
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.750-0500 s20020| 2015-11-10T14:48:52.749-0500 I NETWORK  [conn2] query on config.chunks: { query: { ns: "test.server16690" }, orderby: { lastmod: -1 } } failed to: hanamizu:20015 (127.0.1.1) failed no data
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.851-0500 s20020| 2015-11-10T14:48:52.851-0500 I NETWORK  [conn2] trying reconnect to hanamizu:20015 (127.0.1.1) failed
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.852-0500 s20020| 2015-11-10T14:48:52.851-0500 D NETWORK  [conn2] connected to server hanamizu:20015 (127.0.1.1)
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.853-0500 b20015| 2015-11-10T14:48:52.852-0500 I BRIDGE   [thread19] Received "isMaster" command with arguments { isMaster: 1, hostInfo: "hanamizu:20020" } from hanamizu:20020
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:48:52.853-0500 b20015| 2015-11-10T14:48:52.852-0500 I BRIDGE   [thread19] Discarding "isMaster" command with arguments { isMaster: 1, hostInfo: "hanamizu:20020" } from hanamizu:20020
...
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.849-0500 s20020| 2015-11-10T14:49:22.848-0500 I NETWORK  [conn2] Socket recv() timeout  127.0.1.1:20015
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.849-0500 s20020| 2015-11-10T14:49:22.848-0500 I NETWORK  [conn2] SocketException: remote: 127.0.1.1:20015 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:20015]
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.849-0500 s20020| 2015-11-10T14:49:22.849-0500 D -        [conn2] User Assertion: 6:network error while attempting to run command 'isMaster' on host 'hanamizu:20015'
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.850-0500 s20020| 2015-11-10T14:49:22.849-0500 I NETWORK  [conn2] reconnect hanamizu:20015 (127.0.1.1) failed failed
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.850-0500 s20020| 2015-11-10T14:49:22.849-0500 I NETWORK  [conn2] query on config.chunks: { query: { ns: "test.server16690", lastmod: { $gte: Timestamp 1000|0 } }, orderby: { lastmod: 1 } } failed to: hanamizu:20015 (127.0.1.1) failed exception: socket exception [CONNECT_ERROR] for network error while attempting to run command 'isMaster' on host 'hanamizu:20015'
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.951-0500 s20020| 2015-11-10T14:49:22.950-0500 I SHARDING [conn2] ChunkManager: time to load chunks for test.server16690: 30100ms sequenceNumber: 4 version: 1|3||56424a065de2814f99135918 based on: 1|0||56424a065de2814f99135918
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.952-0500 s20020| 2015-11-10T14:49:22.951-0500 I NETWORK  [conn2] trying reconnect to hanamizu:20015 (127.0.1.1) failed
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.953-0500 s20020| 2015-11-10T14:49:22.952-0500 D NETWORK  [conn2] connected to server hanamizu:20015 (127.0.1.1)
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.953-0500 b20015| 2015-11-10T14:49:22.952-0500 I BRIDGE   [thread21] Received "isMaster" command with arguments { isMaster: 1, hostInfo: "hanamizu:20020" } from hanamizu:20020
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:22.954-0500 b20015| 2015-11-10T14:49:22.952-0500 I BRIDGE   [thread21] Discarding "isMaster" command with arguments { isMaster: 1, hostInfo: "hanamizu:20020" } from hanamizu:20020
...
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:52.949-0500 s20020| 2015-11-10T14:49:52.948-0500 I NETWORK  [conn2] Socket recv() timeout  127.0.1.1:20015
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:52.949-0500 s20020| 2015-11-10T14:49:52.948-0500 I NETWORK  [conn2] SocketException: remote: 127.0.1.1:20015 error: 9001 socket exception [RECV_TIMEOUT] server [127.0.1.1:20015]
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:52.949-0500 s20020| 2015-11-10T14:49:52.948-0500 D -        [conn2] User Assertion: 6:network error while attempting to run command 'isMaster' on host 'hanamizu:20015'
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:52.949-0500 s20020| 2015-11-10T14:49:52.948-0500 I NETWORK  [conn2] reconnect hanamizu:20015 (127.0.1.1) failed failed
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:52.949-0500 s20020| 2015-11-10T14:49:52.948-0500 I NETWORK  [conn2] query on config.settings: { _id: "balancer" } failed to: hanamizu:20015 (127.0.1.1) failed exception: socket exception [CONNECT_ERROR] for network error while attempting to run command 'isMaster' on host 'hanamizu:20015'
[js_test:autosplit_during_config_server_blackhole] 2015-11-10T14:49:53.050-0500 s20020| 2015-11-10T14:49:53.049-0500 I SHARDING [conn2] autosplitted test.server16690 shard: ns: test.server16690, shard: shard0000, lastmod: 1|0||56424a065de2814f99135918, min: { _id: MinKey }, max: { _id: MaxKey } into 3 (splitThreshold 921) (migrate suggested, but no migrations allowed)



 Comments   
Comment by Max Hirschhorn [ 20/Nov/15 ]

Per discussion with Andy, closing this ticket as "Won't Fix". This issue only occurs when the config server appears as a TCP blackhole to the mongos (but not the shards) and the amount of time the insert tasks is bounded.

Behavior when running with CSRS

2015-11-20T10:16:18.558-0500 Write operation 1 of 10 took 3 milliseconds
2015-11-20T10:16:18.559-0500 Write operation 2 of 10 took 4 milliseconds
2015-11-20T10:16:18.560-0500 Write operation 3 of 10 took 4 milliseconds
2015-11-20T10:16:18.561-0500 Write operation 4 of 10 took 3 milliseconds
2015-11-20T10:16:48.583-0500 Write operation 5 of 10 took 30026 milliseconds
2015-11-20T10:16:48.602-0500 Write operation 6 of 10 took 15 milliseconds
2015-11-20T10:16:48.605-0500 Write operation 7 of 10 took 6 milliseconds
2015-11-20T10:16:48.619-0500 Write operation 8 of 10 took 13 milliseconds
2015-11-20T10:16:48.621-0500 Write operation 9 of 10 took 4 milliseconds
2015-11-20T10:16:48.633-0500 Write operation 10 of 10 took 11 milliseconds

Behavior when running with SCCC

2015-11-20T10:23:09.144-0500 Write operation 1 of 10 took 2 milliseconds
2015-11-20T10:23:09.145-0500 Write operation 2 of 10 took 2 milliseconds
2015-11-20T10:23:09.148-0500 Write operation 3 of 10 took 3 milliseconds
2015-11-20T10:23:09.151-0500 Write operation 4 of 10 took 3 milliseconds
2015-11-20T10:24:39.215-0500 Write operation 5 of 10 took 90063 milliseconds
2015-11-20T10:24:39.218-0500 Write operation 6 of 10 took 4 milliseconds
2015-11-20T10:24:39.221-0500 Write operation 7 of 10 took 2 milliseconds
2015-11-20T10:24:39.223-0500 Write operation 8 of 10 took 2 milliseconds
2015-11-20T10:24:39.227-0500 Write operation 9 of 10 took 3 milliseconds
2015-11-20T10:24:39.230-0500 Write operation 10 of 10 took 2 milliseconds


git version: 0730c6551c12450884228e383da12a923a396e3e

Comment by Max Hirschhorn [ 18/Nov/15 ]

Reopening this ticket.

This issue of autosplit taking 90 seconds when first config server is in TCP blackhole affects SCCC and not CSRS. Based on a discussion with renctan, the mongos taking 90 seconds to respond back to the client seemed like a long enough time to warrant filing this ticket. If we aren't intending to change the behavior, then I'd propose doing one or both of the following:

  1. Closing this ticket as "works as designed"
  2. Adding a test case that uses mongobridge to make the first config server appear as to blackhole to mongos and ensuring that CSRS behaves better than SCCC in this scenario.
Comment by Andy Schwerin [ 16/Nov/15 ]

Assigning to kaloian.manassiev to see if this falls out of work he's already doing.

Comment by Max Hirschhorn [ 10/Nov/15 ]

When a message is "discarded", the mongobridge process reads the message from the socket (sending a TCP acknowledgement), but does not reply with a message on the socket (nor does it forward the message onto the destination). This causes a socket timeout to be triggered on the process that sent the message. This issue only seems to manifest when the first config server is in a TCP blackhole; when a config server other than the first one is blackholed from the mongos, the write operation that triggers the autosplit is on the order of milliseconds and not seconds.

Additionally, the test appears to run indefinitely (>10 minutes) when running with CSRS. The mongos retries connecting to the first config server in the replica set continuously. It seems likely that it is due to the same or a similar issue as SERVER-21293. To reproduce, run python buildscripts/resmoke.py --executor sharding autosplit_during_config_server_blackhole.js.

Generated at Thu Feb 08 03:57:15 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.