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

Sync target occasionally changes incorrectly (or not?)

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: 2.6.7
    • Component/s: Replication
    • None
    • ALL

      While examining our logs I've found some messages like these:

      2015-02-15T02:28:04.928+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.942+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.946+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.948+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.951+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.953+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.956+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.958+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.962+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.963+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.966+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.968+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.971+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.972+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.976+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.977+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.981+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.982+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.985+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.987+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.990+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.991+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:04.995+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:04.996+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
2015-02-15T02:28:05.000+0300 [rsBackgroundSync] changing sync target because current sync target's most recent OpTime is Feb 15 02:27:28:1 which is more than 30 seconds behind member d1.s1.fs.drive.bru:27021 whose most recent OpTime is 1423956484
2015-02-15T02:28:05.001+0300 [rsBackgroundSync] replset setting syncSourceFeedback to d2.s1.fs.drive.bru:27021
...

      At first I suspected time sync issue, rechecked twice, found no problems (ntpd is up and running, deviation is less than one second, it wasn't applying time changes at the moment this problem manifested).

      Since this only occurs at night (local time is GMT+3), and this replica set has very light write load, I suspect that the problem might be in no writes being done for extended periods of time (>30 seconds) and background sync complaining about this erroneously.

        1. logs.tar.bz2
          5.89 MB
          Aristarkh Zagorodnikov

            Assignee:
            sam.kleinman Sam Kleinman (Inactive)
            Reporter:
            onyxmaster Aristarkh Zagorodnikov
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved: