Loading...

XML

Word

Printable

JSON

Type: Bug
Resolution: Done
Priority: Major - P3
Fix Version/s: 2.6.0-rc0, 2.7.0
Affects Version/s: 2.4.3
Component/s: Replication
Labels:
- rollback
Environment:
AMD Turion(tm) II Dual-Core Mobile M540, 4GB RAM, Ubuntu 13.04, kernel 3.5.0-28-generic

Backwards Compatibility:
Fully Compatible
Operating System:
ALL
Steps To Reproduce:
Hide

Create replica set with 3 nodes (1 primary, 2 secondary).

Insert some data to update optime.

On primary simulate network problem blocking connection on firewall.

iptables -I INPUT -p tcp --dport 27017 -j DROP

Wait to designate new primary

Insert some new data.

On old primary simulate bringing up the network, by allowing connection on firewall.

iptables -I INPUT -p tcp --dport 27017 -j ACCEPT

Wait till new primary is being elected and optime will sync on all nodes.

Check if data from #5 are available.
Show
Create replica set with 3 nodes (1 primary, 2 secondary). Insert some data to update optime. On primary simulate network problem blocking connection on firewall. iptables -I INPUT -p tcp --dport 27017 -j DROP Wait to designate new primary Insert some new data. On old primary simulate bringing up the network, by allowing connection on firewall. iptables -I INPUT -p tcp --dport 27017 -j ACCEPT Wait till new primary is being elected and optime will sync on all nodes. Check if data from #5 are available.
CAR Domain/s:
None

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name(s):
None
Goal Link:
None

Hello,
Hope this is not a duplicated issue.

Let's assume there are 3 nodes in replica set (#1, #2, #3).

> rs.status()
{
        "set" : "set0",
        "date" : ISODate("2013-05-23T12:48:07Z"),
        "myState" : 2,
        "syncingTo" : "krogon:27001",
        "members" : [
                {
                        "_id" : 0,
                        "name" : "krogon:27001",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 29,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "lastHeartbeat" : ISODate("2013-05-23T12:48:06Z"),
                        "lastHeartbeatRecv" : ISODate("2013-05-23T12:48:07Z"),
                        "pingMs" : 0
                },
                {
                        "_id" : 1,
                        "name" : "krogon:27002",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 29,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "lastHeartbeat" : ISODate("2013-05-23T12:48:06Z"),
                        "lastHeartbeatRecv" : ISODate("1970-01-01T00:00:00Z"),
                        "pingMs" : 0,
                        "lastHeartbeatMessage" : "syncing to: krogon:27001",
                        "syncingTo" : "krogon:27001"
                },
                {
                        "_id" : 2,
                        "name" : "krogon:27003",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 31,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "errmsg" : "syncing to: krogon:27001",
                        "self" : true
                }
        ],
        "ok" : 1
}

