Percona MongoDB with vault

vijendra · March 3, 2021, 9:50am

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

Sergey_Pronin · March 4, 2021, 8:56am

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?

vijendra · March 4, 2021, 10:42am

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.

Sergey_Pronin · March 4, 2021, 11:54am

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”?

vijendra · March 4, 2021, 1:26pm

{"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}}

Sergey_Pronin · March 4, 2021, 1:43pm

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

vijendra · March 4, 2021, 2:16pm

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}}

Sergey_Pronin · March 4, 2021, 9:15pm

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”}}

Try setting permissions to 0600
chmod 0600 /data/key/mongodb.key
Set the user permissions correctly
chown MONGOD_USER /data/key/mongodb.key
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.

vijendra · March 5, 2021, 9:50am

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

Akira_Kurogane · March 5, 2021, 12:39pm

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 https://www.percona.com/doc/percona-server-for-mongodb/LATEST/data_at_rest_encryption.html#local-key-management-using-a-keyfile 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:

github.com

percona/percona-server-mongodb/blob/b8c425c5d2b9c5c96575c4b33a123c7409500c25/src/mongo/db/storage/wiredtiger/encryption_keydb.cpp#L200-L208


      
          auto prohibited_perms{S_IRWXG | S_IRWXO};
          if (serverGlobalParams.relaxPermChecks && stats.st_uid == 0) {
              prohibited_perms = S_IWGRP | S_IXGRP | S_IRWXO;
          }
          if ((stats.st_mode & prohibited_perms) != 0) {
              throw std::runtime_error(str::stream()
                                       << "permissions on " << encryptionGlobalParams.encryptionKeyFile
                                       << " are too open");
          }

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?

vijendra · March 5, 2021, 2:16pm

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"}

Akira_Kurogane · March 9, 2021, 12:37pm

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.

Vineet_Kumar · May 19, 2021, 7:04am

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

Vineet_Kumar · May 19, 2021, 7:25am

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…

Akira_Kurogane · May 19, 2021, 11:13am

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.)

Vineet_Kumar · May 20, 2021, 4:26am

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

wenjian · July 15, 2021, 7:37am

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

wenjian · July 15, 2021, 7:39am

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

wenjian · July 15, 2021, 8:33am

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

Akira_Kurogane · July 15, 2021, 9:08am

Thanks for sharing that detailed tip Wenjian!

Akira

Topic		Replies	Views
Percona MongoDB with vault in ubuntu Percona Server for MongoDB percona	5	1544	April 12, 2021
How to Test encryption at rest with vault mongodb percona Percona Server for MongoDB closed-no-reply	0	510	March 24, 2021
MongoDb dump needs to restore on percona mongoDB with encrypation Percona Server for MongoDB	1	653	August 13, 2021
Test encryption at rest with vault Percona Server for MongoDB	1	589	June 11, 2021
Data at rest encryption - Percona Operator for MongoDB Percona Distribution for MongoDB	1	693	January 21, 2023

Percona MongoDB with vault

Related topics