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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Medium
    • Resolution: Reopened
    • Affects Version/s: 3.6.8-2.0, 4.0.4-1
    • 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

          1. mongod.log
            15 kB
            Tomislav Plavcic

            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