Details
-
Bug
-
Resolution: Done
-
Minor - P4
-
None
-
None
-
Fully Compatible
-
ALL
-
RPL A (10/09/15)
-
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.
Log:
https://logkeeper.mongodb.org/build/5590bd2bbe07c41a360a38f4/test/5590cf50be07c41a360af0c5
Attachments
Issue Links
- is duplicated by
-
SERVER-15637 Remove assert.soon from ReplSetTest.prototype.initiate
-
- Closed
-