Info

Had an issue in a production system this morning where the server service had shut down. Mongo log appeared to report some sort of issue with removing a wiredtiger journal log because access was denied. Is there a way to make this a little more graceful? If it was the journal log and was doing some sort of internal maintenance couldn't it try again? I believe the root cause of the access denied was antivirus and we've added exclusions but not 100% sure of the cause for access denied. 2018-06-26T19:11:00.750-0400 E STORAGE [thread42198] WiredTiger error (13) [1530054660:676349][4728:140706250756224], log-server: D:\MongoData\db\journal\WiredTigerLog.0000028727: file-remove: DeleteFileW: Access is denied. : Permission denied 2018-06-26T19:11:00.750-0400 E STORAGE [thread42198] WiredTiger error (13) [1530054660:750354][4728:140706250756224], log-server: log archive server error: Permission denied 2018-06-26T19:11:00.750-0400 E STORAGE [thread42198] WiredTiger error (13) [1530054660:750354][4728:140706250756224], log-server: log server error: Permission denied 2018-06-26T19:11:00.751-0400 E STORAGE [thread42198] WiredTiger error (-31804) [1530054660:750354][4728:140706250756224], log-server: the process must exit and restart: WT_PANIC: WiredTiger library panic 2018-06-26T19:11:00.886-0400 F - [WTJournalFlusher] Fatal Assertion 28559 at src\mongo\db\storage\wiredtiger\wiredtiger_util.cpp 64 2018-06-26T19:11:00.886-0400 F - [thread42198] Fatal Assertion 28558 at src\mongo\db\storage\wiredtiger\wiredtiger_util.cpp 361 2018-06-26T19:11:00.886-0400 F - [thread42198] ***aborting after fassert() failure 2018-06-26T19:11:00.886-0400 F - [WTJournalFlusher] ***aborting after fassert() failure

Top User Comments

