write concern timeout in tags.js should not exceed max sync source lag secs

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Done
    • Priority: Minor - P4
    • 3.1.9
    • Affects Version/s: None
    • Component/s: Replication
    • None
    • Fully Compatible
    • ALL
    • RPL A (10/09/15)
    • 0
    • None
    • 3
    • None
    • None
    • None
    • None
    • None
    • None

      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

            Assignee:
            Benety Goh
            Reporter:
            Adam Midvidy (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: