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

Sync target occasionally changes incorrectly (or not?)

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor - P4
    • Resolution: Done
    • Affects Version/s: 2.6.7
    • Fix Version/s: None
    • Component/s: Replication
    • Labels:
      None
    • Operating System:
      ALL

      Description

      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.

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved: