[SERVER-35842] Server stopped on wiredtiger log access Created: 27/Jun/18  Updated: 14/Nov/18  Resolved: 14/Nov/18

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

Type: Bug Priority: Major - P3
Reporter: Matt Hughes Assignee: Danny Hatcher (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Server Information
MongoDB starting : pid=3132 port=27017 dbpath=D:\MongoData\db 64-bit host=server
targetMinOS: Windows 7/Windows Server 2008 R2
db version v3.6.3
git version: 9586e557d54ef70f9ca4b43c26892cd55257e1a5
OpenSSL version: OpenSSL 1.0.1u-fips 22 Sep 2016
allocator: tcmalloc
modules: none
build environment:
distmod: 2008plus-ssl
distarch: x86_64
target_arch: x86_64

8 cores
24gb ram
1tb storage
wiredtiger cache limited to 18gb


Issue Links:
Duplicate
duplicates WT-3904 Reconsider error path in log server t... Closed
Operating System: ALL
Participants:

 Description   

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

 

 

 

 



 Comments   
Comment by Danny Hatcher (Inactive) [ 01/Nov/18 ]

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

Comment by Matt Hughes [ 31/Oct/18 ]

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

Comment by Nick Brewer [ 29/Jun/18 ]

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

Comment by Matt Hughes [ 27/Jun/18 ]

Thank you, that one didn't come up in searches. We'll update and monitor.

Comment by Nick Brewer [ 27/Jun/18 ]

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

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