[SERVER-29970] mongodb database file WiredTiger.wt: encountered an illegal file format or internal value Created: 04/Jul/17  Updated: 16/Aug/18  Resolved: 05/Jul/17

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: 3.2.14
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: filipe silva Assignee: Kelsey Schubert
Resolution: Done Votes: 0
Labels: envm, rpo, rps, trcf, wtc
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: HTML File WiredTiger     File WiredTiger.lock     File WiredTiger.turtle     File WiredTiger.wt     File WiredTigerLAS.wt     File _mdb_catalog.wt     Text File repair.log     File repair_attempt.tar.gz     File sizeStorer.wt     File storage.bson    
Operating System: Linux
Steps To Reproduce:

power loss.

Participants:

 Description   

Hi.
After a unexpected power loss on my hostage provider my mongodb database was not working.
I already tried the repair and remove locked files as suggested from my google searches, but didn't work.
Here I leave the files for anyone who can help me repair this.
thank you.

2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] MongoDB starting : pid=5694 port=27017 dbpath=/var/lib/mongodb 64-bit host=napalm
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] db version v3.2.14
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] git version: 92f6668a768ebf294bd4f494c50f48459198e6a3
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] allocator: tcmalloc
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] modules: none
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] build environment:
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten]     distmod: ubuntu1604
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten]     distarch: x86_64
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten]     target_arch: x86_64
2017-07-04T17:13:36.313+0100 I CONTROL  [initandlisten] options: { repair: true, storage: { dbPath: "/var/lib/mongodb" } }
2017-07-04T17:13:36.337+0100 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-07-04T17:13:36.337+0100 I STORAGE  [initandlisten] Detected WT journal files.  Running recovery from last checkpoint.
2017-07-04T17:13:36.337+0100 I STORAGE  [initandlisten] journal to nojournal transition config: create,cache_size=1G,session_max=20000,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),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-07-04T17:13:36.394+0100 E STORAGE  [initandlisten] WiredTiger (0) [1499184816:394726][5694:0x7fc59e429c80], file:WiredTiger.wt, WT_CURSOR.insert: read checksum error for 24576B block at offset 16384: block header checksum of 1814037912 doesn't match expected checksum of 1064729368
2017-07-04T17:13:36.394+0100 E STORAGE  [initandlisten] WiredTiger (0) [1499184816:394789][5694:0x7fc59e429c80], file:WiredTiger.wt, WT_CURSOR.insert: WiredTiger.wt: encountered an illegal file format or internal value
2017-07-04T17:13:36.394+0100 E STORAGE  [initandlisten] WiredTiger (-31804) [1499184816:394807][5694:0x7fc59e429c80], file:WiredTiger.wt, WT_CURSOR.insert: the process must exit and restart: WT_PANIC: WiredTiger library panic
2017-07-04T17:13:36.394+0100 I -        [initandlisten] Fatal Assertion 28558
2017-07-04T17:13:36.394+0100 I -        [initandlisten] 
 
***aborting after fassert() failure
 
 
2017-07-04T17:13:36.412+0100 F -        [initandlisten] Got signal: 6 (Aborted).
 
 0x154e4f2 0x154d499 0x154dd02 0x7fc59d02f390 0x7fc59cc89428 0x7fc59cc8b02a 0x14cb733 0x126e2da 0x97b1e3 0x97b3c9 0x97b58f 0x1b94e95 0x1bae3cb 0x1bb5384 0x1bd5c40 0x1ba46d2 0x1bf19b4 0x1c7d4fe 0x1c16cca 0x1c7df98 0x1be85b7 0x1be0e35 0x1251e3a 0x124b1e5 0x114640e 0x9c7b31 0x97c35a 0x7fc59cc74830 0x9c2e29
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"114E4F2","s":"_ZN5mongo15printStackTraceERSo"},{"b":"400000","o":"114D499"},{"b":"400000","o":"114DD02"},{"b":"7FC59D01E000","o":"11390"},{"b":"7FC59CC54000","o":"35428","s":"gsignal"},{"b":"7FC59CC54000","o":"3702A","s":"abort"},{"b":"400000","o":"10CB733","s":"_ZN5mongo13fassertFailedEi"},{"b":"400000","o":"E6E2DA"},{"b":"400000","o":"57B1E3","s":"__wt_eventv"},{"b":"400000","o":"57B3C9","s":"__wt_err"},{"b":"400000","o":"57B58F","s":"__wt_panic"},{"b":"400000","o":"1794E95","s":"__wt_bm_read"},{"b":"400000","o":"17AE3CB","s":"__wt_bt_read"},{"b":"400000","o":"17B5384","s":"__wt_page_in_func"},{"b":"400000","o":"17D5C40","s":"__wt_row_search"},{"b":"400000","o":"17A46D2","s":"__wt_btcur_insert"},{"b":"400000","o":"17F19B4"},{"b":"400000","o":"187D4FE"},{"b":"400000","o":"1816CCA","s":"__wt_log_scan"},{"b":"400000","o":"187DF98","s":"__wt_txn_recover"},{"b":"400000","o":"17E85B7","s":"__wt_connection_workers"},{"b":"400000","o":"17E0E35","s":"wiredtiger_open"},{"b":"400000","o":"E51E3A","s":"_ZN5mongo18WiredTigerKVEngineC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES8_S8_mbbb"},{"b":"400000","o":"E4B1E5"},{"b":"400000","o":"D4640E","s":"_ZN5mongo20ServiceContextMongoD29initializeGlobalStorageEngineEv"},{"b":"400000","o":"5C7B31"},{"b":"400000","o":"57C35A","s":"main"},{"b":"7FC59CC54000","o":"20830","s":"__libc_start_main"},{"b":"400000","o":"5C2E29","s":"_start"}],"processInfo":{ "mongodbVersion" : "3.2.14", "gitVersion" : "92f6668a768ebf294bd4f494c50f48459198e6a3", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "4.4.0-81-generic", "version" : "#104-Ubuntu SMP Wed Jun 14 08:17:06 UTC 2017", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "B04D4C2514E2C891B5791D71A8F4246ECADF157D" }, { "b" : "7FFC51DD5000", "elfType" : 3, "buildId" : "324AC75434EC60709DEFA00F991DBCAB9848D1D5" }, { "b" : "7FC59DFAA000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "675F454AD6FD0B6CA2E41127C7B98079DA37F7B6" }, { "b" : "7FC59DB66000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "2DA08A7E5BF610030DD33B70DB951399626B7496" }, { "b" : "7FC59D95E000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "F951C1E0765FCAE48F82CAFE35D1ADD36D6C9AF9" }, { "b" : "7FC59D75A000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "0FC788F0861846257B5F1773FBD438E95DFC1032" }, { "b" : "7FC59D451000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "FF7A33D389E756CA381A8189291A968EA5E1F4F8" }, { "b" : "7FC59D23B000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "68220AE2C65D65C1B6AAA12FA6765A6EC2F5F434" }, { "b" : "7FC59D01E000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "27F189EF8DB8C3734C6A678E6EF3CB0B206D58B2" }, { "b" : "7FC59CC54000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "088A6E00A1814622219F346B41E775B8DD46C518" }, { "b" : "7FC59E213000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9157F205547F0EB588E2AB1F2F120B74253A43EA" } ] }}
 mongod(_ZN5mongo15printStackTraceERSo+0x32) [0x154e4f2]
 mongod(+0x114D499) [0x154d499]
 mongod(+0x114DD02) [0x154dd02]
 libpthread.so.0(+0x11390) [0x7fc59d02f390]
 libc.so.6(gsignal+0x38) [0x7fc59cc89428]
 libc.so.6(abort+0x16A) [0x7fc59cc8b02a]
 mongod(_ZN5mongo13fassertFailedEi+0x93) [0x14cb733]
 mongod(+0xE6E2DA) [0x126e2da]
 mongod(__wt_eventv+0x3BA) [0x97b1e3]
 mongod(__wt_err+0x8B) [0x97b3c9]
 mongod(__wt_panic+0x24) [0x97b58f]
 mongod(__wt_bm_read+0x115) [0x1b94e95]
 mongod(__wt_bt_read+0x1DB) [0x1bae3cb]
 mongod(__wt_page_in_func+0x11E4) [0x1bb5384]
 mongod(__wt_row_search+0x640) [0x1bd5c40]
 mongod(__wt_btcur_insert+0xB42) [0x1ba46d2]
 mongod(+0x17F19B4) [0x1bf19b4]
 mongod(+0x187D4FE) [0x1c7d4fe]
 mongod(__wt_log_scan+0xC4A) [0x1c16cca]
 mongod(__wt_txn_recover+0x348) [0x1c7df98]
 mongod(__wt_connection_workers+0x37) [0x1be85b7]
 mongod(wiredtiger_open+0x18F5) [0x1be0e35]
 mongod(_ZN5mongo18WiredTigerKVEngineC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES8_S8_mbbb+0xBDA) [0x1251e3a]
 mongod(+0xE4B1E5) [0x124b1e5]
 mongod(_ZN5mongo20ServiceContextMongoD29initializeGlobalStorageEngineEv+0x3EE) [0x114640e]
 mongod(+0x5C7B31) [0x9c7b31]
 mongod(main+0x73A) [0x97c35a]
 libc.so.6(__libc_start_main+0xF0) [0x7fc59cc74830]
 mongod(_start+0x29) [0x9c2e29]
-----  END BACKTRACE  -----



 Comments   
Comment by Kelsey Schubert [ 05/Jul/17 ]

Hi napalmd,

Glad to hear that the repair attempt was successful. Yes, I'd recommend reviewing our documentation

Please note that SERVER project is for reporting bugs or feature suggestions for the MongoDB server. For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag. A question like this involving more discussion would be best posted on the mongodb-users group.

Kind regards,
Thomas

Comment by filipe silva [ 05/Jul/17 ]

Database seems to be ok, it is just for my pritunl vpn server, and it is now running fine.
Now what's the best way for a backup? Or I'll check it in the docs...
Thanks again!

Comment by filipe silva [ 05/Jul/17 ]

Yes I noticed that and deleted the lock files before starting mongod but made no difference.
Then I noticed a lot of the database files were owned by root, and I think they might have changed when I made the repair or something...
I did a chown -hR mongodb:mongodb , deleted the lock files and started mongod and it worked, it is running now.
I'll check now if the database is ok...
Thanks.

Comment by Kelsey Schubert [ 05/Jul/17 ]

These error messages suggest that another process (likely another mongod instance) may be accessing these files? Would you please resolve the permission error by ensuring no other processes are active?

Thanks,
Thomas

Comment by filipe silva [ 05/Jul/17 ]

Thanks for replying.
I replaced the files, made repair, and then started mongod, but didn't work.
About your questions:
1. This is a VPS I think they use some kind of raid...
2. fsck said volume is clean
3. I was running 3.2.12 and just now updated to .14 to see if it would repair the error.
4. never manipulated the database files.
5. never restored from backups
6. was not doing backup
7. don't know

here are the logs
repair:

