Skip to:

  1. Skip to Jira Navigation
  2. Skip to Side Navigation
  3. Skip to Main Content

Restore failed with "incompatible auth version with target server"

Description

  1. pbm restore 2020-01-21T16:52:26Z --mongodb-uri="mongodb://pbmuser:password1@dbvrp51235.uhc.com:27017,dbvrp51236.uhc.com:27017,dbvrp51240.uhc.com:27017/?replicaSet=rd0"
    Restore of the snapshot from '2020-01-21T16:52:26Z' has started

No activity recorded in opslog or in respective pbm-agent logs. In fact, no information in pbm-agent logs – even successful backup.

Percona Backup for MongoDB installed from root

  1. ls -l /bin/pbm*
    -rwxr-xr-x. 1 root root 20021648 Jan 9 08:13 /bin/pbm
    -rwxr-xr-x. 1 root root 22070432 Jan 9 08:13 /bin/pbm-agent

Respective pbm-agent log owned by pbm:pbm and empty.

  1. ls -l /var/log/pbm-agent.log
    rw-r----. 1 pbm pbm 0 Jan 16 17:21 /var/log/pbm-agent.log

User pbmuser created per instructions

Environment

3 node replica set
Red Hat 7
2CPU - 8GB each node

is duplicated by

Smart Checklist

Activity

Show:

Akira Kurogane January 29, 2020 at 7:39 AM

Hi Fernando.

FYI we think it's a regression caused by .

We're working on a v1.1.1 as a relatively quick bug-fix release now. Basically only this and a vendor libraries update are planned to be in that release.

Please continue watching this ticket for updates. Until we get 1.1.1 out I'm afraid the restore won't work for you.

Akira

andrew.pogrebnoi January 27, 2020 at 12:32 PM

Hi ,

 

Thanks for the providing detailed info. We’ve found an issue and going to make a patch release with the fix.

Fernando Guillory January 24, 2020 at 4:33 PM

Hi Andrii Pogrebnoi,

Below is respective "grep pbm /var/log/messages" from each node. Node dbvrp51235 is primary. I do believe I ran the backup and restore from node dbvrp51236, which from my understanding does not matter.

root@dbvrp51235:/root

  1. grep pbm /var/log/messages
    Jan 17 14:59:14 dbvrp51235 systemd: Started pbm-agent.
    Jan 17 14:59:15 dbvrp51235 pbm-agent: pbm agent is listening for the commands
    Jan 21 10:52:26 dbvrp51235 pbm-agent: 2020/01/21 10:52:26 Got command backup 2020-01-21T16:52:26Z
    Jan 21 10:52:39 dbvrp51235 pbm-agent: 2020/01/21 10:52:39 Backup has been scheduled on another replset node
    Jan 22 15:06:10 dbvrp51235 pbm-agent: 2020/01/22 15:06:10 Got command restore 2020-01-21T16:52:26Z
    Jan 22 15:06:10 dbvrp51235 pbm-agent: 2020/01/22 15:06:10 [INFO] Restore of '2020-01-21T16:52:26Z' started
    Jan 22 15:06:10 dbvrp51235 pbm-agent: 2020-01-22T15:06:10.369-0600#011preparing collections to restore from
    Jan 22 15:06:10 dbvrp51235 pbm-agent: 2020-01-22T15:06:10.384-0600#011assuming users in the dump directory are from <= 2.4 (auth version 1)
    Jan 22 15:06:10 dbvrp51235 pbm-agent: 2020/01/22 15:06:10 [ERROR] restore: restore mongo dump (successes: 0 / fails: 0): the users and roles collections in the dump have an incompatible auth version with target server: cannot restore users of auth version 1 to a server of auth version 5
    Jan 22 15:23:49 dbvrp51235 pbm-agent: 2020/01/22 15:23:49 Got command restore 2020-01-21T16:52:26Z
    Jan 22 15:23:49 dbvrp51235 pbm-agent: 2020/01/22 15:23:49 [INFO] Restore of '2020-01-21T16:52:26Z' started
    Jan 22 15:23:49 dbvrp51235 pbm-agent: 2020-01-22T15:23:49.872-0600#011preparing collections to restore from
    Jan 22 15:23:49 dbvrp51235 pbm-agent: 2020-01-22T15:23:49.887-0600#011assuming users in the dump directory are from <= 2.4 (auth version 1)
    Jan 22 15:23:49 dbvrp51235 pbm-agent: 2020/01/22 15:23:49 [ERROR] restore: restore mongo dump (successes: 0 / fails: 0): the users and roles collections in the dump have an incompatible auth version with target server: cannot restore users of auth version 1 to a server of auth version 5
    Jan 23 16:11:05 dbvrp51235 pbm-agent: 2020/01/23 16:11:05 Got command restore 2020-01-21T16:52:26Z
    Jan 23 16:11:05 dbvrp51235 pbm-agent: 2020/01/23 16:11:05 [ERROR] unbale to run the restore while another backup or restore process running