daniel.hatcher commented on Thu, 1 Nov 2018 15:26:01 +0000: Hello Matt, It appears that this situation is slightly different than before; the error message mentions another process using the file: DeleteFileW: The process cannot access the file because it is being used by another process.: Resource device The change in WT-3904 was to add retry logic to this path. Instead of simply failing once and returning this error, WiredTiger will retry up to 10 times in order to avoid any transient issues. However, the root issue leading to this problem is another process accessing MongoDB's internal files. You mentioned in your original description that you were using an antivirus program. Does this 3.6.8 process also have an antivirus present on the machine? Thank you, Danny mhughes commented on Wed, 31 Oct 2018 17:59:18 +0000: I had this happen again on a site running 3.6.8 2018-10-31T13:19:31.519-0400 I NETWORK [conn23550] received client metadata from 10.10.25.162:61736 conn23550: { driver: { name: "mongo-csharp-driver", version: "2.4.1.18" }, os: { type: "Windows", name: "Microsoft Windows 6.3.9600", architecture: "x86_32", version: "6.3.9600" }, platform: ".NET Framework 4.0.30319.36399" } 2018-10-31T13:19:31.604-0400 I ACCESS [conn23550] Successfully authenticated as principal fusion_maint on admin 2018-10-31T13:20:18.349-0400 I NETWORK [conn23545] end connection ##.##.##.##:61571 (39 connections now open) 2018-10-31T13:20:32.488-0400 E STORAGE [thread23551] WiredTiger error (16) [1541006432:488726][6552:140710365958976], log-server: E:\Program Files\MongoDB\MongoData\db\journal\WiredTigerLog.0000057858: file-remove: DeleteFileW: The process cannot access the file because it is being used by another process.: Resource device 2018-10-31T13:20:32.489-0400 E STORAGE [thread23551] WiredTiger error (16) [1541006432:488726][6552:140710365958976], log-server: log archive server error: Resource device 2018-10-31T13:20:32.489-0400 E STORAGE [thread23551] WiredTiger error (16) [1541006432:488726][6552:140710365958976], log-server: log server error: Resource device 2018-10-31T13:20:32.489-0400 E STORAGE [thread23551] WiredTiger error (-31804) [1541006432:488726][6552:140710365958976], log-server: the process must exit and restart: WT_PANIC: WiredTiger library panic 2018-10-31T13:20:32.492-0400 F - [thread23551] Fatal Assertion 28558 at src\mongo\db\storage\wiredtiger\wiredtiger_util.cpp 366 2018-10-31T13:20:32.492-0400 F - [thread23551] ***aborting after fassert() failure 2018-10-31T13:20:32.504-0400 F - [WTJournalFlusher] Fatal Assertion 28559 at src\mongo\db\storage\wiredtiger\wiredtiger_util.cpp 64 2018-10-31T13:20:32.504-0400 F - [WTJournalFlusher] ***aborting after fassert() failure 2018-10-31T13:41:33.094-0400 I CONTROL [main] **** SERVER RESTARTED **** 2018-10-31T13:41:34.238-0400 I CONTROL [main] Trying to start Windows service 'MongoDB' 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] MongoDB starting : pid=6584 port=27017 dbpath=E:\Program Files\MongoDB\MongoData\db 64-bit host=CAC-DB-Prod 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] db version v3.6.8 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] git version: 6bc9ed599c3fa164703346a22bad17e33fa913e4 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.2o-fips 27 Mar 2018 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] allocator: tcmalloc 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] modules: none 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] build environment: 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] distmod: 2008plus-ssl 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] distarch: x86_64 2018-10-31T13:41:34.240-0400 I CONTROL [initandlisten] target_arch: x86_64 2018-10-31T13:41:34.241-0400 I CONTROL [initandlisten] options: { config: "E:\Program Files\MongoDB\MongoData\mongod.cfg", net: { bindIp: "127.0.0.1,##.##.##.##", port: 27017 }, security: { authorization: "enabled" }, service: true, storage: { dbPath: "E:\Program Files\MongoDB\MongoData\db", wiredTiger: { engineConfig: { cacheSizeGB: 18.0 } } }, systemLog: { destination: "file", logAppend: true, path: "E:\Program Files\MongoDB\MongoData\log\mongod.log" } } 2018-10-31T13:41:34.241-0400 W - [initandlisten] Detected unclean shutdown - E:\Program Files\MongoDB\MongoData\db\mongod.lock is not empty. 2018-10-31T13:41:34.243-0400 I - [initandlisten] Detected data files in E:\Program Files\MongoDB\MongoData\db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. 2018-10-31T13:41:34.244-0400 W STORAGE [initandlisten] Recovering data from the last clean checkpoint. 2018-10-31T13:41:34.245-0400 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=18432M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),cache_cursors=false,compatibility=(release="3.0",require_max="3.0"),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress), 2018-10-31T13:41:34.617-0400 I STORAGE [initandlisten] WiredTiger message [1541007694:616778][6584:140710365958976], txn-recover: Main recovery loop: starting at 57859/6229760 2018-10-31T13:41:34.621-0400 I STORAGE [initandlisten] WiredTiger message [1541007694:620780][6584:140710365958976], txn-recover: Recovering log 57859 through 57860 nick.brewer commented on Fri, 29 Jun 2018 17:33:13 +0000: I'm going to close this ticket for now - if you run into this error after upgrading, feel free to comment here and we can reopen it. Nick mhughes commented on Wed, 27 Jun 2018 20:54:55 +0000: Thank you, that one didn't come up in searches. We'll update and monitor. nick.brewer commented on Wed, 27 Jun 2018 20:16:54 +0000: Hi mhughes From the initial information you've provided, this looks to me like a known issue that was addressed in WT-3904. I'd suggest that you upgrade to version 3.6.4, as it contains a fix for this behavior. If you're still running into this after the upgrade, let us know and we can investigate further. Nick

Steps to Reproduce