[SERVER-20151] write concern timeout in tags.js should not exceed max sync source lag secs Created: 29/Jun/15  Updated: 25/Jan/17  Resolved: 07/Oct/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: 3.1.9

Type: Bug Priority: Minor - P4
Reporter: Adam Midvidy Assignee: Benety Goh
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-15637 Remove assert.soon from ReplSetTest.p... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: RPL A (10/09/15)
Participants:
Linked BF Score: 0

 Description   

replsets/tags.js was using a timeout for the negative write concern test cases that results in the nodes disconnecting from their sync sources.

Here's a sequence of events:

[js_test:tags] 2015-09-30T01:39:37.184+0000 tags output: done bridging
[js_test:tags] 2015-09-30T01:39:37.184+0000 tags output: paritions: [0-1-2-0] [3] [4]
[js_test:tags] 2015-09-30T01:39:37.184+0000 tags output: test1
[js_test:tags] 2015-09-30T01:39:37.184+0000 tags output: 2 should be primary
[js_test:tags] 2015-09-30T01:39:37.204+0000 			"infoMessage" : "could not find member to sync from",
[js_test:tags] 2015-09-30T01:40:08.239+0000 tags output: partitions: [1-4] [0-1-2-0] [3]
[js_test:tags] 2015-09-30T01:40:08.239+0000 tags output: test2
[js_test:tags] 2015-09-30T01:40:09.197+0000 tags output: partitions: [1-4] [0-1-2-0] [3]
[js_test:tags] 2015-09-30T01:40:09.197+0000 tags output: test3
 
("test3" expects the write concern to block for the entire duration of the timeout (30 seconds) before returning with an error.)
 
[js_test:tags] 2015-09-30T01:40:40.210+0000 tags output: partitions: [0-4-3] [0-1-2-0]
[js_test:tags] 2015-09-30T01:40:40.211+0000 tags output: 31004 should sync from 31001 (31026)
[js_test:tags] 2015-09-30T01:40:40.211+0000 tags output: 31003 should sync from 31004 (31024)
[js_test:tags] 2015-09-30T01:40:40.211+0000 tags output: test4
 
("test4" expects all 5 nodes in the spanning tree to be writable)
 
[js_test:tags] 2015-09-30T01:40:40.223+0000 d20014| 2015-09-30T01:40:40.224+0000 I REPL     [ReplicationExecutor] changing sync target because current sync target's most recent OpTime is (term: -1, timestamp: Sep 30 01:40:09:2) which is more than 30s behind member WIN-MIAKGV0GBFF:20034 whose most recent OpTime is (term: -1, timestamp: Sep 30 01:40:40:1)
30T01:40:40.225+0000 I REPL     [ReplicationExecutor] could not find member to sync from

------

	
[js_test:tags] 2015-06-29T00:58:12.173-0400 assert.soon failed, msg:Finding master
[js_test:tags] 2015-06-29T00:58:12.179-0400 Error: assert.soon failed, msg:Finding master
[js_test:tags] 2015-06-29T00:58:12.179-0400     at Error (<anonymous>)
[js_test:tags] 2015-06-29T00:58:12.179-0400     at doassert (src/mongo/shell/assert.js:11:14)
[js_test:tags] 2015-06-29T00:58:12.179-0400     at Function.assert.soon (src/mongo/shell/assert.js:189:13)
[js_test:tags] 2015-06-29T00:58:12.179-0400     at ReplSetTest.getMaster (src/mongo/shell/replsettest.js:374:12)
[js_test:tags] 2015-06-29T00:58:12.179-0400     at ReplSetTest.bridge (src/mongo/shell/replsettest.js:1177:17)
[js_test:tags] 2015-06-29T00:58:12.179-0400     at jstests/replsets/tags.js:81:10
[js_test:tags] 2015-06-29T00:58:12.179-0400 ReplSetTest getMaster failed: Error: assert.soon failed, msg:Finding master
[js_test:tags] 2015-06-29T00:58:12.180-0400 Error: Printing Stack Trace
[js_test:tags] 2015-06-29T00:58:12.180-0400     at printStackTrace (src/mongo/shell/utils.js:49:15)
[js_test:tags] 2015-06-29T00:58:12.180-0400     at ReplSetTest.getMaster (src/mongo/shell/replsettest.js:381:5)
[js_test:tags] 2015-06-29T00:58:12.180-0400     at ReplSetTest.bridge (src/mongo/shell/replsettest.js:1177:17)
[js_test:tags] 2015-06-29T00:58:12.180-0400     at jstests/replsets/tags.js:81:10
[js_test:tags] 2015-06-29T00:58:12.180-0400 2015-06-29T00:58:12.180-0400 E QUERY    [main] Error: assert.soon failed, msg:Finding master
[js_test:tags] 2015-06-29T00:58:12.180-0400     at Error (<anonymous>)
[js_test:tags] 2015-06-29T00:58:12.180-0400     at doassert (src/mongo/shell/assert.js:11:14)
[js_test:tags] 2015-06-29T00:58:12.180-0400     at Function.assert.soon (src/mongo/shell/assert.js:189:13)
[js_test:tags] 2015-06-29T00:58:12.180-0400     at ReplSetTest.getMaster (src/mongo/shell/replsettest.js:374:12)
[js_test:tags] 2015-06-29T00:58:12.181-0400     at ReplSetTest.bridge (src/mongo/shell/replsettest.js:1177:17)
[js_test:tags] 2015-06-29T00:58:12.181-0400     at jstests/replsets/tags.js:81:10 at src/mongo/shell/replsettest.js:382
[js_test:tags] 2015-06-29T00:58:12.181-0400 failed to load: jstests/replsets/tags.js
[js_test:tags] 2015-06-29T00:58:12.181-0400  m31000| 2015-06-29T00:58:12.180-0400 I CONTROL  [signalProcessingThread] got signal 15 (Terminated: 15), will terminate after current cmd ends
[js_test:tags] 2015-06-29T00:58:12.181-0400  m31000| 2015-06-29T00:58:12.180-0400 I REPL     [signalProcessingThread] Stopping replication applier threads
[js_test:tags] 2015-06-29T00:58:12.225-0400  m31002| 2015-06-29T00:58:12.224-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-06-29T00:58:12.225-0400  m31000| 2015-06-29T00:58:12.225-0400 I STORAGE  [conn7] got request after shutdown()

Also some weird stuff in the logs like this log line:

[js_test:tags] 2015-06-29T00:58:13.945-0400  m31026| 2015-06-29T00:58:13.944-0400 I NETWORK  [main] select() failure: ret=-1 errno:9 Bad file descriptor

and some gibberish logged here

[js_test:tags] 2015-06-29T00:58:14.732-0400  m31019| eennededen en ndcndcd od o cn cnconcononeonenncnncnetneteciecictoctotintinio io ono2n2n n0 0  288220..00852588.202..5.1.55215122.9-9..1101119.6.9912-211.121..2696221:T:11650566:606::56:6556550665182441
[js_test:tags] 2015-06-29T00:58:14.733-0400  m31019| :

Which looks like it could be some sort of race printing the "ended connection to..." log message.

Task:
https://evergreen.mongodb.com/task/mongodb_mongo_master_osx_108_debug_replicasets_91c9eaeae7dbe3ff5e5e5b369871562beda908a8_15_06_29_01_52_44

Log:
https://logkeeper.mongodb.org/build/5590bd2bbe07c41a360a38f4/test/5590cf50be07c41a360af0c5



 Comments   
Comment by Githook User [ 07/Oct/15 ]

Author:

{u'username': u'benety', u'name': u'Benety Goh', u'email': u'benety@mongodb.com'}

Message: SERVER-20151 updated tags.js to use a timeout for the failing write operations that is shorter than the default maxSyncSourceLagSecs
Branch: master
https://github.com/mongodb/mongo/commit/35e0068ac2e41efd18cb6380aedd1f01b376103f

Comment by Githook User [ 07/Oct/15 ]

Author:

{u'username': u'benety', u'name': u'Benety Goh', u'email': u'benety@mongodb.com'}

Message: SERVER-20151 do not retry replSetInitiate in ReplSetTest.initiate
Branch: master
https://github.com/mongodb/mongo/commit/19a7e7dfa731fe3e9dd1e29519cacbe09fadfefa