root@dbvrp51236:/root

  1. grep pbm /var/log/messages
    Jan 17 16:18:18 dbvrp51236 systemd: Started pbm-agent.
    Jan 17 16:18:18 dbvrp51236 pbm-agent: pbm agent is listening for the commands
    Jan 21 10:52:26 dbvrp51236 pbm-agent: 2020/01/21 10:52:26 Got command backup 2020-01-21T16:52:26Z
    Jan 21 10:52:26 dbvrp51236 pbm-agent: 2020/01/21 10:52:26 Backup has been scheduled on another replset node
    Jan 22 15:06:09 dbvrp51236 pbm-agent: 2020/01/22 15:06:09 Got command restore 2020-01-21T16:52:26Z
    Jan 22 15:06:09 dbvrp51236 pbm-agent: 2020/01/22 15:06:09 Node in not suitable for restore
    Jan 22 15:23:49 dbvrp51236 pbm-agent: 2020/01/22 15:23:49 Got command restore 2020-01-21T16:52:26Z
    Jan 22 15:23:49 dbvrp51236 pbm-agent: 2020/01/22 15:23:49 Node in not suitable for restore
    Jan 23 16:11:04 dbvrp51236 pbm-agent: 2020/01/23 16:11:04 Got command restore 2020-01-21T16:52:26Z
    Jan 23 16:11:04 dbvrp51236 pbm-agent: 2020/01/23 16:11:04 Node in not suitable for restore

root@dbvrp51240:/root

  1. grep pbm /var/log/messages
    Jan 17 16:24:43 dbvrp51240 systemd: Started pbm-agent.
    Jan 17 16:24:43 dbvrp51240 pbm-agent: pbm agent is listening for the commands
    Jan 21 10:52:26 dbvrp51240 pbm-agent: 2020/01/21 10:52:26 Got command backup 2020-01-21T16:52:26Z
    Jan 21 10:52:26 dbvrp51240 pbm-agent: 2020/01/21 10:52:26 Backup has been scheduled on another replset node
    Jan 22 15:06:09 dbvrp51240 pbm-agent: 2020/01/22 15:06:09 Got command restore 2020-01-21T16:52:26Z
    Jan 22 15:06:09 dbvrp51240 pbm-agent: 2020/01/22 15:06:09 Node in not suitable for restore
    Jan 22 15:23:49 dbvrp51240 pbm-agent: 2020/01/22 15:23:49 Got command restore 2020-01-21T16:52:26Z
    Jan 22 15:23:49 dbvrp51240 pbm-agent: 2020/01/22 15:23:49 Node in not suitable for restore
    Jan 23 16:11:04 dbvrp51240 pbm-agent: 2020/01/23 16:11:04 Got command restore 2020-01-21T16:52:26Z
    Jan 23 16:11:05 dbvrp51240 pbm-agent: 2020/01/23 16:11:05 Node in not suitable for restore

It looks like I attempted the first restore on Jan 22, not on Jan 21 as reported in the previous comment. I do see the first node reports a restore error which I cannot decipher.

Regards,
Fernando Guillory

Fernando Guillory January 24, 2020 at 4:17 PM

Hi Andrii Pogrebnoi,

The information you requested is below:

1. `pbm version` output.

  1. pbm version
    Version: 1.1.0
    Platform: linux/amd64
    GitCommit: b26a35262f9d21ea8441423687215829be1fdea0
    GitBranch: master
    BuildTime: 2020-01-09_09:13_UTC
    GoVersion: go1.12.9

2. `pbm list` output.

pbm list --mongodb-uri mongodb://pbmuser:password1@dbvrp51235.uhc.com:27017,dbvrp51236.uhc.com:27017,dbvrp51240.uhc.com:27017/?replicaSet=rd0

3. How do you run pbm-agent(s)?
As a service. Just ran the status and it may shed some light. The first attempt at a restore was Jan 21.

  1. service pbm-agent status
    Redirecting to /bin/systemctl status pbm-agent.service
    ● pbm-agent.service - pbm-agent
    Loaded: loaded (/usr/lib/systemd/system/pbm-agent.service; enabled; vendor preset: disabled)
    Active: active (running) since Fri 2020-01-17 14:59:14 CST; 6 days ago
    Main PID: 62675 (pbm-agent)
    CGroup: /system.slice/pbm-agent.service
    └─62675 /usr/bin/pbm-agent --mongodb-uri=mongodb://pbmuser:password1@localhost:27017/?authSource=admin&replicaSet=rd0

Jan 22 15:06:10 dbvrp51235 pbm-agent[62675]: 2020-01-22T15:06:10.369-0600 preparing collections to restore from
Jan 22 15:06:10 dbvrp51235 pbm-agent[62675]: 2020-01-22T15:06:10.384-0600 assuming users in the dump directory are from <= 2.4 (auth version 1)
Jan 22 15:06:10 dbvrp51235 pbm-agent[62675]: 2020/01/22 15:06:10 [ERROR] restore: restore mongo dump (successes: 0 / fails: 0): the users and roles colle...version 5
Jan 22 15:23:49 dbvrp51235 pbm-agent[62675]: 2020/01/22 15:23:49 Got command restore 2020-01-21T16:52:26Z
Jan 22 15:23:49 dbvrp51235 pbm-agent[62675]: 2020/01/22 15:23:49 [INFO] Restore of '2020-01-21T16:52:26Z' started
Jan 22 15:23:49 dbvrp51235 pbm-agent[62675]: 2020-01-22T15:23:49.872-0600 preparing collections to restore from
Jan 22 15:23:49 dbvrp51235 pbm-agent[62675]: 2020-01-22T15:23:49.887-0600 assuming users in the dump directory are from <= 2.4 (auth version 1)
Jan 22 15:23:49 dbvrp51235 pbm-agent[62675]: 2020/01/22 15:23:49 [ERROR] restore: restore mongo dump (successes: 0 / fails: 0): the users and roles colle...version 5
Jan 23 16:11:05 dbvrp51235 pbm-agent[62675]: 2020/01/23 16:11:05 Got command restore 2020-01-21T16:52:26Z
Jan 23 16:11:05 dbvrp51235 pbm-agent[62675]: 2020/01/23 16:11:05 [ERROR] unbale to run the restore while another backup or restore process running
Hint: Some lines were ellipsized, use -l to show in full.

4. From which host (pbm-agent) the empty log you shown in the description?
Each respective log on all three nodes of the replica set is empty. The pbm-agent service is started on each respective replica node.

5. What is in the logs of other ppm-agents?
Per answer in question 4, all pbm-agent logs are empty.

Regards,
Fernando Guillory

andrew.pogrebnoi January 24, 2020 at 10:57 AM
Edited

Hi ,

 

Can you provide us with some additional info: 

  1. `pbm version` output.

  2. `pbm list` output.

  3. How do you run pbm-agent(s)?

  4. From which host (pbm-agent) the empty log you shown in the description?

  5. What is in the logs of other ppm-agents?

 

Thank you!

Done

Details

Assignee

Reporter

Time tracking

2d 1h logged

Fix versions

Affects versions

Priority

Smart Checklist

Created January 23, 2020 at 10:47 PM
Updated March 5, 2024 at 7:18 PM
Resolved January 31, 2020 at 2:06 PM