Uploaded image for project: 'Percona Server for MongoDB'
  1. Percona Server for MongoDB
  2. PSMDB-246

Issue when restoring encrypted db from hotbackup and specifying wrong master key

    Details

    • Type: Bug
    • Status: Open
    • Priority: Medium
    • Resolution: Reopened
    • Affects Version/s: 4.0.4-1, 3.6.8-2.0
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      There's an issue when you have replicaset and make a backup of one node and try to restore it and incidentally specify the wrong master key - you won't be able to start even if you fix the master key, you'll need to recopy backup again.

      The steps to reproduce are (this is for one node in replicaset):
      1. run some workload
      2. create a backup
      3. stop instance
      4. remove datadir and restore from backup
      5. "incidentally" use wrong master key when starting the instance, it will not start and it will error as expected
      6. this time specify the right master key and it will still not want to start, even if you remove keydb and restore just this part from backup it will still not want to start, you'll need to restore again

      Currently I couldn't reproduce it if I just start/stop the instance with wrong/correct key without restoring from hotbackup and also couldn't reproduce it if the instance wasn't part of the replicaset for some reason.

      Here's how the error looks:

      ### First time with the wrong key ###
      Starting mongod on port: 27019 storage engine: wiredTiger replica set: rs1
      [1540550087:683335][11813:0x7f7fb795cc80], WT_CURSOR.next: libcrypto: 1:error:06065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt:evp_enc.c:531:
      
      ./start.sh: line 3: 11813 Segmentation fault      /home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/bin/mongod --port 27019 --storageEngine wiredTiger --dbpath /home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/db --logpath /home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/mongod.log --replSet rs1 --wiredTigerCacheSizeGB 2 --enableEncryption --encryptionKeyFile /home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/mongodb-keyfile2 --encryptionCipherMode AES256-CBC
      
      ### Second time with the correct master key ###
      plavi@bender  ~/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3  ./start.sh
      Starting mongod on port: 27019 storage engine: wiredTiger replica set: rs1
      2018-10-26T12:39:14.287+0200 I CONTROL  [main] log file "/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/mongod.log" exists; moved to "/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/mongod.log.2018-10-26T10-39-14".
      [1540550354:764070][12053:0x7f15d0510c80], txn-recover: libcrypto: 1:error:06065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt:evp_enc.c:531:
      [1540550354:764086][12053:0x7f15d0510c80], txn-recover: libcrypto: 1:error:06065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt:evp_enc.c:531:
      [1540550354:764092][12053:0x7f15d0510c80], txn-recover: Recovery failed: Invalid argument
      
      ### ERROR LOG: ###
      2018-10-26T12:39:14.293+0200 I CONTROL  [initandlisten] options: { net: { port: 27019 }, replication: { replSet: "rs1" }, security: { enableEncryption: true, encryptionCipherMode: "AES256-CBC", encryptionKeyFile: "/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/mongodb-keyfile" }, storage: { dbPath: "/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/db", engine: "wiredTiger", wiredTiger: { engineConfig: { cacheSizeGB: 2.0 } } }, systemLog: { destination: "file", path: "/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/mongod.log" } }
      2018-10-26T12:39:14.293+0200 I STORAGE  [initandlisten]
      2018-10-26T12:39:14.293+0200 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
      2018-10-26T12:39:14.293+0200 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
      2018-10-26T12:39:14.767+0200 E STORAGE  [initandlisten] error opening keys DB at '/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/db/keydb': Invalid argument
      2018-10-26T12:39:14.767+0200 I STORAGE  [initandlisten] exception in initAndListen std::exception: error opening keys DB at '/home/plavi/lab/psmdb/bin/percona-server-mongodb-3.6.8-2.0/nodes/node3/db/keydb': Invalid argument, terminating
      2018-10-26T12:39:14.767+0200 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
      2018-10-26T12:39:14.767+0200 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27019.sock
      2018-10-26T12:39:14.767+0200 I CONTROL  [initandlisten] now exiting
      2018-10-26T12:39:14.767+0200 I CONTROL  [initandlisten] shutting down with code:100
      

        Smart Checklist

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  igor.solodovnikov Igor Solodovnikov
                  Reporter:
                  tomislav.plavcic@percona.com Tomislav Plavcic
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved:

                    Time Tracking

                    Estimated:
                    Original Estimate - Not Specified
                    Not Specified
                    Remaining:
                    Remaining Estimate - 0 minutes
                    0m
                    Logged:
                    Time Spent - 1 week, 1 day
                    1w 1d