2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] MongoDB starting : pid=12028 port=27017 dbpath=/var/lib/mongodb 64-bit host=napalm
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] db version v3.2.14
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] git version: 92f6668a768ebf294bd4f494c50f48459198e6a3
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] allocator: tcmalloc
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] modules: none
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] build environment:
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten]     distmod: ubuntu1604
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten]     distarch: x86_64
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten]     target_arch: x86_64
2017-07-05T21:55:27.553+0100 I CONTROL  [initandlisten] options: { repair: true, storage: { dbPath: "/var/lib/mongodb" } }
2017-07-05T21:55:27.587+0100 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-07-05T21:55:27.587+0100 I STORAGE  [initandlisten] Detected WT journal files.  Running recovery from last checkpoint.
2017-07-05T21:55:27.587+0100 I STORAGE  [initandlisten] journal to nojournal transition config: create,cache_size=1G,session_max=20000,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),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-07-05T21:55:27.908+0100 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,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),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),,log=(enabled=false),
2017-07-05T21:55:28.220+0100 I STORAGE  [initandlisten] Repairing size cache
2017-07-05T21:55:28.232+0100 E STORAGE  [initandlisten] WiredTiger (-31802) [1499288128:232181][12028:0x7ffa0fdd1c80], file:sizeStorer.wt, WT_SESSION.verify: unable to read root page from file:sizeStorer.wt: WT_ERROR: non-specific WiredTiger error
2017-07-05T21:55:28.232+0100 E STORAGE  [initandlisten] WiredTiger (0) [1499288128:232224][12028:0x7ffa0fdd1c80], file:sizeStorer.wt, WT_SESSION.verify: file ranges never verified: 1
2017-07-05T21:55:28.232+0100 I STORAGE  [initandlisten] Verify failed on uri table:sizeStorer. Running a salvage operation.
2017-07-05T21:55:28.235+0100 I STORAGE  [initandlisten] Repairing catalog metadata
2017-07-05T21:55:28.245+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:_mdb_catalog. Not salvaging.
2017-07-05T21:55:28.380+0100 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2017-07-05T21:55:28.380+0100 I CONTROL  [initandlisten] 
2017-07-05T21:55:28.380+0100 I CONTROL  [initandlisten] 
2017-07-05T21:55:28.380+0100 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2017-07-05T21:55:28.380+0100 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2017-07-05T21:55:28.381+0100 I CONTROL  [initandlisten] 
2017-07-05T21:55:28.381+0100 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2017-07-05T21:55:28.381+0100 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2017-07-05T21:55:28.381+0100 I CONTROL  [initandlisten] 
2017-07-05T21:55:28.508+0100 I STORAGE  [initandlisten] repairDatabase local
2017-07-05T21:55:28.508+0100 I STORAGE  [initandlisten] Repairing collection local.startup_log
2017-07-05T21:55:28.541+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:collection-0--1621018067372228548. Not salvaging.
2017-07-05T21:55:28.684+0100 I INDEX    [initandlisten] build index on: local.startup_log properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.startup_log" }
2017-07-05T21:55:28.688+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2017-07-05T21:55:28.726+0100 I STORAGE  [initandlisten] repairDatabase pritunl
2017-07-05T21:55:28.726+0100 I STORAGE  [initandlisten] Repairing collection pritunl.administrators
2017-07-05T21:55:28.742+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:collection-24--1621018067372228548. Not salvaging.
2017-07-05T21:55:28.751+0100 I INDEX    [initandlisten] build index on: pritunl.administrators properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "pritunl.administrators" }
2017-07-05T21:55:28.751+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-07-05T21:55:28.757+0100 I INDEX    [initandlisten] build index on: pritunl.administrators properties: { v: 1, unique: true, key: { username: 1 }, name: "username_1", ns: "pritunl.administrators", background: true }
2017-07-05T21:55:28.757+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-07-05T21:55:28.767+0100 I STORAGE  [initandlisten] Repairing collection pritunl.auth_csrf_tokens
2017-07-05T21:55:28.769+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:collection-132--1621018067372228548. Not salvaging.
2017-07-05T21:55:28.787+0100 I INDEX    [initandlisten] build index on: pritunl.auth_csrf_tokens properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "pritunl.auth_csrf_tokens" }
2017-07-05T21:55:28.787+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2017-07-05T21:55:28.792+0100 I STORAGE  [initandlisten] Repairing collection pritunl.auth_limiter
 
36--1621018067372228548. Not salvaging.
2017-07-05T21:55:31.817+0100 I INDEX    [initandlisten] build index on: pritunl.users_key_link properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "pritunl.users_key_link" }
2017-07-05T21:55:31.817+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.822+0100 I INDEX    [initandlisten] build index on: pritunl.users_key_link properties: { v: 1, key: { key_id: 1 }, name: "key_id_1", ns: "pritunl.users_key_link", background: true }
2017-07-05T21:55:31.822+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.827+0100 I INDEX    [initandlisten] build index on: pritunl.users_key_link properties: { v: 1, unique: true, key: { short_id: 1 }, name: "short_id_1", ns: "pritunl.users_key_link", background: true }
2017-07-05T21:55:31.827+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.842+0100 I INDEX    [initandlisten] build index on: pritunl.users_key_link properties: { v: 1, key: { timestamp: 1 }, name: "timestamp_1", ns: "pritunl.users_key_link", expireAfterSeconds: 86400, background: true }
2017-07-05T21:55:31.842+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.876+0100 I STORAGE  [initandlisten] Repairing collection pritunl.users_net_link
2017-07-05T21:55:31.877+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:collection-40--1621018067372228548. Not salvaging.
2017-07-05T21:55:31.902+0100 I INDEX    [initandlisten] build index on: pritunl.users_net_link properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "pritunl.users_net_link" }
2017-07-05T21:55:31.902+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.938+0100 I INDEX    [initandlisten] build index on: pritunl.users_net_link properties: { v: 1, key: { user_id: 1 }, name: "user_id_1", ns: "pritunl.users_net_link", background: true }
2017-07-05T21:55:31.938+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.943+0100 I INDEX    [initandlisten] build index on: pritunl.users_net_link properties: { v: 1, key: { org_id: 1 }, name: "org_id_1", ns: "pritunl.users_net_link", background: true }
2017-07-05T21:55:31.943+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.948+0100 I INDEX    [initandlisten] build index on: pritunl.users_net_link properties: { v: 1, key: { network: 1 }, name: "network_1", ns: "pritunl.users_net_link", background: true }
2017-07-05T21:55:31.948+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 125 megabytes of RAM
2017-07-05T21:55:31.966+0100 I STORAGE  [initandlisten] Repairing collection pritunl.vxlans
2017-07-05T21:55:31.972+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:collection-106--1621018067372228548. Not salvaging.
2017-07-05T21:55:31.979+0100 I INDEX    [initandlisten] build index on: pritunl.vxlans properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "pritunl.vxlans" }
2017-07-05T21:55:31.979+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-07-05T21:55:31.999+0100 I INDEX    [initandlisten] build index on: pritunl.vxlans properties: { v: 1, unique: true, key: { server_id: 1 }, name: "server_id_1", ns: "pritunl.vxlans", background: true }
2017-07-05T21:55:31.999+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-07-05T21:55:32.007+0100 I STORAGE  [initandlisten] Repairing collection pritunl.yubikey
2017-07-05T21:55:32.008+0100 I STORAGE  [initandlisten] Verify succeeded on uri table:collection-123--1621018067372228548. Not salvaging.
2017-07-05T21:55:32.034+0100 I INDEX    [initandlisten] build index on: pritunl.yubikey properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "pritunl.yubikey" }
2017-07-05T21:55:32.034+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-07-05T21:55:32.040+0100 I INDEX    [initandlisten] build index on: pritunl.yubikey properties: { v: 1, key: { timestamp: 1 }, name: "timestamp_1", ns: "pritunl.yubikey", expireAfterSeconds: 86400, background: true }
2017-07-05T21:55:32.040+0100 I INDEX    [initandlisten] 	 building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-07-05T21:55:32.195+0100 I STORAGE  [initandlisten] finished checking dbs
2017-07-05T21:55:32.195+0100 I CONTROL  [initandlisten] now exiting
2017-07-05T21:55:32.195+0100 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
2017-07-05T21:55:32.195+0100 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27017.sock
2017-07-05T21:55:32.195+0100 I NETWORK  [initandlisten] shutdown: going to flush diaglog...
2017-07-05T21:55:32.195+0100 I NETWORK  [initandlisten] shutdown: going to close sockets...
2017-07-05T21:55:32.195+0100 I STORAGE  [initandlisten] WiredTigerKVEngine shutting down
2017-07-05T21:55:32.204+0100 I STORAGE  [initandlisten] shutdown: removing fs lock...
2017-07-05T21:55:32.204+0100 I CONTROL  [initandlisten] dbexit:  rc: 0

mongod,log:

2017-07-05T21:58:15.403+0100 I CONTROL  [main] ***** SERVER RESTARTED *****
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] MongoDB starting : pid=12222 port=27017 dbpath=/var/lib/mongodb 64-bit host=napalm
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] db version v3.2.14
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] git version: 92f6668a768ebf294bd4f494c50f48459198e6a3
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] allocator: tcmalloc
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] modules: none
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] build environment:
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten]     distmod: ubuntu1604
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten]     distarch: x86_64
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten]     target_arch: x86_64
2017-07-05T21:58:15.426+0100 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2017-07-05T21:58:15.448+0100 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-07-05T21:58:15.448+0100 I STORAGE  [initandlisten] exception in initAndListen: 98 Unable to create/open lock file: /var/lib/mongodb/mongod.lock errno:13 Permission denied Is a mongod instance already running?, terminating
2017-07-05T21:58:15.448+0100 I CONTROL  [initandlisten] dbexit:  rc: 100
2017-07-05T22:01:27.274+0100 I CONTROL  [main] ***** SERVER RESTARTED *****
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] MongoDB starting : pid=12413 port=27017 dbpath=/var/lib/mongodb 64-bit host=napalm
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] db version v3.2.14
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] git version: 92f6668a768ebf294bd4f494c50f48459198e6a3
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] allocator: tcmalloc
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] modules: none
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] build environment:
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten]     distmod: ubuntu1604
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten]     distarch: x86_64
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten]     target_arch: x86_64
2017-07-05T22:01:27.278+0100 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2017-07-05T22:01:27.300+0100 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-07-05T22:01:27.301+0100 I STORAGE  [initandlisten] exception in initAndListen: 98 Unable to create/open lock file: /var/lib/mongodb/mongod.lock errno:13 Permission denied Is a mongod instance already running?, terminating
2017-07-05T22:01:27.301+0100 I CONTROL  [initandlisten] dbexit:  rc: 100
2017-07-05T22:01:55.112+0100 I CONTROL  [main] ***** SERVER RESTARTED *****
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] MongoDB starting : pid=12454 port=27017 dbpath=/var/lib/mongodb 64-bit host=napalm
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] db version v3.2.14
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] git version: 92f6668a768ebf294bd4f494c50f48459198e6a3
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] allocator: tcmalloc
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] modules: none
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] build environment:
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten]     distmod: ubuntu1604
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten]     distarch: x86_64
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten]     target_arch: x86_64
2017-07-05T22:01:55.117+0100 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2017-07-05T22:01:55.140+0100 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2017-07-05T22:01:55.141+0100 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,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),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] 
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] 
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2017-07-05T22:01:55.341+0100 I CONTROL  [initandlisten] 
2017-07-05T22:01:55.405+0100 E STORAGE  [initandlisten] WiredTiger (13) [1499288515:405025][12454:0x7eff18c72c80], file:index-0--7347504868102783876.wt, WT_SESSION.open_cursor: /var/lib/mongodb/index-0--7347504868102783876.wt: handle-open: open: Permission denied
2017-07-05T22:01:55.411+0100 I -        [initandlisten] Invariant failure: ret resulted in status UnknownError: 13: Permission denied at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 79
2017-07-05T22:01:55.469+0100 I CONTROL  [initandlisten] 
 0x154e4f2 0x14e6ce4 0x14cd793 0x12680df 0x1266423 0x1243757 0xd8b01a 0xb50052 0xb502d4 0xb50787 0xb2c875 0xb2cb11 0xb2cced 0x9c8d71 0x97c35a 0x7eff174bd830 0x9c2e29
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"114E4F2","s":"_ZN5mongo15printStackTraceERSo"},{"b":"400000","o":"10E6CE4","s":"_ZN5mongo10logContextEPKc"},{"b":"400000","o":"10CD793","s":"_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j"},{"b":"400000","o":"E680DF","s":"_ZN5mongo17WiredTigerSession9getCursorERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmb"},{"b":"400000","o":"E66423","s":"_ZN5mongo16WiredTigerCursorC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmbPNS_16OperationContextE"},{"b":"400000","o":"E43757","s":"_ZN5mongo15WiredTigerIndex6insertEPNS_16OperationContextERKNS_7BSONObjERKNS_8RecordIdEb"},{"b":"400000","o":"98B01A","s":"_ZN5mongo17IndexAccessMethod6insertEPNS_16OperationContextERKNS_7BSONObjERKNS_8RecordIdERKNS_19InsertDeleteOptionsEPl"},{"b":"400000","o":"750052","s":"_ZN5mongo12IndexCatalog21_indexFilteredRecordsEPNS_16OperationContextEPNS_17IndexCatalogEntryERKSt6vectorINS_10BsonRecordESaIS6_EE"},{"b":"400000","o":"7502D4","s":"_ZN5mongo12IndexCatalog13_indexRecordsEPNS_16OperationContextEPNS_17IndexCatalogEntryERKSt6vectorINS_10BsonRecordESaIS6_EE"},{"b":"400000","o":"750787","s":"_ZN5mongo12IndexCatalog12indexRecordsEPNS_16OperationContextERKSt6vectorINS_10BsonRecordESaIS4_EE"},{"b":"400000","o":"72C875","s":"_ZN5mongo10Collection16_insertDocumentsEPNS_16OperationContextEN9__gnu_cxx17__normal_iteratorIPKNS_7BSONObjESt6vectorIS5_SaIS5_EEEESB_b"},{"b":"400000","o":"72CB11","s":"_ZN5mongo10Collection15insertDocumentsEPNS_16OperationContextEN9__gnu_cxx17__normal_iteratorIPKNS_7BSONObjESt6vectorIS5_SaIS5_EEEESB_bb"},{"b":"400000","o":"72CCED","s":"_ZN5mongo10Collection14insertDocumentEPNS_16OperationContextERKNS_7BSONObjEbb"},{"b":"400000","o":"5C8D71"},{"b":"400000","o":"57C35A","s":"main"},{"b":"7EFF1749D000","o":"20830","s":"__libc_start_main"},{"b":"400000","o":"5C2E29","s":"_start"}],"processInfo":{ "mongodbVersion" : "3.2.14", "gitVersion" : "92f6668a768ebf294bd4f494c50f48459198e6a3", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "4.4.0-83-generic", "version" : "#106-Ubuntu SMP Mon Jun 26 17:54:43 UTC 2017", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "B04D4C2514E2C891B5791D71A8F4246ECADF157D" }, { "b" : "7FFCB6395000", "elfType" : 3, "buildId" : "9434509C45E2694AB16F0FF9DE029F9CCD51DB57" }, { "b" : "7EFF187F3000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "675F454AD6FD0B6CA2E41127C7B98079DA37F7B6" }, { "b" : "7EFF183AF000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "2DA08A7E5BF610030DD33B70DB951399626B7496" }, { "b" : "7EFF181A7000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "F951C1E0765FCAE48F82CAFE35D1ADD36D6C9AF9" }, { "b" : "7EFF17FA3000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "0FC788F0861846257B5F1773FBD438E95DFC1032" }, { "b" : "7EFF17C9A000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "FF7A33D389E756CA381A8189291A968EA5E1F4F8" }, { "b" : "7EFF17A84000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "68220AE2C65D65C1B6AAA12FA6765A6EC2F5F434" }, { "b" : "7EFF17867000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "27F189EF8DB8C3734C6A678E6EF3CB0B206D58B2" }, { "b" : "7EFF1749D000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "088A6E00A1814622219F346B41E775B8DD46C518" }, { "b" : "7EFF18A5C000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9157F205547F0EB588E2AB1F2F120B74253A43EA" } ] }}
 mongod(_ZN5mongo15printStackTraceERSo+0x32) [0x154e4f2]
 mongod(_ZN5mongo10logContextEPKc+0x174) [0x14e6ce4]
 mongod(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0xF3) [0x14cd793]
 mongod(_ZN5mongo17WiredTigerSession9getCursorERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmb+0xEF) [0x12680df]
 mongod(_ZN5mongo16WiredTigerCursorC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmbPNS_16OperationContextE+0x53) [0x1266423]
 mongod(_ZN5mongo15WiredTigerIndex6insertEPNS_16OperationContextERKNS_7BSONObjERKNS_8RecordIdEb+0x97) [0x1243757]
 mongod(_ZN5mongo17IndexAccessMethod6insertEPNS_16OperationContextERKNS_7BSONObjERKNS_8RecordIdERKNS_19InsertDeleteOptionsEPl+0x1DA) [0xd8b01a]
 mongod(_ZN5mongo12IndexCatalog21_indexFilteredRecordsEPNS_16OperationContextEPNS_17IndexCatalogEntryERKSt6vectorINS_10BsonRecordESaIS6_EE+0xB2) [0xb50052]
 mongod(_ZN5mongo12IndexCatalog13_indexRecordsEPNS_16OperationContextEPNS_17IndexCatalogEntryERKSt6vectorINS_10BsonRecordESaIS6_EE+0x1C4) [0xb502d4]
 mongod(_ZN5mongo12IndexCatalog12indexRecordsEPNS_16OperationContextERKSt6vectorINS_10BsonRecordESaIS4_EE+0x77) [0xb50787]
 mongod(_ZN5mongo10Collection16_insertDocumentsEPNS_16OperationContextEN9__gnu_cxx17__normal_iteratorIPKNS_7BSONObjESt6vectorIS5_SaIS5_EEEESB_b+0x5A5) [0xb2c875]
 mongod(_ZN5mongo10Collection15insertDocumentsEPNS_16OperationContextEN9__gnu_cxx17__normal_iteratorIPKNS_7BSONObjESt6vectorIS5_SaIS5_EEEESB_bb+0x241) [0xb2cb11]
 mongod(_ZN5mongo10Collection14insertDocumentEPNS_16OperationContextERKNS_7BSONObjEbb+0x6D) [0xb2cced]
 mongod(+0x5C8D71) [0x9c8d71]
 mongod(main+0x73A) [0x97c35a]
 libc.so.6(__libc_start_main+0xF0) [0x7eff174bd830]
 mongod(_start+0x29) [0x9c2e29]
-----  END BACKTRACE  -----
2017-07-05T22:01:55.470+0100 I -        [initandlisten] 
 
***aborting after invariant() failure
 
 

Comment by Kelsey Schubert [ 05/Jul/17 ]

Hello napalmd,

Thank you for the report. I've attached a repair attempt of the files you've provided. Would you please extract these files and replace them in your $dbpath and let us know if it resolves the issue? If you are still seeing errors after replacing these files, please provide the complete logs from mongod so that we can further investigate. Additionally, I have a few questions to better understand what has happened here:

  1. What kind of underlying storage mechanism are you using? Are the storage devices attached locally or over the network? Are the disks SSDs or HDDs? What kind of RAID and/or volume management system are you using?
  2. Would you please check the integrity of your disks?
  3. Has the database always been running this version of MongoDB? If not please describe the upgrade/downgrade cycles the database has been through.
  4. Have you manipulated (copied or moved) the underlying database files? If so, was mongod running?
  5. Have you ever restored this instance from backups?
  6. What method do you use to create backups?
  7. When was the underlying filesystem last checked and is it currently marked clean?

Thanks,
Thomas

Generated at Thu Feb 08 04:22:17 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.