When there is a network connectivity problem to primary node (#1), election is taking place and new primary is being designed (#3). Then inserting new data will update optime on #2 and #3. Old primary is alive but cannot communicate with other nodes.

> rs.status()
{
        "set" : "set0",
        "date" : ISODate("2013-05-23T12:55:44Z"),
        "myState" : 1,
        "members" : [
                {
                        "_id" : 0,
                        "name" : "krogon:27001",
                        "health" : 0,
                        "state" : 8,
                        "stateStr" : "(not reachable/healthy)",
                        "uptime" : 0,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "lastHeartbeat" : ISODate("2013-05-23T12:55:13Z"),
                        "lastHeartbeatRecv" : ISODate("2013-05-23T12:55:43Z"),
                        "pingMs" : 0
                },
                {
                        "_id" : 1,
                        "name" : "krogon:27002",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 486,
                        "optime" : {
                                "t" : 1369313742,
                                "i" : 1
                        },
                        "optimeDate" : ISODate("2013-05-23T12:55:42Z"),
                        "lastHeartbeat" : ISODate("2013-05-23T12:55:43Z"),
                        "lastHeartbeatRecv" : ISODate("1970-01-01T00:00:00Z"),
                        "pingMs" : 0,
                        "syncingTo" : "krogon:27003"
                },
                {
                        "_id" : 2,
                        "name" : "krogon:27003",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 488,
                        "optime" : {
                                "t" : 1369313742,
                                "i" : 1
                        },
                        "optimeDate" : ISODate("2013-05-23T12:55:42Z"),
                        "self" : true
                }
        ],
        "ok" : 1
}

Log from #1:

[rsHealthPoll] replset info krogon:27002 thinks that we are down
[rsHealthPoll] replset info krogon:27003 thinks that we are down

Log from #2:

[rsHealthPoll] replset info krogon:27001 heartbeat failed, retrying
[rsHealthPoll] replSet info krogon:27001 is down (or slow to respond): 
[rsHealthPoll] replSet member krogon:27001 is now in state DOWN
[rsMgr] not electing self, krogon:27003 would veto with 'krogon:27002 is trying to elect itself but krogon:27001 is already primary and more up-to-date'
[rsMgr] not electing self, krogon:27003 would veto with 'krogon:27002 is trying to elect itself but krogon:27001 is already primary and more up-to-date'
[rsMgr] not electing self, krogon:27003 would veto with 'krogon:27002 is trying to elect itself but krogon:27001 is already primary and more up-to-date'
[rsHealthPoll] replset info krogon:27001 heartbeat failed, retrying
[rsMgr] not electing self, krogon:27003 would veto with 'krogon:27002 is trying to elect itself but krogon:27001 is already primary and more up-to-date'
[rsBackgroundSync] Socket recv() timeout  127.0.1.1:27001
[rsBackgroundSync] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [3] server [127.0.1.1:27001] 
[rsBackgroundSync] replSet db exception in producer: 10278 dbclient error communicating with server: krogon:27001
[conn9] replSet info voting yea for krogon:27003 (2)
[rsMgr] replSet not trying to elect self as responded yea to someone else recently
[rsHealthPoll] replset info krogon:27001 heartbeat failed, retrying
[rsMgr] not electing self, krogon:27003 would veto with 'I am already primary, krogon:27002 can try again once I've stepped down'
[rsHealthPoll] replSet member krogon:27003 is now in state PRIMARY
[rsBackgroundSync] replSet syncing to: krogon:27003
[rsHealthPoll] replset info krogon:27001 heartbeat failed, retrying
[rsSyncNotifier] replset setting oplog notifier to krogon:27003
[rsHealthPoll] replset info krogon:27001 heartbeat failed, retrying
[rsHealthPoll] couldn't connect to krogon:27001: couldn't connect to server krogon:27001

Logs from #3:

[rsHealthPoll] couldn't connect to krogon:27001: couldn't connect to server krogon:27001
[rsHealthPoll] replSet info krogon:27001 is down (or slow to respond): 
[rsHealthPoll] replSet member krogon:27001 is now in state DOWN
[rsBackgroundSync] Socket recv() timeout  127.0.1.1:27001
[rsBackgroundSync] SocketException: remote: 127.0.1.1:27001 error: 9001 socket exception [3] server [127.0.1.1:27001] 
[rsBackgroundSync] replSet db exception in producer: 10278 dbclient error communicating with server: krogon:27001
[rsMgr] replSet info electSelf 2
[rsMgr] replSet PRIMARY
[rsHealthPoll] couldn't connect to krogon:27001: couldn't connect to server krogon:27001

Now the connectivity is back. Election is taking part. Old primary should (#1) rollback data which was not replicated and become secondary. After become secondary it should download data from new master (#3), which has higher optime.

Hovewer during election old primary (#1) becomes primary again. New primary (#3) after swiching to secondary is syncing to old primary (#1) with older optime which causes data loss.

> rs.status()
{
        "set" : "set0",
        "date" : ISODate("2013-05-23T12:59:37Z"),
        "myState" : 2,
        "syncingTo" : "krogon:27001",
        "members" : [
                {
                        "_id" : 0,
                        "name" : "krogon:27001",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 59,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "lastHeartbeat" : ISODate("2013-05-23T12:59:36Z"),
                        "lastHeartbeatRecv" : ISODate("2013-05-23T12:59:37Z"),
                        "pingMs" : 0
                },
                {
                        "_id" : 1,
                        "name" : "krogon:27002",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 719,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "lastHeartbeat" : ISODate("2013-05-23T12:59:37Z"),
                        "lastHeartbeatRecv" : ISODate("1970-01-01T00:00:00Z"),
                        "pingMs" : 0,
                        "syncingTo" : "krogon:27001"
                },
                {
                        "_id" : 2,
                        "name" : "krogon:27003",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 721,
                        "optime" : {
                                "t" : 1369313180,
                                "i" : 2
                        },
                        "optimeDate" : ISODate("2013-05-23T12:46:20Z"),
                        "errmsg" : "syncing to: krogon:27001",
                        "self" : true
                }
        ],
        "ok" : 1
}

LOGS from #3:

[rsHealthPoll] couldn't connect to krogon:27001: couldn't connect to server krogon:27001
[rsHealthPoll] replSet member krogon:27001 is up
[rsHealthPoll] replSet member krogon:27001 is now in state PRIMARY
[rsMgr] replSet relinquishing primary state
[rsMgr] replSet SECONDARY
[rsMgr] replSet closing client sockets after relinquishing primary
[rsBackgroundSync] replSet syncing to: krogon:27001
[rsHealthPoll] replset info krogon:27001 heartbeat failed, retrying
[conn14] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:53226] 
[rsBackgroundSync] replSet we are ahead of the sync source, will try to roll back
[rsBackgroundSync] replSet rollback 0
[rsBackgroundSync] replSet ROLLBACK
[rsBackgroundSync] replSet rollback 1
[rsBackgroundSync] replSet rollback 2 FindCommonPoint
[rsBackgroundSync] replSet info rollback our last optime:   May 23 14:56:36:1
[rsBackgroundSync] replSet info rollback their last optime: May 23 14:46:20:2
[rsBackgroundSync] replSet info rollback diff in end of log times: 616 seconds
[rsBackgroundSync] replSet rollback found matching events at May 23 14:46:20:2
[rsBackgroundSync] replSet rollback findcommonpoint scanned : 142
[rsBackgroundSync] replSet replSet rollback 3 fixup
[rsBackgroundSync] replSet rollback 3.5
[rsBackgroundSync] replSet rollback 4 n:100
[rsBackgroundSync] replSet minvalid=May 23 14:46:20 519e0f9c:2
[rsBackgroundSync] replSet rollback 4.6
[rsBackgroundSync] replSet rollback 4.7
[rsBackgroundSync] replSet rollback 5 d:0 u:100
[rsBackgroundSync] replSet rollback 6
[rsBackgroundSync] replSet rollback 7
[rsBackgroundSync] replSet rollback done
[rsBackgroundSync] replSet RECOVERING
[rsBackgroundSync] replSet syncing to: krogon:27001
[rsSync] replSet SECONDARY
[rsBackgroundSync] replSet syncing to: krogon:27001

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

node1.log
54 kB
May 23 2013 01:33:32 PM UTC
node2.log
12 kB
May 23 2013 01:33:32 PM UTC
node3.log
11 kB
May 23 2013 01:33:33 PM UTC

is duplicated by

SERVER-10768 add proper support for SIGSTOP and SIGCONT (currently, on replica set primary can cause data loss)

Closed

SERVER-8145 Two primaries for the same replica set

Closed

SERVER-10575 Two Primaries if Replica Set Heartbeats Fail in One Direction: "Old" Primary doesn't relinquish.

Closed

related to

SERVER-9283 lastHeartbeatRecv flaps between invalid and valid dates

Closed

Assignee:: Eric Milkie
Reporter:: krogon_tsi
Participants:: Eric Milkie, Githook User, krogon_tsi
Votes:: 0 Vote for this issue
Watchers:: 13 Start watching this issue

Created:: May 23 2013 01:16:21 PM UTC
Updated:: Jul 11 2016 05:37:39 PM UTC
Resolved:: Feb 18 2014 06:38:33 PM UTC

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates