Percona MongoDB with vault

Hi,
After enable encryption mongodb percona service failed to start
security:
enableEncryption: true
encryptionKeyFile: /data/key/mongodb.key

Please help me with percona mongodb with encryption data at rest

1 Like

Hello @vijendra ,

could you please share more details for us to help you?

  • MongoDB version
  • Type of deployment (is it regular setup or through the operator on Kubernetes)?
  • Logs
  • Any error when you start mongod?
1 Like

Hi Spronin,

MongoDB version :- Percona Server for MongoDB shell Version v4.4.4-6

Type of Deployment :- Regular setup in ubuntu 18.04

Logs :- test@test-VirtualBox:~$ tail -f /var/log/mongodb/mongod.log

{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:"-", “id”:20520, “ctx”:“initandlisten”,“msg”:“Stopping further Flow Control ticket acquisitions.”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“NETWORK”, “id”:4784918, “ctx”:“initandlisten”,“msg”:“Shutting down the ReplicaSetMonitor”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“SHARDING”, “id”:4784921, “ctx”:“initandlisten”,“msg”:“Shutting down the MigrationUtilExecutor”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“CONTROL”, “id”:4784925, “ctx”:“initandlisten”,“msg”:“Shutting down free monitoring”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“STORAGE”, “id”:4784927, “ctx”:“initandlisten”,“msg”:“Shutting down the HealthLog”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“STORAGE”, “id”:4784929, “ctx”:“initandlisten”,“msg”:“Acquiring the global lock for shutdown”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:"-", “id”:4784931, “ctx”:“initandlisten”,“msg”:“Dropping the scope cache for shutdown”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“FTDC”, “id”:4784926, “ctx”:“initandlisten”,“msg”:“Shutting down full-time data capture”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“CONTROL”, “id”:20565, “ctx”:“initandlisten”,“msg”:“Now exiting”}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“I”, “c”:“CONTROL”, “id”:23138, “ctx”:“initandlisten”,“msg”:“Shutting down”,“attr”:{“exitCode”:100}}

Whenever I include in /etc/mongodb.conf
security:
enableEncryption: true
encryptionKeyFile: /data/key/mongodb.key

Mongod service stopped if I remove this part service working fine.

1 Like

Is it all the logs that appear after you try to start mongod with encryption? I see you are using “tail -f”, what about “tail -1000”?

1 Like
{"t":{"$date":"2021-03-03T16:30:47.423+05:30"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2021-03-03T16:30:47.427+05:30"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2021-03-03T16:30:47.427+05:30"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2021-03-03T16:30:47.427+05:30"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":31415,"port":27017,"dbPath":"/var/lib/mongodb","architecture":"64-bit","host":"test-VirtualBox"}}
{"t":{"$date":"2021-03-03T16:30:47.427+05:30"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.4-6","gitVersion":"f3dd4bc7c7500705a537de40bb4d6127ba498bd3","openSSLVersion":"OpenSSL 1.1.1  11 Sep 2018","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2021-03-03T16:30:47.427+05:30"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"18.04"}}}
{"t":{"$date":"2021-03-03T16:30:47.427+05:30"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongod.conf","net":{"bindIp":"127.0.0.1","port":27017},"processManagement":{"fork":true,"pidFilePath":"/var/run/mongod.pid"},"storage":{"dbPath":"/var/lib/mongodb","journal":{"enabled":true}},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log"}}}}
{"t":{"$date":"2021-03-03T16:30:47.428+05:30"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2021-03-03T16:30:47.428+05:30"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=1456M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
{"t":{"$date":"2021-03-03T16:30:48.110+05:30"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1614769248:110779][31415:0x7f7353983140], txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Set global recovery timestamp: (0, 0)"}}
{"t":{"$date":"2021-03-03T16:30:48.110+05:30"},"s":"I",  "c":"STORAGE",  "id":22430,   "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1614769248:110843][31415:0x7f7353983140], txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Set global oldest timestamp: (0, 0)"}}
{"t":{"$date":"2021-03-03T16:30:48.133+05:30"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":705}}
{"t":{"$date":"2021-03-03T16:30:48.133+05:30"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2021-03-03T16:30:48.172+05:30"},"s":"I",  "c":"STORAGE",  "id":4366408, "ctx":"initandlisten","msg":"No table logging settings modifications are required for existing WiredTiger tables","attr":{"loggingEnabled":true}}
{"t":{"$date":"2021-03-03T16:30:48.173+05:30"},"s":"I",  "c":"STORAGE",  "id":22262,   "ctx":"initandlisten","msg":"Timestamp monitor starting"}
{"t":{"$date":"2021-03-03T16:30:48.194+05:30"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted. You can use percona-server-mongodb-enable-auth.sh to fix it","tags":["startupWarnings"]}
{"t":{"$date":"2021-03-03T16:30:48.195+05:30"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"admin.system.version","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"a2e15026-f7ad-46e9-a6a2-fbab04783983"}},"options":{"uuid":{"$uuid":"a2e15026-f7ad-46e9-a6a2-fbab04783983"}}}}
{"t":{"$date":"2021-03-03T16:30:48.232+05:30"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"admin.system.version","index":"_id_","commitTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2021-03-03T16:30:48.233+05:30"},"s":"I",  "c":"COMMAND",  "id":20459,   "ctx":"initandlisten","msg":"Setting featureCompatibilityVersion","attr":{"newVersion":"4.4"}}
{"t":{"$date":"2021-03-03T16:30:48.233+05:30"},"s":"I",  "c":"STORAGE",  "id":20536,   "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}
{"t":{"$date":"2021-03-03T16:30:48.235+05:30"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"initandlisten","msg":"createCollection","attr":{"namespace":"local.startup_log","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"adc01e95-a1fd-4a82-bdc7-31853fca3bff"}},"options":{"capped":true,"size":10485760}}}
{"t":{"$date":"2021-03-03T16:30:48.278+05:30"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"initandlisten","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"local.startup_log","index":"_id_","commitTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2021-03-03T16:30:48.279+05:30"},"s":"I",  "c":"FTDC",     "id":20625,   "ctx":"initandlisten","msg":"Initializing full-time diagnostic data capture","attr":{"dataDirectory":"/var/lib/mongodb/diagnostic.data"}}
{"t":{"$date":"2021-03-03T16:30:48.284+05:30"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"LogicalSessionCacheRefresh","msg":"createCollection","attr":{"namespace":"config.system.sessions","uuidDisposition":"generated","uuid":{"uuid":{"$uuid":"8d41b7a4-dbff-48a6-884c-979428faf754"}},"options":{}}}
{"t":{"$date":"2021-03-03T16:30:48.286+05:30"},"s":"I",  "c":"CONTROL",  "id":20712,   "ctx":"LogicalSessionCacheReap","msg":"Sessions collection is not set up; waiting until next sessions reap interval","attr":{"error":"NamespaceNotFound: config.system.sessions does not exist"}}
{"t":{"$date":"2021-03-03T16:30:48.287+05:30"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"/tmp/mongodb-27017.sock"}}
{"t":{"$date":"2021-03-03T16:30:48.287+05:30"},"s":"I",  "c":"NETWORK",  "id":23015,   "ctx":"listener","msg":"Listening on","attr":{"address":"127.0.0.1"}}
{"t":{"$date":"2021-03-03T16:30:48.287+05:30"},"s":"I",  "c":"NETWORK",  "id":23016,   "ctx":"listener","msg":"Waiting for connections","attr":{"port":27017,"ssl":"off"}}
{"t":{"$date":"2021-03-03T16:30:48.372+05:30"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"_id_","commitTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2021-03-03T16:30:48.372+05:30"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"LogicalSessionCacheRefresh","msg":"Index build: done building","attr":{"buildUUID":null,"namespace":"config.system.sessions","index":"lsidTTLIndex","commitTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2021-03-03T19:37:54.362+05:30"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:50894","connectionId":1,"connectionCount":1}}
{"t":{"$date":"2021-03-03T19:37:54.362+05:30"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn1","msg":"client metadata","attr":{"remote":"127.0.0.1:50894","client":"conn1","doc":{"application":{"name":"MongoDB Shell"},"driver":{"name":"MongoDB Internal Client","version":"4.4.4-6"},"os":{"type":"Linux","name":"Ubuntu","architecture":"x86_64","version":"18.04"}}}}
{"t":{"$date":"2021-03-04T16:01:05.011+05:30"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn1","msg":"Connection ended","attr":{"remote":"127.0.0.1:50894","connectionId":1,"connectionCount":0}}
{"t":{"$date":"2021-03-04T16:03:29.771+05:30"},"s":"I",  "c":"CONTROL",  "id":23377,   "ctx":"SignalHandler","msg":"Received signal","attr":{"signal":15,"error":"Terminated"}}
{"t":{"$date":"2021-03-04T16:03:29.771+05:30"},"s":"I",  "c":"CONTROL",  "id":23378,   "ctx":"SignalHandler","msg":"Signal was sent by kill(2)","attr":{"pid":1,"uid":0}}
{"t":{"$date":"2021-03-04T16:03:29.771+05:30"},"s":"I",  "c":"CONTROL",  "id":23381,   "ctx":"SignalHandler","msg":"will terminate after current cmd ends"}
{"t":{"$date":"2021-03-04T16:03:29.771+05:30"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"SignalHandler","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":10000}}
{"t":{"$date":"2021-03-04T16:03:29.772+05:30"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"SignalHandler","msg":"Shutting down the MirrorMaestro"}
{"t":{"$date":"2021-03-04T16:03:29.772+05:30"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"SignalHandler","msg":"Shutting down the WaitForMajorityService"}
{"t":{"$date":"2021-03-04T16:03:29.772+05:30"},"s":"I",  "c":"CONTROL",  "id":4784903, "ctx":"SignalHandler","msg":"Shutting down the LogicalSessionCache"}
{"t":{"$date":"2021-03-04T16:03:29.774+05:30"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"SignalHandler","msg":"Shutdown: going to close listening sockets"}
{"t":{"$date":"2021-03-04T16:03:29.774+05:30"},"s":"I",  "c":"NETWORK",  "id":23017,   "ctx":"listener","msg":"removing socket file","attr":{"path":"/tmp/mongodb-27017.sock"}}
{"t":{"$date":"2021-03-04T16:03:29.776+05:30"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"SignalHandler","msg":"Shutting down the global connection pool"}
{"t":{"$date":"2021-03-04T16:03:29.776+05:30"},"s":"I",  "c":"STORAGE",  "id":4784906, "ctx":"SignalHandler","msg":"Shutting down the FlowControlTicketholder"}
{"t":{"$date":"2021-03-04T16:03:29.776+05:30"},"s":"I",  "c":"-",        "id":20520,   "ctx":"SignalHandler","msg":"Stopping further Flow Control ticket acquisitions."}
{"t":{"$date":"2021-03-04T16:03:29.776+05:30"},"s":"I",  "c":"STORAGE",  "id":4784908, "ctx":"SignalHandler","msg":"Shutting down the PeriodicThreadToAbortExpiredTransactions"}
{"t":{"$date":"2021-03-04T16:03:29.777+05:30"},"s":"I",  "c":"STORAGE",  "id":4784934, "ctx":"SignalHandler","msg":"Shutting down the PeriodicThreadToDecreaseSnapshotHistoryCachePressure"}
{"t":{"$date":"2021-03-04T16:03:29.778+05:30"},"s":"I",  "c":"REPL",     "id":4784909, "ctx":"SignalHandler","msg":"Shutting down the ReplicationCoordinator"}
{"t":{"$date":"2021-03-04T16:03:29.778+05:30"},"s":"I",  "c":"SHARDING", "id":4784910, "ctx":"SignalHandler","msg":"Shutting down the ShardingInitializationMongoD"}
{"t":{"$date":"2021-03-04T16:03:29.778+05:30"},"s":"I",  "c":"REPL",     "id":4784911, "ctx":"SignalHandler","msg":"Enqueuing the ReplicationStateTransitionLock for shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.778+05:30"},"s":"I",  "c":"-",        "id":4784912, "ctx":"SignalHandler","msg":"Killing all operations for shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"-",        "id":4695300, "ctx":"SignalHandler","msg":"Interrupted all currently running operations","attr":{"opsKilled":3}}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"COMMAND",  "id":4784913, "ctx":"SignalHandler","msg":"Shutting down all open transactions"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"REPL",     "id":4784914, "ctx":"SignalHandler","msg":"Acquiring the ReplicationStateTransitionLock for shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"INDEX",    "id":4784915, "ctx":"SignalHandler","msg":"Shutting down the IndexBuildsCoordinator"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"REPL",     "id":4784916, "ctx":"SignalHandler","msg":"Reacquiring the ReplicationStateTransitionLock for shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"REPL",     "id":4784917, "ctx":"SignalHandler","msg":"Attempting to mark clean shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"SignalHandler","msg":"Shutting down the ReplicaSetMonitor"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"SignalHandler","msg":"Shutting down the MigrationUtilExecutor"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"CONTROL",  "id":4784925, "ctx":"SignalHandler","msg":"Shutting down free monitoring"}
{"t":{"$date":"2021-03-04T16:03:29.779+05:30"},"s":"I",  "c":"CONTROL",  "id":20609,   "ctx":"SignalHandler","msg":"Shutting down free monitoring"}
{"t":{"$date":"2021-03-04T16:03:29.782+05:30"},"s":"I",  "c":"STORAGE",  "id":4784927, "ctx":"SignalHandler","msg":"Shutting down the HealthLog"}
{"t":{"$date":"2021-03-04T16:03:29.782+05:30"},"s":"I",  "c":"STORAGE",  "id":4784929, "ctx":"SignalHandler","msg":"Acquiring the global lock for shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":4784930, "ctx":"SignalHandler","msg":"Shutting down the storage engine"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":20282,   "ctx":"SignalHandler","msg":"Deregistering all the collections"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":22261,   "ctx":"SignalHandler","msg":"Timestamp monitor shutting down"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":22317,   "ctx":"SignalHandler","msg":"WiredTigerKVEngine shutting down"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":22318,   "ctx":"SignalHandler","msg":"Shutting down session sweeper thread"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":22319,   "ctx":"SignalHandler","msg":"Finished shutting down session sweeper thread"}
{"t":{"$date":"2021-03-04T16:03:29.783+05:30"},"s":"I",  "c":"STORAGE",  "id":22320,   "ctx":"SignalHandler","msg":"Shutting down journal flusher thread"}
{"t":{"$date":"2021-03-04T16:03:29.784+05:30"},"s":"I",  "c":"STORAGE",  "id":22321,   "ctx":"SignalHandler","msg":"Finished shutting down journal flusher thread"}
{"t":{"$date":"2021-03-04T16:03:29.784+05:30"},"s":"I",  "c":"STORAGE",  "id":22322,   "ctx":"SignalHandler","msg":"Shutting down checkpoint thread"}
{"t":{"$date":"2021-03-04T16:03:29.790+05:30"},"s":"I",  "c":"STORAGE",  "id":22323,   "ctx":"SignalHandler","msg":"Finished shutting down checkpoint thread"}
{"t":{"$date":"2021-03-04T16:03:29.791+05:30"},"s":"I",  "c":"STORAGE",  "id":4795902, "ctx":"SignalHandler","msg":"Closing WiredTiger","attr":{"closeConfig":"leak_memory=true,"}}
{"t":{"$date":"2021-03-04T16:03:29.904+05:30"},"s":"I",  "c":"STORAGE",  "id":4795901, "ctx":"SignalHandler","msg":"WiredTiger closed","attr":{"durationMillis":113}}
{"t":{"$date":"2021-03-04T16:03:29.904+05:30"},"s":"I",  "c":"STORAGE",  "id":22279,   "ctx":"SignalHandler","msg":"shutdown: removing fs lock..."}
{"t":{"$date":"2021-03-04T16:03:29.905+05:30"},"s":"I",  "c":"-",        "id":4784931, "ctx":"SignalHandler","msg":"Dropping the scope cache for shutdown"}
{"t":{"$date":"2021-03-04T16:03:29.905+05:30"},"s":"I",  "c":"FTDC",     "id":4784926, "ctx":"SignalHandler","msg":"Shutting down full-time data capture"}
{"t":{"$date":"2021-03-04T16:03:29.905+05:30"},"s":"I",  "c":"FTDC",     "id":20626,   "ctx":"SignalHandler","msg":"Shutting down full-time diagnostic data capture"}
{"t":{"$date":"2021-03-04T16:03:29.915+05:30"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"SignalHandler","msg":"Now exiting"}
{"t":{"$date":"2021-03-04T16:03:29.915+05:30"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"SignalHandler","msg":"Shutting down","attr":{"exitCode":0}}
{"t":{"$date":"2021-03-04T16:03:30.057+05:30"},"s":"I",  "c":"CONTROL",  "id":20698,   "ctx":"main","msg":"***** SERVER RESTARTED *****"}
{"t":{"$date":"2021-03-04T16:03:30.063+05:30"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2021-03-04T16:03:30.066+05:30"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2021-03-04T16:03:30.066+05:30"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2021-03-04T16:03:30.066+05:30"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":2522,"port":27017,"dbPath":"/var/lib/mongodb","architecture":"64-bit","host":"test-VirtualBox"}}
{"t":{"$date":"2021-03-04T16:03:30.066+05:30"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.4-6","gitVersion":"f3dd4bc7c7500705a537de40bb4d6127ba498bd3","openSSLVersion":"OpenSSL 1.1.1  11 Sep 2018","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2021-03-04T16:03:30.066+05:30"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"18.04"}}}
{"t":{"$date":"2021-03-04T16:03:30.066+05:30"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongod.conf","net":{"bindIp":"127.0.0.1","port":27017},"processManagement":{"fork":true,"pidFilePath":"/var/run/mongod.pid"},"security":{"enableEncryption":true,"encryptionKeyFile":"/data/key/mongodb.key"},"storage":{"dbPath":"/var/lib/mongodb","journal":{"enabled":true}},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log"}}}}
{"t":{"$date":"2021-03-04T16:03:30.067+05:30"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongodb","storageEngine":"wiredTiger"}}
{"t":{"$date":"2021-03-04T16:03:30.067+05:30"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"E",  "c":"STORAGE",  "id":29038,   "ctx":"initandlisten","msg":"Exception in EncryptionKeyDB::init: {e}","attr":{"e":"cannot open specified encryption key file: /data/key/mongodb.key"}}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"E",  "c":"STORAGE",  "id":20558,   "ctx":"initandlisten","msg":"std::exception in initAndListen, terminating","attr":{"error":"cannot open specified encryption key file: /data/key/mongodb.key"}}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"initandlisten","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":10000}}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"initandlisten","msg":"Shutting down the MirrorMaestro"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"initandlisten","msg":"Shutting down the WaitForMajorityService"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"initandlisten","msg":"Shutdown: going to close listening sockets"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"initandlisten","msg":"Shutting down the global connection pool"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"STORAGE",  "id":4784906, "ctx":"initandlisten","msg":"Shutting down the FlowControlTicketholder"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"-",        "id":20520,   "ctx":"initandlisten","msg":"Stopping further Flow Control ticket acquisitions."}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"initandlisten","msg":"Shutting down the ReplicaSetMonitor"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"initandlisten","msg":"Shutting down the MigrationUtilExecutor"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"CONTROL",  "id":4784925, "ctx":"initandlisten","msg":"Shutting down free monitoring"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"STORAGE",  "id":4784927, "ctx":"initandlisten","msg":"Shutting down the HealthLog"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"STORAGE",  "id":4784929, "ctx":"initandlisten","msg":"Acquiring the global lock for shutdown"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"-",        "id":4784931, "ctx":"initandlisten","msg":"Dropping the scope cache for shutdown"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"FTDC",     "id":4784926, "ctx":"initandlisten","msg":"Shutting down full-time data capture"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"initandlisten","msg":"Now exiting"}
{"t":{"$date":"2021-03-04T16:03:30.068+05:30"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"initandlisten","msg":"Shutting down","attr":{"exitCode":100}}
1 Like

So here is the error:

“ctx”:“initandlisten”,“msg”:“Exception in EncryptionKeyDB::init: {e}”,“attr”:{“e”:“cannot open specified encryption key file: /data/key/mongodb.key”}}
{“t”:{"$date":“2021-03-04T16:03:30.068+05:30”},“s”:“E”, “c”:“STORAGE”, “id”:20558, “ctx”:“initandlisten”,“msg”:“std::exception in initAndListen, terminating”,“attr”:{“error”:“cannot open specified encryption key file: /data/key/mongodb.key”}}

Looks like the key is not where you say it is or mongod process does not have sufficient permissions to read the file:

cannot open specified encryption key file: /data/key/mongodb.key

1 Like

Even with full permission /data/ folder the same can’t start the service.

{"t":{"$date":"2021-03-04T19:46:10.241+05:30"},"s":"I",  "c":"CONTROL",  "id":20698,   "ctx":"main","msg":"***** SERVER RESTARTED *****"}
{"t":{"$date":"2021-03-04T19:46:10.243+05:30"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2021-03-04T19:46:10.251+05:30"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2021-03-04T19:46:10.251+05:30"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2021-03-04T19:46:10.252+05:30"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":4672,"port":27017,"dbPath":"/var/lib/mongodb","architecture":"64-bit","host":"test-VirtualBox"}}
{"t":{"$date":"2021-03-04T19:46:10.252+05:30"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.4-6","gitVersion":"f3dd4bc7c7500705a537de40bb4d6127ba498bd3","openSSLVersion":"OpenSSL 1.1.1  11 Sep 2018","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2021-03-04T19:46:10.253+05:30"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"18.04"}}}
{"t":{"$date":"2021-03-04T19:46:10.253+05:30"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongod.conf","net":{"bindIp":"127.0.0.1","port":27017},"processManagement":{"fork":true,"pidFilePath":"/var/run/mongod.pid"},"security":{"enableEncryption":true,"encryptionKeyFile":"/data/key/mongodb.key"},"storage":{"dbPath":"/var/lib/mongodb","journal":{"enabled":true}},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log"}}}}
{"t":{"$date":"2021-03-04T19:46:10.254+05:30"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongodb","storageEngine":"wiredTiger"}}
{"t":{"$date":"2021-03-04T19:46:10.255+05:30"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2021-03-04T19:46:10.255+05:30"},"s":"E",  "c":"STORAGE",  "id":29038,   "ctx":"initandlisten","msg":"Exception in EncryptionKeyDB::init: {e}","attr":{"e":"permissions on /data/key/mongodb.key are too open"}}
{"t":{"$date":"2021-03-04T19:46:10.256+05:30"},"s":"E",  "c":"STORAGE",  "id":20558,   "ctx":"initandlisten","msg":"std::exception in initAndListen, terminating","attr":{"error":"permissions on /data/key/mongodb.key are too open"}}
{"t":{"$date":"2021-03-04T19:46:10.256+05:30"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"initandlisten","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":10000}}
{"t":{"$date":"2021-03-04T19:46:10.257+05:30"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"initandlisten","msg":"Shutting down the MirrorMaestro"}
{"t":{"$date":"2021-03-04T19:46:10.257+05:30"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"initandlisten","msg":"Shutting down the WaitForMajorityService"}
{"t":{"$date":"2021-03-04T19:46:10.257+05:30"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"initandlisten","msg":"Shutdown: going to close listening sockets"}
{"t":{"$date":"2021-03-04T19:46:10.257+05:30"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"initandlisten","msg":"Shutting down the global connection pool"}
{"t":{"$date":"2021-03-04T19:46:10.257+05:30"},"s":"I",  "c":"STORAGE",  "id":4784906, "ctx":"initandlisten","msg":"Shutting down the FlowControlTicketholder"}
{"t":{"$date":"2021-03-04T19:46:10.258+05:30"},"s":"I",  "c":"-",        "id":20520,   "ctx":"initandlisten","msg":"Stopping further Flow Control ticket acquisitions."}
{"t":{"$date":"2021-03-04T19:46:10.258+05:30"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"initandlisten","msg":"Shutting down the ReplicaSetMonitor"}
{"t":{"$date":"2021-03-04T19:46:10.258+05:30"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"initandlisten","msg":"Shutting down the MigrationUtilExecutor"}
{"t":{"$date":"2021-03-04T19:46:10.258+05:30"},"s":"I",  "c":"CONTROL",  "id":4784925, "ctx":"initandlisten","msg":"Shutting down free monitoring"}
{"t":{"$date":"2021-03-04T19:46:10.259+05:30"},"s":"I",  "c":"STORAGE",  "id":4784927, "ctx":"initandlisten","msg":"Shutting down the HealthLog"}
{"t":{"$date":"2021-03-04T19:46:10.259+05:30"},"s":"I",  "c":"STORAGE",  "id":4784929, "ctx":"initandlisten","msg":"Acquiring the global lock for shutdown"}
{"t":{"$date":"2021-03-04T19:46:10.259+05:30"},"s":"I",  "c":"-",        "id":4784931, "ctx":"initandlisten","msg":"Dropping the scope cache for shutdown"}
{"t":{"$date":"2021-03-04T19:46:10.259+05:30"},"s":"I",  "c":"FTDC",     "id":4784926, "ctx":"initandlisten","msg":"Shutting down full-time data capture"}
{"t":{"$date":"2021-03-04T19:46:10.260+05:30"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"initandlisten","msg":"Now exiting"}
{"t":{"$date":"2021-03-04T19:46:10.260+05:30"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"initandlisten","msg":"Shutting down","attr":{"exitCode":100}}
1 Like

As you see now it is saying that permissions are too open:

{“t”:{"$date":“2021-03-04T19:46:10.255+05:30”},“s”:“E”, “c”:“STORAGE”, “id”:29038, “ctx”:“initandlisten”,“msg”:“Exception in EncryptionKeyDB::init: {e}”,“attr”:{“e”:“permissions on /data/key/mongodb.key are too open”}}
  1. Try setting permissions to 0600
    chmod 0600 /data/key/mongodb.key

  2. Set the user permissions correctly
    chown MONGOD_USER /data/key/mongodb.key

  3. Verify if the key is correct in the file. What I mean, if you were copy/pasting it, check if it has all the data.

2 Likes

Still same issue
test@test-VirtualBox:~ sudo cat /data/key/mongodb.key jSzJ6KBOe5YsH5wSP4OsB+RUMfwdvKF9+j4wLEkMONs= test@test-VirtualBox:~ ll /data/key/mongodb.key
-rw------- 1 mongod mongod 45 Mar 3 12:45 /data/key/mongodb.key

#######################################################
Please share any link that show how to work with percona mongodb with vault
with all steps

1 Like

To add a third pair of eyes:

I see you’re using a local keyfile, which is a testing-only sort of thing to do. This is fine as a test though.

As it says the PMSDB documentation Data at Rest Encryption the file should be 600 or 400 file mode, and you’ve shown that it is.

The error though is clearly from this check in the code:

relaxPermChecks will be false, so feel free to ignore that little block in the middle.

The filemode mask S_IRWXG is only about group user (which you’ve given no perms to) and likewise for S_IRWO is for “other” user (again there is no perms).

So I don’t see why it rejects. Could you please restart one more time?

1 Like

Same when Restart

{"t":{"$date":"2021-03-05T19:45:41.080+05:30"},"s":"I",  "c":"CONTROL",  "id":20698,   "ctx":"main","msg":"***** SERVER RESTARTED *****"}
{"t":{"$date":"2021-03-05T19:45:41.086+05:30"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2021-03-05T19:45:41.088+05:30"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2021-03-05T19:45:41.089+05:30"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2021-03-05T19:45:41.089+05:30"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":4642,"port":27017,"dbPath":"/var/lib/mongodb","architecture":"64-bit","host":"test-VirtualBox"}}
{"t":{"$date":"2021-03-05T19:45:41.089+05:30"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.4-6","gitVersion":"f3dd4bc7c7500705a537de40bb4d6127ba498bd3","openSSLVersion":"OpenSSL 1.1.1  11 Sep 2018","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2021-03-05T19:45:41.090+05:30"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"18.04"}}}
{"t":{"$date":"2021-03-05T19:45:41.090+05:30"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongod.conf","net":{"bindIp":"127.0.0.1","port":27017},"processManagement":{"fork":true,"pidFilePath":"/var/run/mongod.pid"},"security":{"enableEncryption":true,"encryptionKeyFile":"/data/key/mongodb.key"},"storage":{"dbPath":"/var/lib/mongodb","journal":{"enabled":true}},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log"}}}}
{"t":{"$date":"2021-03-05T19:45:41.091+05:30"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongodb","storageEngine":"wiredTiger"}}
{"t":{"$date":"2021-03-05T19:45:41.091+05:30"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2021-03-05T19:45:41.092+05:30"},"s":"I",  "c":"STORAGE",  "id":29037,   "ctx":"initandlisten","msg":"Initializing KeyDB with wiredtiger_open config: {cfg}","attr":{"cfg":"create,config_base=false,extensions=[local=(entry=percona_encryption_extension_init,early_load=true,config=(cipher=AES256-CBC,rotation=false))],encryption=(name=percona,keyid=\"\"),log=(enabled,file_max=5MB),transaction_sync=(enabled=true,method=fsync),"}}
{"t":{"$date":"2021-03-05T19:45:41.825+05:30"},"s":"I",  "c":"STORAGE",  "id":29039,   "ctx":"initandlisten","msg":"Encryption keys DB is initialized successfully"}
{"t":{"$date":"2021-03-05T19:45:41.826+05:30"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=1456M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],encryption=(name=percona,keyid=\"/default\"),extensions=[local=(entry=percona_encryption_extension_init,early_load=true,config=(cipher=AES256-CBC)),],"}}
{"t":{"$date":"2021-03-05T19:45:41.853+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:852972][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 606: unable to read root page from file:WiredTiger.wt: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.853+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:853443][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 612: WiredTiger has failed to open its metadata: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.853+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:853703][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 615: This may be due to the database files being encrypted, being from an older version or due to corruption on disk: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.853+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:853940][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 618: You should confirm that you have opened the database with the correct options including all encryption and compression options: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.861+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:861745][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 606: unable to read root page from file:WiredTiger.wt: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.862+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:862103][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 612: WiredTiger has failed to open its metadata: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.862+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:862357][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 615: This may be due to the database files being encrypted, being from an older version or due to corruption on disk: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.862+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:862604][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 618: You should confirm that you have opened the database with the correct options including all encryption and compression options: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.872+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:872037][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 606: unable to read root page from file:WiredTiger.wt: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.872+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:872496][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 612: WiredTiger has failed to open its metadata: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.872+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:872763][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 615: This may be due to the database files being encrypted, being from an older version or due to corruption on disk: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.872+05:30"},"s":"E",  "c":"STORAGE",  "id":22435,   "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":-31802,"message":"[1614953741:872987][4642:0x7ff015644140], file:WiredTiger.wt, connection: __wt_btree_tree_open, 618: You should confirm that you have opened the database with the correct options including all encryption and compression options: WT_ERROR: non-specific WiredTiger error"}}
{"t":{"$date":"2021-03-05T19:45:41.874+05:30"},"s":"W",  "c":"STORAGE",  "id":22347,   "ctx":"initandlisten","msg":"Failed to start up WiredTiger under any compatibility version. This may be due to an unsupported upgrade or downgrade."}
{"t":{"$date":"2021-03-05T19:45:41.875+05:30"},"s":"W",  "c":"STORAGE",  "id":22348,   "ctx":"initandlisten","msg":"WiredTiger metadata corruption detected"}
{"t":{"$date":"2021-03-05T19:45:41.875+05:30"},"s":"F",  "c":"STORAGE",  "id":50944,   "ctx":"initandlisten","msg":"Please read the documentation for starting MongoDB with --repair here: http://dochub.mongodb.org/core/repair"}
{"t":{"$date":"2021-03-05T19:45:41.875+05:30"},"s":"F",  "c":"-",        "id":23091,   "ctx":"initandlisten","msg":"Fatal assertion","attr":{"msgid":50944,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp","line":1293}}
{"t":{"$date":"2021-03-05T19:45:41.875+05:30"},"s":"F",  "c":"-",        "id":23092,   "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"}
1 Like

Hi Vijendra.

Actually it seems that it succeeded in overcoming the “Exception in EncryptionKeyDB::init: {e}” problem when you restarted. It moved on and shows “Initializing KeyDB with wiredtiger_open config: {cfg}” instead. So that is progress.

The error you’re at now is: having loaded a key it finds existing WiredTiger data files and tries to decrypt them.

Trying to use keys with existing data files that were made without encryption won’t work. You get the error you see above (“unable to read root page from file” + “This may be due to the database files being encrypted”).

When you first enable the keys you should restart with an empty db directory path. Which means restart in an existing replicaset to sync existing database collections from the other members that haven’t begun to use data-at-rest encryption yet. Or making a new, empty replica set.

1 Like

I have similar issue and below is the logs

{"t":{"$date":"2021-05-19T07:40:29.288+01:00"},"s":"I",  "c":"CONTROL",  "id":20698,   "ctx":"main","msg":"***** SERVER RESTARTED *****"}
{"t":{"$date":"2021-05-19T07:40:29.292+01:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2021-05-19T07:40:29.303+01:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2021-05-19T07:40:29.304+01:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2021-05-19T07:40:29.306+01:00"},"s":"I",  "c":"STORAGE",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":19556,"port":27017,"dbPath":"/var/lib/mongodb","architecture":"64-bit","host":"earth"}}
{"t":{"$date":"2021-05-19T07:40:29.306+01:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.5-7","gitVersion":"7961a01b5c2f3666c0a15a491c7b049badfa5eda","openSSLVersion":"OpenSSL 1.1.1  11 Sep 2018","modules":[],"allocator":"tcmalloc","environment":{"distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2021-05-19T07:40:29.306+01:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"18.04"}}}
{"t":{"$date":"2021-05-19T07:40:29.306+01:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongod.conf","net":{"bindIp":"127.0.0.1","port":27017},"processManagement":{"fork":true,"pidFilePath":"/var/run/mongod.pid"},"security":{"enableEncryption":true,"encryptionKeyFile":"~/mongodb-secret-keyfile"},"storage":{"dbPath":"/var/lib/mongodb","journal":{"enabled":true}},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log"}}}}
{"t":{"$date":"2021-05-19T07:40:29.311+01:00"},"s":"I",  "c":"STORAGE",  "id":22297,   "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
{"t":{"$date":"2021-05-19T07:40:29.312+01:00"},"s":"E",  "c":"STORAGE",  "id":29038,   "ctx":"initandlisten","msg":"Exception in EncryptionKeyDB::init: {e}","attr":{"e":"cannot read stats of encryption key file: ~/mongodb-secret-keyfile: No such file or directory"}}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"E",  "c":"STORAGE",  "id":20558,   "ctx":"initandlisten","msg":"std::exception in initAndListen, terminating","attr":{"error":"cannot read stats of encryption key file: ~/mongodb-secret-keyfile: No such file or directory"}}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"initandlisten","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":10000}}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"initandlisten","msg":"Shutting down the MirrorMaestro"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"initandlisten","msg":"Shutting down the WaitForMajorityService"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"initandlisten","msg":"Shutdown: going to close listening sockets"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"initandlisten","msg":"Shutting down the global connection pool"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"STORAGE",  "id":4784906, "ctx":"initandlisten","msg":"Shutting down the FlowControlTicketholder"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"-",        "id":20520,   "ctx":"initandlisten","msg":"Stopping further Flow Control ticket acquisitions."}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"initandlisten","msg":"Shutting down the ReplicaSetMonitor"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"initandlisten","msg":"Shutting down the MigrationUtilExecutor"}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"I",  "c":"CONTROL",  "id":4784925, "ctx":"initandlisten","msg":"Shutting down free monitoring"}
{"t":{"$date":"2021-05-19T07:40:29.314+01:00"},"s":"I",  "c":"STORAGE",  "id":4784927, "ctx":"initandlisten","msg":"Shutting down the HealthLog"}
{"t":{"$date":"2021-05-19T07:40:29.314+01:00"},"s":"I",  "c":"STORAGE",  "id":4784929, "ctx":"initandlisten","msg":"Acquiring the global lock for shutdown"}
{"t":{"$date":"2021-05-19T07:40:29.314+01:00"},"s":"I",  "c":"-",        "id":4784931, "ctx":"initandlisten","msg":"Dropping the scope cache for shutdown"}
{"t":{"$date":"2021-05-19T07:40:29.314+01:00"},"s":"I",  "c":"FTDC",     "id":4784926, "ctx":"initandlisten","msg":"Shutting down full-time data capture"}
{"t":{"$date":"2021-05-19T07:40:29.314+01:00"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"initandlisten","msg":"Now exiting"}
{"t":{"$date":"2021-05-19T07:40:29.314+01:00"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"initandlisten","msg":"Shutting down","attr":{"exitCode":100}}

It seems this is the error but I checked and the files exist and with correct permissions

"ctx":"initandlisten","msg":"Exception in EncryptionKeyDB::init: {e}","attr":{"e":"cannot read stats of encryption key file: ~/mongodb-secret-keyfile: No such file or directory"}}
{"t":{"$date":"2021-05-19T07:40:29.313+01:00"},"s":"E",  "c":"STORAGE",  "id":20558,   "ctx":"initandlisten","msg":"std::exception in initAndListen, terminating","attr":{"error":"cannot read stats of encryption key file: ~/mongodb-secret-keyfile: No such file or directory"}}

Secret Key Permission

>  ~  ls -l ~/mongodb-secret-keyfile
-rw------- 1 mongod mongod 45 May 19 07:35 /home/something/mongodb-secret-keyfile

1 Like

Strangely it worked after moving key inside the folder

~/mongoSSL/mongodb-secret-keyfile

It would be nice if someone can tell me the reason for this…

1 Like

I’m guessing that it is directory permission issue. Eg. The “mongod” user doesn’t have the x permission on /home/something, so it can’t list files, but it could list /home/something/mongoSSL.

(For other readers please note: SSL/TLS and data-at-rest encryption are not related. This is not a TLS-related post.)

1 Like

Yes that’s correct it is home directory and mongod user does not have required permission to do that. Thanks for clarification

1 Like

So, what is the final solution though? Seems I faced this issue too on percona mongodb 4.4.6-8

1 Like

btw, I use the docker container to start my mongodb service

1 Like

use the user “1000” to run the container fixed this issue for me

1 Like

Thanks for sharing that detailed tip Wenjian!

Akira

1 Like