Comment by Matt Dannenberg [ 31/Aug/15 ]

The patch was reverted because it broke some rollback tests, which is something we could adapt those tests to handle. However, tags.js manage to fail with the patch present, so this approach is not worth pursuing any further.

Comment by Githook User [ 27/Aug/15 ]

Author:

{u'username': u'benety', u'name': u'Benety Goh', u'email': u'benety@mongodb.com'}

Message: Revert "SERVER-20151 awaitReplication before restarting all the nodes when bridging a ReplSetTest"

This reverts commit b53ae44a850d011fb47596637c83d375b5751e55.
Branch: master
https://github.com/mongodb/mongo/commit/d64275b8da6825f3758fd2d7993eecb80d8d1e20

Comment by Githook User [ 26/Aug/15 ]

Author:

{u'username': u'dannenberg', u'name': u'matt dannenberg', u'email': u'matt.dannenberg@10gen.com'}

Message: SERVER-20151 awaitReplication before restarting all the nodes when bridging a ReplSetTest
Branch: master
https://github.com/mongodb/mongo/commit/b53ae44a850d011fb47596637c83d375b5751e55

Comment by Benety Goh [ 26/Aug/15 ]

9b054f0032 OS X 10.8 DEBUG replicasets

https://evergreen.mongodb.com/task/mongodb_mongo_master_osx_108_debug_replicasets_9b054f00326b23a87ba0571cbd8997b91fe5ce16_15_08_26_13_10_01/0

Comment by Benety Goh [ 26/Aug/15 ]

5d76623abc OS X 10.8 DEBUG replicasets_WT

https://evergreen.mongodb.com/task/mongodb_mongo_master_osx_108_debug_replicasets_WT_5d76623abc23f453c6530b1f8543476c5d65c4e9_15_08_26_04_49_10

