Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-8017

jstests/replsets/sync_passive2.js failing

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 2.3.2
    • Affects Version/s: None
    • Component/s: Testing Infrastructure
    • Environment:
      Failures seen on Solaris build slave and Windows 64-bit.
    • ALL

      http://buildlogs.mongodb.org/Solaris-SmartOS%2064-bit/builds/759/test/recent%20failures/sync_passive2.js

      ReplSetTest await TS for connection to bs-smartos-x86-64-1.10gen.cc:31004 is 1356198556000:1 and latest is 1356198556000:1
      ReplSetTest await oplog size for connection to bs-smartos-x86-64-1.10gen.cc:31004 is 20002
      ReplSetTest await synced=true
      force 2 to sync from 3
       m31002| Sat Dec 22 17:49:56.892 [conn2] attempting to sync from bs-smartos-x86-64-1.10gen.cc:31003, but its latest opTime is 1356198504 and ours is 1356198556 so this may not work
       m31000| Sat Dec 22 17:49:57.073 [conn23] end connection 165.225.128.186:64842 (10 connections now open)
       m31002| Sat Dec 22 17:49:57.073 [rsBackgroundSync] replSet syncing to: bs-smartos-x86-64-1.10gen.cc:31003 by request
       m31003| Sat Dec 22 17:49:57.073 [initandlisten] connection accepted from 165.225.128.186:54430 #19 (6 connections now open)
       m31002| Sat Dec 22 17:49:57.074 [rsBackgroundSync] replSet syncing to: bs-smartos-x86-64-1.10gen.cc:31000
       m31003| Sat Dec 22 17:49:57.074 [conn19] end connection 165.225.128.186:54430 (5 connections now open)
       m31000| Sat Dec 22 17:49:57.074 [initandlisten] connection accepted from 165.225.128.186:47032 #30 (11 connections now open)
      {
      	"set" : "sync_passive2",
      	"date" : ISODate("2012-12-22T17:49:57Z"),
      	"myState" : 2,
      	"syncingTo" : "bs-smartos-x86-64-1.10gen.cc:31000",
      	"members" : [
      		{
      			"_id" : 0,
      			"name" : "bs-smartos-x86-64-1.10gen.cc:31000",
      			"health" : 1,
      			"state" : 1,
      			"stateStr" : "PRIMARY",
      			"uptime" : 40,
      			"optime" : {
      				"t" : 1356198556000,
      				"i" : 1
      			},
      			"optimeDate" : ISODate("2012-12-22T17:49:16Z"),
      			"lastHeartbeat" : ISODate("2012-12-22T17:49:55Z"),
      			"lastHeartbeatRecv" : ISODate("2012-12-22T17:49:56Z"),
      			"pingMs" : 0
      		},
      		{
      			"_id" : 1,
      			"name" : "bs-smartos-x86-64-1.10gen.cc:31001",
      			"health" : 1,
      			"state" : 7,
      			"stateStr" : "ARBITER",
      			"uptime" : 40,
      			"lastHeartbeat" : ISODate("2012-12-22T17:49:55Z"),
      			"lastHeartbeatRecv" : ISODate("2012-12-22T17:49:56Z"),
      			"pingMs" : 0
      		},
      		{
      			"_id" : 2,
      			"name" : "bs-smartos-x86-64-1.10gen.cc:31002",
      			"health" : 1,
      			"state" : 2,
      			"stateStr" : "SECONDARY",
      			"uptime" : 74,
      			"optime" : {
      				"t" : 1356198556000,
      				"i" : 1
      			},
      			"optimeDate" : ISODate("2012-12-22T17:49:16Z"),
      			"errmsg" : "syncing to: bs-smartos-x86-64-1.10gen.cc:31000",
      			"self" : true
      		},
      		{
      			"_id" : 3,
      			"name" : "bs-smartos-x86-64-1.10gen.cc:31003",
      			"health" : 1,
      			"state" : 2,
      			"stateStr" : "SECONDARY",
      			"uptime" : 40,
      			"optime" : {
      				"t" : 1356198504000,
      				"i" : 4242
      			},
      			"optimeDate" : ISODate("2012-12-22T17:48:24Z"),
      			"lastHeartbeat" : ISODate("2012-12-22T17:49:55Z"),
      			"lastHeartbeatRecv" : ISODate("2012-12-22T17:49:57Z"),
      			"pingMs" : 0,
      			"lastHeartbeatMessage" : "syncing to: bs-smartos-x86-64-1.10gen.cc:31000"
      		},
      		{
      			"_id" : 4,
      			"name" : "bs-smartos-x86-64-1.10gen.cc:31004",
      			"health" : 1,
      			"state" : 2,
      			"stateStr" : "SECONDARY",
      			"uptime" : 40,
      			"optime" : {
      				"t" : 1356198556000,
      				"i" : 1
      			},
      			"optimeDate" : ISODate("2012-12-22T17:49:16Z"),
      			"lastHeartbeat" : ISODate("2012-12-22T17:49:55Z"),
      			"lastHeartbeatRecv" : ISODate("2012-12-22T17:49:56Z"),
      			"pingMs" : 0,
      			"lastHeartbeatMessage" : "syncing to: bs-smartos-x86-64-1.10gen.cc:31000"
      		}
      	],
      	"ok" : 1
      }
      

      This test has problems at this stage. It expects to be able to see that it has successfully changed the "sync to" setting for a node and expects to see it be automatically changed to a non-slave-delayed node "within ~30 seconds". In this failure, the setting was successfully changed and was automatically reset 1 millisecond later:

       m31002| Sat Dec 22 17:49:56.892 [conn2] attempting to sync from bs-smartos-x86-64-1.10gen.cc:31003, but its latest opTime is 1356198504 and ours is 1356198556 so this may not work
       m31000| Sat Dec 22 17:49:57.073 [conn23] end connection 165.225.128.186:64842 (10 connections now open)
       m31002| Sat Dec 22 17:49:57.073 [rsBackgroundSync] replSet syncing to: bs-smartos-x86-64-1.10gen.cc:31003 by request
       m31003| Sat Dec 22 17:49:57.073 [initandlisten] connection accepted from 165.225.128.186:54430 #19 (6 connections now open)
       m31002| Sat Dec 22 17:49:57.074 [rsBackgroundSync] replSet syncing to: bs-smartos-x86-64-1.10gen.cc:31000
      

      This very fast reset doesn't give the script any time to see that its setting did, in fact, work.

            Assignee:
            kristina Kristina Chodorow (Inactive)
            Reporter:
            tad Tad Marshall
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: