PBM backup: waiting for dump done: backup stuck, last beat ts

MongoDB Percona Backup for MongoDB
1

pbm logs:

bash-4.4$ pbm logs -x -s D -t 0 -e backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] init backup meta
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination list for rs0: [[mongo-cluster-rs0-1.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [mongo-cluster-rs0-0.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017]]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination list for cfg: [[mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-cfg-0.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017]]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination list for rs1: [[mongo-cluster-rs1-1.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [mongo-cluster-rs1-2.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017]]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination list for rs2: [[mongo-cluster-rs2-1.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-rs2-2.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017] [mongo-cluster-rs2-0.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017]]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination rs0, set candidates [mongo-cluster-rs0-1.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination cfg, set candidates [mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-cfg-0.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination rs1, set candidates [mongo-cluster-rs1-1.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017]
2022-12-08T16:40:29Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] nomination rs2, set candidates [mongo-cluster-rs2-1.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017 mongo-cluster-rs2-2.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017]
2022-12-08T16:40:30Z I [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] backup started
2022-12-08T16:40:30Z I [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] backup started
2022-12-08T16:40:30Z I [cfg/mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] backup started
2022-12-08T16:40:30Z D [cfg/mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] waiting for balancer off
2022-12-08T16:40:30Z D [rs1/mongo-cluster-rs1-2.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:30Z D [rs0/mongo-cluster-rs0-0.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:30Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:30Z I [rs2/mongo-cluster-rs2-2.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] backup started
2022-12-08T16:40:30Z D [cfg/mongo-cluster-cfg-0.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:30Z D [cfg/mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] balancer status: off
2022-12-08T16:40:30Z D [rs2/mongo-cluster-rs2-1.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:31Z D [rs2/mongo-cluster-rs2-0.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:31Z D [rs1/mongo-cluster-rs1-1.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:31Z D [rs0/mongo-cluster-rs0-1.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] skip after nomination, probably started by another node
2022-12-08T16:40:35Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] bcp nomination: rs0 won by mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017
2022-12-08T16:40:35Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] bcp nomination: rs1 won by mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017
2022-12-08T16:40:35Z D [cfg/mongo-cluster-cfg-1.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] bcp nomination: rs2 won by mongo-cluster-rs2-2.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017
2022-12-08T16:40:37Z D [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] wait for tmp users {1670517637 1677}
2022-12-08T16:40:37Z D [rs2/mongo-cluster-rs2-2.mongo-cluster-rs2.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] wait for tmp users {1670517637 3436}
2022-12-08T16:40:37Z D [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] wait for tmp users {1670517637 3085}
2022-12-08T16:40:38Z D [cfg/mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] wait for tmp users {1670517638 8}
2022-12-08T16:40:44Z I [cfg/mongo-cluster-cfg-2.mongo-cluster-cfg.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] mongodump finished, waiting for the oplog
2022-12-09T00:46:56Z I [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] mongodump finished, waiting for the oplog
2022-12-09T00:51:30Z I [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] mongodump finished, waiting for the oplog
2022-12-09T01:04:46Z I [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] dropping tmp collections
2022-12-09T01:04:46Z I [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] mark RS as error `waiting for dump done: backup stuck, last beat ts: 1670547855`: <nil>
2022-12-09T01:04:46Z D [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] set balancer on
2022-12-09T01:04:46Z E [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] backup: waiting for dump done: backup stuck, last beat ts: 1670547855
2022-12-09T01:04:46Z D [rs1/mongo-cluster-rs1-0.mongo-cluster-rs1.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] releasing lock
2022-12-09T01:04:46Z I [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] dropping tmp collections
2022-12-09T01:04:46Z I [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] mark RS as error `waiting for dump done: backup stuck, last beat ts: 1670547855`: <nil>
2022-12-09T01:04:46Z D [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] set balancer on
2022-12-09T01:04:46Z E [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] backup: waiting for dump done: backup stuck, last beat ts: 1670547855
2022-12-09T01:04:46Z D [rs0/mongo-cluster-rs0-2.mongo-cluster-rs0.platform-percona-mongo-cluster.svc.cluster.local:27017] [backup/2022-12-08T16:40:29Z/6392137da296cf278aecab95] releasing lock
1 Like
2

I have similar issue, where can I find the reason or is there any readily available workdaround to avoid this?

3

Hi, please look at journalctl -u pbm-agent on all nodes. That should help pinpoint the problem