https://logkeeper.mongodb.org/build/55dd4dd2be07c47abf9365ab/test/55dd63e2be07c47abf9383c4

	
[js_test:tags] 2015-08-26T03:04:56.619-0400  m31000| 2015-08-26T03:04:56.619-0400 W NETWORK  [ReplExecNetThread-11] Failed to connect to 208.52.191.216:31007, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.620-0400  m31000| 2015-08-26T03:04:56.619-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-26T03:04:56.620-0400  m31000| 2015-08-26T03:04:56.619-0400 W NETWORK  [ReplExecNetThread-6] Failed to connect to 208.52.191.216:31007, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.620-0400  m31000| 2015-08-26T03:04:56.619-0400 W NETWORK  [ReplExecNetThread-4] Failed to connect to 208.52.191.216:31008, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.621-0400  m31000| 2015-08-26T03:04:56.619-0400 I REPL     [ReplicationExecutor] Error in heartbeat request to mci-osx108-7.build.10gen.cc:31007; HostUnreachable couldn't connect to server mci-osx108-7.build.10gen.cc:31007, connection attempt failed
[js_test:tags] 2015-08-26T03:04:56.621-0400  m31000| 2015-08-26T03:04:56.620-0400 I REPL     [ReplicationExecutor] Error in heartbeat request to mci-osx108-7.build.10gen.cc:31008; HostUnreachable couldn't connect to server mci-osx108-7.build.10gen.cc:31008, connection attempt failed
[js_test:tags] 2015-08-26T03:04:56.622-0400  m31000| 2015-08-26T03:04:56.620-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-7.build.10gen.cc:31009 would veto with 'mci-osx108-7.build.10gen.cc:31025 has lower priority of 1 than mci-osx108-7.build.10gen.cc:31027 which has a priority of 2'
[js_test:tags] 2015-08-26T03:04:56.622-0400  m31000| 2015-08-26T03:04:56.620-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-26T03:04:56.622-0400  m31000| 2015-08-26T03:04:56.620-0400 W NETWORK  [ReplExecNetThread-2] Failed to connect to 208.52.191.216:31007, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.622-0400  m31000| 2015-08-26T03:04:56.620-0400 I REPL     [ReplicationExecutor] Error in heartbeat request to mci-osx108-7.build.10gen.cc:31007; HostUnreachable couldn't connect to server mci-osx108-7.build.10gen.cc:31007, connection attempt failed
[js_test:tags] 2015-08-26T03:04:56.623-0400  m31000| 2015-08-26T03:04:56.621-0400 W NETWORK  [ReplExecNetThread-1] Failed to connect to 208.52.191.216:31008, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.623-0400  m31000| 2015-08-26T03:04:56.621-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-26T03:04:56.623-0400  m31000| 2015-08-26T03:04:56.621-0400 I REPL     [ReplicationExecutor] Error in heartbeat request to mci-osx108-7.build.10gen.cc:31008; HostUnreachable couldn't connect to server mci-osx108-7.build.10gen.cc:31008, connection attempt failed
[js_test:tags] 2015-08-26T03:04:56.623-0400  m31000| 2015-08-26T03:04:56.621-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-7.build.10gen.cc:31006 would veto with 'mci-osx108-7.build.10gen.cc:31010 has lower priority of 1 than mci-osx108-7.build.10gen.cc:31012 which has a priority of 2'
[js_test:tags] 2015-08-26T03:04:56.624-0400  m31000| 2015-08-26T03:04:56.621-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-26T03:04:56.624-0400  m31000| 2015-08-26T03:04:56.621-0400 W NETWORK  [ReplExecNetThread-9] Failed to connect to 208.52.191.216:31007, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.624-0400  m31000| 2015-08-26T03:04:56.622-0400 W NETWORK  [ReplExecNetThread-7] Failed to connect to 208.52.191.216:31008, reason: errno:61 Connection refused
[js_test:tags] 2015-08-26T03:04:56.624-0400  m31000| 2015-08-26T03:04:56.622-0400 I REPL     [ReplicationExecutor] Error in heartbeat request to mci-osx108-7.build.10gen.cc:31007; HostUnreachable couldn't connect to server mci-osx108-7.build.10gen.cc:31007, connection attempt failed
[js_test:tags] 2015-08-26T03:04:56.624-0400  m31000| 2015-08-26T03:04:56.622-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-26T03:04:56.624-0400  m31000| 2015-08-26T03:04:56.622-0400 I REPL     [ReplicationExecutor] Error in heartbeat request to mci-osx108-7.build.10gen.cc:31008; HostUnreachable couldn't connect to server mci-osx108-7.build.10gen.cc:31008, connection attempt failed
[js_test:tags] 2015-08-26T03:04:56.625-0400  m31000| 2015-08-26T03:04:56.622-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-7.build.10gen.cc:31006 would veto with 'mci-osx108-7.build.10gen.cc:31010 has lower priority of 1 than mci-osx108-7.build.10gen.cc:31012 which has a priority of 2'
[js_test:tags] 2015-08-26T03:04:56.625-0400  m31000| 2015-08-26T03:04:56.622-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-26T03:04:56.633-0400 assert.soon failed, msg:Finding master
[js_test:tags] 2015-08-26T03:04:56.633-0400 doassert@src/mongo/shell/assert.js:11:14
[js_test:tags] 2015-08-26T03:04:56.634-0400 assert.soon@src/mongo/shell/assert.js:189:13
[js_test:tags] 2015-08-26T03:04:56.634-0400 ReplSetTest.prototype.getMaster@src/mongo/shell/replsettest.js:383:5
[js_test:tags] 2015-08-26T03:04:56.634-0400 ReplSetTest.prototype.bridge@src/mongo/shell/replsettest.js:1187:12
[js_test:tags] 2015-08-26T03:04:56.634-0400 @jstests/replsets/tags.js:81:1
[js_test:tags] 2015-08-26T03:04:56.634-0400 
[js_test:tags] 2015-08-26T03:04:56.634-0400 ReplSetTest getMaster failed: Error: assert.soon failed, msg:Finding master
[js_test:tags] 2015-08-26T03:04:56.634-0400 printStackTrace@src/mongo/shell/utils.js:65:15
[js_test:tags] 2015-08-26T03:04:56.634-0400 ReplSetTest.prototype.getMaster@src/mongo/shell/replsettest.js:390:5
[js_test:tags] 2015-08-26T03:04:56.635-0400 ReplSetTest.prototype.bridge@src/mongo/shell/replsettest.js:1187:12
[js_test:tags] 2015-08-26T03:04:56.635-0400 @jstests/replsets/tags.js:81:1
[js_test:tags] 2015-08-26T03:04:56.635-0400 
[js_test:tags] 2015-08-26T03:04:56.635-0400 2015-08-26T03:04:56.633-0400 E QUERY    [thread1] Error: assert.soon failed, msg:Finding master :
[js_test:tags] 2015-08-26T03:04:56.635-0400 doassert@src/mongo/shell/assert.js:11:14
[js_test:tags] 2015-08-26T03:04:56.635-0400 assert.soon@src/mongo/shell/assert.js:189:13
[js_test:tags] 2015-08-26T03:04:56.635-0400 ReplSetTest.prototype.getMaster@src/mongo/shell/replsettest.js:383:5
[js_test:tags] 2015-08-26T03:04:56.635-0400 ReplSetTest.prototype.bridge@src/mongo/shell/replsettest.js:1187:12
[js_test:tags] 2015-08-26T03:04:56.635-0400 @jstests/replsets/tags.js:81:1
[js_test:tags] 2015-08-26T03:04:56.635-0400 

