Реплика MongoDB установлена ​​- вторичный повторно выходит из строя - PullRequest
Новая
       38

Реплика MongoDB установлена ​​- вторичный повторно выходит из строя

1 голос
/ 02 апреля 2019

Я пытаюсь настроить набор реплик MongoDB в моем кластере Kubernetes, но вторичный элемент продолжает перезапускаться через несколько секунд.

Вот пара вещей, но полезно знать:

  • Версия сервера (и клиента) Mongo: 4.0.6
  • Я использую официальную диаграмму helm mongodb-replicaset для настройки набора реплик, и единственная пользовательская настройка, которую я использую, это enableMajorityReadConcern: false
  • Размер Oplog настроен на ~ 1228 МБ (используется только 4,7)
  • Это происходит как с первичной-вторичной дугой, так и с архитектурой PSA, когда арбитр многократно умирает, как вторичный член, в то время как первичный всегда работает и работает
  • Это происходит как на моем мини-кубе, так и на промежуточном кластере на GCP с большим количеством свободных ресурсов (я развертываю это без ограничений ресурсов, статус кластера см. Ниже)

Состояние промежуточного кластера (4 узла): 

NAME                               CPU(cores)   CPU%   MEMORY(bytes)   MEMORY%   
gke-staging-pool-1-********-****   551m         28%    3423Mi          60%       
gke-staging-pool-1-********-****   613m         31%    3752Mi          66%       
gke-staging-pool-1-********-****   960m         49%    2781Mi          49%       
gke-staging-pool-1-********-****   602m         31%    3590Mi          63%

В тот момент, когда Primary, кажется, может работать и работать, мне удалось сохранить работоспособность кластера, удалив votes для всех участников, кроме основного. Таким образом, Mongo не отказывается от основного из-за того, что не может видеть большую часть набора, а мое приложение все еще может делать записи.

Если я включу logLevel в 5 на вторичном сервере, единственная ошибка, которую я получаю, это: 

2019-04-02T15:11:42.233+0000 D EXECUTOR [replication-0] Executing a task on behalf of pool replication
2019-04-02T15:11:42.233+0000 D EXECUTOR [replication-0] Not reaping because the earliest retirement date is 2019-04-02T15:12:11.980+0000
2019-04-02T15:11:42.233+0000 D NETWORK  [RS] Timer received error: CallbackCanceled: Callback was canceled
2019-04-02T15:11:42.235+0000 D NETWORK  [RS] Decompressing message with snappy
2019-04-02T15:11:42.235+0000 D ASIO     [RS] Request 114334 finished with response: { cursor: { nextBatch: [], id: 46974224885, ns: "local.oplog.rs" }, ok: 1.0, operationTime: Timestamp(1554217899, 1), $replData: { term: 11536, lastOpCommitted: { ts: Timestamp(1554217899, 1), t: 11536 }, lastOpVisible: { ts: Timestamp(1554217899, 1), t: 11536 }, configVersion: 666752, replicaSetId: ObjectId('5c8a607380091703c787b3ff'), primaryIndex: 0, syncSourceIndex: -1 }, $oplogQueryData: { lastOpCommitted: { ts: Timestamp(1554217899, 1), t: 11536 }, lastOpApplied: { ts: Timestamp(1554217899, 1), t: 11536 }, rbid: 1, primaryIndex: 0, syncSourceIndex: -1 }, $clusterTime: { clusterTime: Timestamp(1554217899, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } } }
2019-04-02T15:11:42.235+0000 D EXECUTOR [RS] Received remote response: RemoteResponse --  cmd:{ cursor: { nextBatch: [], id: 46974224885, ns: "local.oplog.rs" }, ok: 1.0, operationTime: Timestamp(1554217899, 1), $replData: { term: 11536, lastOpCommitted: { ts: Timestamp(1554217899, 1), t: 11536 }, lastOpVisible: { ts: Timestamp(1554217899, 1), t: 11536 }, configVersion: 666752, replicaSetId: ObjectId('5c8a607380091703c787b3ff'), primaryIndex: 0, syncSourceIndex: -1 }, $oplogQueryData: { lastOpCommitted: { ts: Timestamp(1554217899, 1), t: 11536 }, lastOpApplied: { ts: Timestamp(1554217899, 1), t: 11536 }, rbid: 1, primaryIndex: 0, syncSourceIndex: -1 }, $clusterTime: { clusterTime: Timestamp(1554217899, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } } }
2019-04-02T15:11:42.235+0000 D EXECUTOR [replication-5] Executing a task on behalf of pool replication
2019-04-02T15:11:42.235+0000 D REPL     [replication-5] oplog fetcher read 0 operations from remote oplog
2019-04-02T15:11:42.235+0000 D EXECUTOR [replication-5] Scheduling remote command request: RemoteCommand 114336 -- target:foodchain-backend-mongodb-replicaset-0.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017 db:local expDate:2019-04-02T15:11:47.285+0000 cmd:{ getMore: 46974224885, collection: "oplog.rs", batchSize: 13981010, maxTimeMS: 50, term: 11536, lastKnownCommittedOpTime: { ts: Timestamp(1554217899, 1), t: 11536 } }
2019-04-02T15:11:42.235+0000 D ASIO     [replication-5] startCommand: RemoteCommand 114336 -- target:foodchain-backend-mongodb-replicaset-0.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017 db:local expDate:2019-04-02T15:11:47.285+0000 cmd:{ getMore: 46974224885, collection: "oplog.rs", batchSize: 13981010, maxTimeMS: 50, term: 11536, lastKnownCommittedOpTime: { ts: Timestamp(1554217899, 1), t: 11536 } }
2019-04-02T15:11:42.235+0000 D EXECUTOR [replication-5] Not reaping because the earliest retirement date is 2019-04-02T15:12:11.980+0000
2019-04-02T15:11:42.235+0000 D NETWORK  [RS] Timer received error: CallbackCanceled: Callback was canceled
2019-04-02T15:11:42.235+0000 D NETWORK  [RS] Compressing message with snappy
2019-04-02T15:11:42.235+0000 D NETWORK  [RS] Timer received error: CallbackCanceled: Callback was canceled
2019-04-02T15:11:42.235+0000 D NETWORK  [RS] Timer received error: CallbackCanceled: Callback was canceled
2019-04-02T15:11:42.235+0000 D NETWORK  [RS] Timer received error: CallbackCanceled: Callback was canceled

Учитывая сетевую ошибку, я проверил, могут ли все участники соединяться друг с другом, и могут ли они (это явно показано в журналах всех трех участников).

ДОПОЛНИТЕЛЬНАЯ ИНФОРМАЦИЯ: 

foodchain_rs:PRIMARY> rs.status()
{
    "set" : "foodchain_rs",
    "date" : ISODate("2019-04-02T15:35:02.640Z"),
    "myState" : 1,
    "term" : NumberLong(11536),
    "syncingTo" : "",
    "syncSourceHost" : "",
    "syncSourceId" : -1,
    "heartbeatIntervalMillis" : NumberLong(2000),
    "optimes" : {
        "lastCommittedOpTime" : {
            "ts" : Timestamp(1554219299, 1),
            "t" : NumberLong(11536)
        },
        "readConcernMajorityOpTime" : {
            "ts" : Timestamp(1554219299, 1),
            "t" : NumberLong(11536)
        },
        "appliedOpTime" : {
            "ts" : Timestamp(1554219299, 1),
            "t" : NumberLong(11536)
        },
        "durableOpTime" : {
            "ts" : Timestamp(1554219299, 1),
            "t" : NumberLong(11536)
        }
    },
    "members" : [
        {
            "_id" : 0,
            "name" : "foodchain-backend-mongodb-replicaset-0.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017",
            "health" : 1,
            "state" : 1,
            "stateStr" : "PRIMARY",
            "uptime" : 4376,
            "optime" : {
                "ts" : Timestamp(1554219299, 1),
                "t" : NumberLong(11536)
            },
            "optimeDate" : ISODate("2019-04-02T15:34:59Z"),
            "syncingTo" : "",
            "syncSourceHost" : "",
            "syncSourceId" : -1,
            "infoMessage" : "",
            "electionTime" : Timestamp(1554214927, 1),
            "electionDate" : ISODate("2019-04-02T14:22:07Z"),
            "configVersion" : 666752,
            "self" : true,
            "lastHeartbeatMessage" : ""
        },
        {
            "_id" : 1,
            "name" : "foodchain-backend-mongodb-replicaset-1.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017",
            "health" : 1,
            "state" : 2,
            "stateStr" : "SECONDARY",
            "uptime" : 10,
            "optime" : {
                "ts" : Timestamp(1554219299, 1),
                "t" : NumberLong(11536)
            },
            "optimeDurable" : {
                "ts" : Timestamp(1554219299, 1),
                "t" : NumberLong(11536)
            },
            "optimeDate" : ISODate("2019-04-02T15:34:59Z"),
            "optimeDurableDate" : ISODate("2019-04-02T15:34:59Z"),
            "lastHeartbeat" : ISODate("2019-04-02T15:35:01.747Z"),
            "lastHeartbeatRecv" : ISODate("2019-04-02T15:35:01.456Z"),
            "pingMs" : NumberLong(0),
            "lastHeartbeatMessage" : "",
            "syncingTo" : "foodchain-backend-mongodb-replicaset-0.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017",
            "syncSourceHost" : "foodchain-backend-mongodb-replicaset-0.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017",
            "syncSourceId" : 0,
            "infoMessage" : "",
            "configVersion" : 666752
        }
    ],
    "ok" : 1,
    "operationTime" : Timestamp(1554219299, 1),
    "$clusterTime" : {
        "clusterTime" : Timestamp(1554219299, 1),
        "signature" : {
            "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
            "keyId" : NumberLong(0)
        }
    }
}
foodchain_rs:PRIMARY> rs.printReplicationInfo()
configured oplog size:   1228.8701171875MB
log length start to end: 1646798secs (457.44hrs)
oplog first event time:  Thu Mar 14 2019 14:08:51 GMT+0000 (UTC)
oplog last event time:   Tue Apr 02 2019 15:35:29 GMT+0000 (UTC)
now:                     Tue Apr 02 2019 15:35:34 GMT+0000 (UTC)
foodchain_rs:PRIMARY> db.getReplicationInfo()
{
    "logSizeMB" : 1228.8701171875,
    "usedMB" : 4.7,
    "timeDiff" : 1646838,
    "timeDiffHours" : 457.46,
    "tFirst" : "Thu Mar 14 2019 14:08:51 GMT+0000 (UTC)",
    "tLast" : "Tue Apr 02 2019 15:36:09 GMT+0000 (UTC)",
    "now" : "Tue Apr 02 2019 15:36:11 GMT+0000 (UTC)"
}
foodchain_rs:PRIMARY> rs.conf()
{
    "_id" : "foodchain_rs",
    "version" : 666752,
    "protocolVersion" : NumberLong(1),
    "writeConcernMajorityJournalDefault" : true,
    "members" : [
        {
            "_id" : 0,
            "host" : "foodchain-backend-mongodb-replicaset-0.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017",
            "arbiterOnly" : false,
            "buildIndexes" : true,
            "hidden" : false,
            "priority" : 1,
            "tags" : {

            },
            "slaveDelay" : NumberLong(0),
            "votes" : 1
        },
        {
            "_id" : 1,
            "host" : "foodchain-backend-mongodb-replicaset-1.foodchain-backend-mongodb-replicaset.foodchain.svc.cluster.local:27017",
            "arbiterOnly" : false,
            "buildIndexes" : true,
            "hidden" : false,
            "priority" : 0,
            "tags" : {

            },
            "slaveDelay" : NumberLong(0),
            "votes" : 0
        }
    ],
    "settings" : {
        "chainingAllowed" : true,
        "heartbeatIntervalMillis" : 2000,
        "heartbeatTimeoutSecs" : 10,
        "electionTimeoutMillis" : 100,
        "catchUpTimeoutMillis" : -1,
        "catchUpTakeoverDelayMillis" : 30000,
        "getLastErrorModes" : {

        },
        "getLastErrorDefaults" : {
            "w" : 1,
            "wtimeout" : 0
        },
        "replicaSetId" : ObjectId("5c8a607380091703c787b3ff")
    }
}

1 Ответ

2 голосов
/ 03 апреля 2019

Проблема была слишком короткой lectionTimeoutMillis .

Более низкие значения приводят к более быстрому переключению при отказе, но повышают чувствительность к медленному или пятнистости основного узла или сети.

В моем случае это было установлено на 100ms, и у моего Вторичного компьютера не было достаточно времени, чтобы найти члена Primary, поэтому он не мог синхронизироваться и, следовательно, недоступен.

Я думаю, также стоит отметить, что процесс не был убит. mongod PID всегда был 1, а время работы, показанное в top, не совпадало с временем работы, показанным в оболочке rs.status() mongo.

То, что я делал, контролировало время бесперебойной работы через оболочку mongo следующим образом: 

watch -n 1.0 "kubectl -n foodchain exec -it foodchain-backend-mongodb-replicaset-0 -- mongo --eval='rs.status().members.map(m => m.uptime)'"

С помощью этой команды я мог видеть, что время работы Вторичного сервера никогда не превышало 10 с, поэтому я предполагал, что он перезапускается или убивается OOM или что-то в этом роде, вместо этого я думаю, что он пытался провести выборы, но не имел голосов для сделать так и замолчал при перезагрузке. На самом деле, я думаю, что меня по-настоящему смутило отсутствие информации об этом, несмотря на то, что для logLevel было установлено значение 5.

.
...