Comment by Benety Goh [ 26/Aug/15 ]

546066e9df OS X 10.8 DEBUG replicasets

https://evergreen.mongodb.com/task/mongodb_mongo_master_osx_108_debug_replicasets_546066e9df30a2b6e1a6bfeff208d4b3c0510eb6_15_08_25_19_52_19

https://logkeeper.mongodb.org/build/55dcd4b590413011a29151ab/test/55dce663be07c47abf91e14e

Comment by Benety Goh [ 25/Aug/15 ]

efa95c72b0 OS X 10.8 DEBUG replicasets_WT

https://evergreen.mongodb.com/task/mongodb_mongo_master_osx_108_debug_replicasets_WT_efa95c72b047a3a92c13bba9562733b5d5e0f944_15_08_25_03_46_55

https://logkeeper.mongodb.org/build/55dbee0b90413011a28d0698/test/55dc0c7090413011a28d9605

[js_test:tags] 2015-08-25T02:40:08.737-0400  m31002| 2015-08-25T02:40:08.737-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-25T02:40:08.738-0400  m31002| 2015-08-25T02:40:08.738-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-10.build.10gen.cc:31015 would veto with 'I don't think mci-osx108-10.build.10gen.cc:31007 is electable because the member is not currently a secondary; member is more than 10 seconds behind the most up-to-date member (mask 0xA)'
[js_test:tags] 2015-08-25T02:40:08.739-0400  m31002| 2015-08-25T02:40:08.738-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-25T02:40:08.739-0400  m31002| 2015-08-25T02:40:08.738-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-25T02:40:08.739-0400  m31002| 2015-08-25T02:40:08.739-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-10.build.10gen.cc:31015 would veto with 'I don't think mci-osx108-10.build.10gen.cc:31007 is electable because the member is not currently a secondary; member is more than 10 seconds behind the most up-to-date member (mask 0xA)'
[js_test:tags] 2015-08-25T02:40:08.740-0400  m31002| 2015-08-25T02:40:08.739-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-25T02:40:08.886-0400  m31004| 2015-08-25T02:40:08.886-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-25T02:40:08.887-0400  m31004| 2015-08-25T02:40:08.886-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-10.build.10gen.cc:31025 would veto with 'mci-osx108-10.build.10gen.cc:31009 has lower priority of 1 than mci-osx108-10.build.10gen.cc:31006 which has a priority of 1.5'
[js_test:tags] 2015-08-25T02:40:08.887-0400  m31004| 2015-08-25T02:40:08.887-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-25T02:40:08.888-0400  m31004| 2015-08-25T02:40:08.887-0400 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-25T02:40:08.888-0400  m31004| 2015-08-25T02:40:08.887-0400 I REPL     [ReplicationExecutor] not electing self, mci-osx108-10.build.10gen.cc:31025 would veto with 'mci-osx108-10.build.10gen.cc:31009 has lower priority of 1 than mci-osx108-10.build.10gen.cc:31006 which has a priority of 1.5'
[js_test:tags] 2015-08-25T02:40:08.888-0400  m31004| 2015-08-25T02:40:08.888-0400 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-25T02:40:09.586-0400 assert.soon failed, msg:Finding master
[js_test:tags] 2015-08-25T02:40:09.586-0400 doassert@src/mongo/shell/assert.js:11:14
[js_test:tags] 2015-08-25T02:40:09.586-0400 assert.soon@src/mongo/shell/assert.js:189:13
[js_test:tags] 2015-08-25T02:40:09.587-0400 ReplSetTest.prototype.getMaster@src/mongo/shell/replsettest.js:383:5
[js_test:tags] 2015-08-25T02:40:09.587-0400 ReplSetTest.prototype.bridge@src/mongo/shell/replsettest.js:1187:12
[js_test:tags] 2015-08-25T02:40:09.587-0400 @jstests/replsets/tags.js:81:1
[js_test:tags] 2015-08-25T02:40:09.587-0400 
[js_test:tags] 2015-08-25T02:40:09.587-0400 ReplSetTest getMaster failed: Error: assert.soon failed, msg:Finding master
[js_test:tags] 2015-08-25T02:40:09.587-0400 printStackTrace@src/mongo/shell/utils.js:65:15
[js_test:tags] 2015-08-25T02:40:09.588-0400 ReplSetTest.prototype.getMaster@src/mongo/shell/replsettest.js:390:5
[js_test:tags] 2015-08-25T02:40:09.588-0400 ReplSetTest.prototype.bridge@src/mongo/shell/replsettest.js:1187:12
[js_test:tags] 2015-08-25T02:40:09.588-0400 @jstests/replsets/tags.js:81:1
[js_test:tags] 2015-08-25T02:40:09.588-0400 
[js_test:tags] 2015-08-25T02:40:09.588-0400 2015-08-25T02:40:09.586-0400 E QUERY    [thread1] Error: assert.soon failed, msg:Finding master :
[js_test:tags] 2015-08-25T02:40:09.588-0400 doassert@src/mongo/shell/assert.js:11:14
[js_test:tags] 2015-08-25T02:40:09.588-0400 assert.soon@src/mongo/shell/assert.js:189:13
[js_test:tags] 2015-08-25T02:40:09.588-0400 ReplSetTest.prototype.getMaster@src/mongo/shell/replsettest.js:383:5
[js_test:tags] 2015-08-25T02:40:09.588-0400 ReplSetTest.prototype.bridge@src/mongo/shell/replsettest.js:1187:12
[js_test:tags] 2015-08-25T02:40:09.589-0400 @jstests/replsets/tags.js:81:1
[js_test:tags] 2015-08-25T02:40:09.589-0400 
[js_test:tags] 2015-08-25T02:40:09.589-0400 failed to load: jstests/replsets/tags.js

Comment by Benety Goh [ 22/Aug/15 ]

Not really related other than it's tags.js

6124799c4e Windows 64-bit 2008R2+ DEBUG replicasets_WT

https://evergreen.mongodb.com/task/mongodb_mongo_master_windows_64_2k8_debug_replicasets_WT_6124799c4e14d1ffc9419e6548ec96626e73dcda_15_08_21_21_43_46/0

https://logkeeper.mongodb.org/build/55d7a92690413011a280a2c7/test/55d7bf39be07c47abf812c9c

[js_test:tags] 2015-08-22T00:22:11.233+0000  m31000| 2015-08-22T00:22:11.233+0000 I REPL     [ReplicationExecutor] Error in heartbeat request to WIN-MIAKGV0GBFF:31008; HostUnreachable couldn't connect to server WIN-MIAKGV0GBFF:31008, connection attempt failed
[js_test:tags] 2015-08-22T00:22:11.243+0000  m31003| 2015-08-22T00:22:11.243+0000 W NETWORK  [ReplExecNetThread-2] Failed to connect to 10.230.134.45:31020, reason: errno:10061 No connection could be made because the target machine actively refused it.
[js_test:tags] 2015-08-22T00:22:11.243+0000  m31003| 2015-08-22T00:22:11.243+0000 I REPL     [ReplicationExecutor] Error in heartbeat request to WIN-MIAKGV0GBFF:31020; HostUnreachable couldn't connect to server WIN-MIAKGV0GBFF:31020, connection attempt failed
[js_test:tags] 2015-08-22T00:22:11.625+0000  m31004| 2015-08-22T00:22:11.626+0000 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-22T00:22:11.627+0000  m31004| 2015-08-22T00:22:11.627+0000 I REPL     [ReplicationExecutor] not electing self, WIN-MIAKGV0GBFF:31026 would veto with 'WIN-MIAKGV0GBFF:31014 is trying to elect itself but WIN-MIAKGV0GBFF:31012 is already primary and more up-to-date'
[js_test:tags] 2015-08-22T00:22:11.627+0000  m31004| 2015-08-22T00:22:11.627+0000 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-22T00:22:11.665+0000  m31004| 2015-08-22T00:22:11.666+0000 W NETWORK  [ReplExecNetThread-4] Failed to connect to 10.230.134.45:31025, reason: errno:10061 No connection could be made because the target machine actively refused it.
[js_test:tags] 2015-08-22T00:22:11.665+0000  m31004| 2015-08-22T00:22:11.666+0000 I REPL     [ReplicationExecutor] Error in heartbeat request to WIN-MIAKGV0GBFF:31025; HostUnreachable couldn't connect to server WIN-MIAKGV0GBFF:31025, connection attempt failed
[js_test:tags] 2015-08-22T00:22:11.665+0000  m31004| 2015-08-22T00:22:11.666+0000 I REPL     [ReplicationExecutor] Standing for election
[js_test:tags] 2015-08-22T00:22:11.667+0000  m31004| 2015-08-22T00:22:11.667+0000 I REPL     [ReplicationExecutor] not electing self, WIN-MIAKGV0GBFF:31026 would veto with 'WIN-MIAKGV0GBFF:31014 is trying to elect itself but WIN-MIAKGV0GBFF:31012 is already primary and more up-to-date'
[js_test:tags] 2015-08-22T00:22:11.667+0000  m31004| 2015-08-22T00:22:11.667+0000 I REPL     [ReplicationExecutor] not electing self, we are not freshest
[js_test:tags] 2015-08-22T00:22:11.835+0000  m31002| 2015-08-22T00:22:11.835+0000 W NETWORK  [ReplExecNetThread-3] Failed to connect to 10.230.134.45:31019, reason: errno:10061 No connection could be made because the target machine actively refused it.
[js_test:tags] 2015-08-22T00:22:11.835+0000  m31002| 2015-08-22T00:22:11.835+0000 I REPL     [ReplicationExecutor] Error in heartbeat request to WIN-MIAKGV0GBFF:31019; HostUnreachable couldn't connect to server WIN-MIAKGV0GBFF:31019, connection attempt failed
[js_test:tags] 2015-08-22T00:22:12.216+0000  m31003| 2015-08-22T00:22:12.216+0000 W NETWORK  [ReplExecNetThread-4] Failed to connect to 10.230.134.45:31022, reason: errno:10061 No connection could be made because the target machine actively refused it.
[js_test:tags] 2015-08-22T00:22:12.216+0000  m31002| 2015-08-22T00:22:12.216+0000 W NETWORK  [ReplExecNetThread-0] Failed to connect to 10.230.134.45:31018, reason: errno:10061 No connection could be made because the target machine actively refused it.
[js_test:tags] 2015-08-22T00:22:12.216+0000  m31002| 2015-08-22T00:22:12.216+0000 I REPL     [ReplicationExecutor] Error in heartbeat request to WIN-MIAKGV0GBFF:31018; HostUnreachable couldn't connect to server WIN-MIAKGV0GBFF:31018, connection attempt failed
[js_test:tags] 2015-08-22T00:22:12.216+0000  m31003| 2015-08-22T00:22:12.216+0000 I REPL     [ReplicationExecutor] Error in heartbeat request to WIN-MIAKGV0GBFF:31022; HostUnreachable couldn't connect to server WIN-MIAKGV0GBFF:31022, connection attempt failed
[js_test:tags] 2015-08-22T00:22:12.405+0000  m31002| 2015-08-22T00:22:12.406+0000 I COMMAND  [conn2] command foo.$cmd command: insert { insert: "bar", documents: [ { _id: ObjectId('55d7c09647a7df3289ea0dd7'), x: 1.0 } ], ordered: true, writeConcern: { w: "2 dc and 3 server", wtimeout: 30000.0 } } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:170 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_command 30007ms
[js_test:tags] 2015-08-22T00:22:12.407+0000 assert: write concern failed with errors: {
[js_test:tags] 2015-08-22T00:22:12.407+0000 	"nInserted" : 1,
[js_test:tags] 2015-08-22T00:22:12.407+0000 	"writeConcernError" : {
[js_test:tags] 2015-08-22T00:22:12.407+0000 		"code" : 64,
[js_test:tags] 2015-08-22T00:22:12.407+0000 		"errInfo" : {
[js_test:tags] 2015-08-22T00:22:12.407+0000 			"wtimeout" : true
[js_test:tags] 2015-08-22T00:22:12.407+0000 		},
[js_test:tags] 2015-08-22T00:22:12.407+0000 		"errmsg" : "waiting for replication timed out"
[js_test:tags] 2015-08-22T00:22:12.407+0000 	}
[js_test:tags] 2015-08-22T00:22:12.407+0000 }
[js_test:tags] 2015-08-22T00:22:12.407+0000 doassert@src/mongo/shell/assert.js:11:14
[js_test:tags] 2015-08-22T00:22:12.407+0000 assert.writeOK@src/mongo/shell/assert.js:400:9
[js_test:tags] 2015-08-22T00:22:12.407+0000 @jstests\replsets\tags.js:160:1
[js_test:tags] 2015-08-22T00:22:12.407+0000 
[js_test:tags] 2015-08-22T00:22:12.408+0000 2015-08-22T00:22:12.407+0000 E QUERY    [thread1] Error: write concern failed with errors: {
[js_test:tags] 2015-08-22T00:22:12.408+0000 	"nInserted" : 1,
[js_test:tags] 2015-08-22T00:22:12.408+0000 	"writeConcernError" : {
[js_test:tags] 2015-08-22T00:22:12.408+0000 		"code" : 64,
[js_test:tags] 2015-08-22T00:22:12.408+0000 		"errInfo" : {
[js_test:tags] 2015-08-22T00:22:12.408+0000 			"wtimeout" : true
[js_test:tags] 2015-08-22T00:22:12.408+0000 		},
[js_test:tags] 2015-08-22T00:22:12.408+0000 		"errmsg" : "waiting for replication timed out"
[js_test:tags] 2015-08-22T00:22:12.408+0000 	}
[js_test:tags] 2015-08-22T00:22:12.410+0000 } :
[js_test:tags] 2015-08-22T00:22:12.410+0000 doassert@src/mongo/shell/assert.js:11:14
[js_test:tags] 2015-08-22T00:22:12.410+0000 assert.writeOK@src/mongo/shell/assert.js:400:9
[js_test:tags] 2015-08-22T00:22:12.410+0000 @jstests\replsets\tags.js:160:1
[js_test:tags] 2015-08-22T00:22:12.410+0000 
[js_test:tags] 2015-08-22T00:22:12.410+0000 failed to load: jstests\replsets\tags.js

Comment by Ian Whalen (Inactive) [ 14/Aug/15 ]

ping scotthernandez

Comment by Ian Whalen (Inactive) [ 13/Jul/15 ]

Got it. scotthernandez any ideas then?

Comment by Ernie Hershey [ 13/Jul/15 ]

I don't think it's related because I don't see anything about a ulimit type error. The "bad file descriptor" error usually means something else wrong, like the internal representation of the file handle, or trying to write to a closed socket or things like that.

Comment by Ian Whalen (Inactive) [ 13/Jul/15 ]

ernie.hershey@10gen.com can we just write this off to the ulimit and link it to BUILD-758?

Comment by Matt Dannenberg [ 29/Jun/15 ]

Given that this is a file descriptor related failure on OSX, I wonder if this is related to the maximum file descriptors problem. ernie.hershey@10gen.com thoughts?

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