File in use by another process

Problem reported by Elazar Broad - 5/14/2019 at 7:52 AM

Resolved

Hello -

Since upgrading to SmarterMail 7053 (currently on 7068), I've been seeing the follow logged in my delivery log for every single incoming message:

The process cannot access the file 'path\to\SmarterMail\mail\Spool\SubSpool1\1665641204000.eml' because it is being used by another process.

Monitoring the MailService.exe process in procmon, it looks like SM might be leaking file handles. There are several CreateFile() calls without corresponding CloseFile().

While email is being delivered, the issue appears to be impacting spam checks and virus quarantine. Anyone else seeing this?

Thanks,

Elazar

14 Replies

Reply to Thread

Kyle Kerst Replied

5/14/2019 at 9:57 AM

Employee Post

Hello Elazar, and thanks for sending along the details here. Can we have you adjust procmon to exclude MailService.exe from monitoring to confirm nothing else is accessing these files?

Kyle Kerst IT Coordinator SmarterTools Inc. www.smartertools.com

Elazar Broad Replied

5/14/2019 at 12:58 PM

Hi Kyle -

I've adjusted procmon, and no dice. There's no other process, that procmon can see anyway, that's accessing the Spool folder. Additionally, I've done a handle search within processexplorer, and the only process that has a handle on the Spool folder is MailService.exe, as expected.

I upgraded to 7053 (from 7040) on 4/29 and I've verified in my delivery logs that as soon as I started the 7053 build, those errors began to appear. I just happened to notice them yesterday when investigating why an email detected as a virus never made it into the quarantine, as it should have.

I do have A/V and EDR solutions running, but both have proper exclusions configured for SmarterMail - again noting that this wasn't an issue with them coexisting until 7053.

Edit to add: I've disabled the on-access scanner in my A/V solution, and disabled my EDR solution altogether, to no avail. Still seeing the same error.

Thanks,

Elazar

Kyle Kerst Replied

5/14/2019 at 4:13 PM

Employee Post

Thanks Elazar, this is definitely interesting behavior and if possible I suggest submitting a support ticket so we can check this out in more detail. In the meantime:

1. I suggest upgrading to our latest minor release to see if this helps by chance. The minor update you're looking for is b7068 and it includes a number of significant fixes and improvements.

2. Lastly, could you temporarily stop the AV/EDR solutions on the SM server to see if these issues happen to clear up?

When submitting a support ticket these two items will likely get brought up pretty quick, so its good to get them out of the way now. Thanks in advance!

Kyle Kerst IT Coordinator SmarterTools Inc. www.smartertools.com

Elazar Broad Replied

5/14/2019 at 10:36 PM

Hi Kyle -

I've uninstalled both my A/V and EDR solutions, and rebooted, still seeing the same error in the delivery logs. As noted earlier, I'm already running build 7068, though I started seeing these errors when upgrading to 7053. I'll open a ticket in the morning.

Thanks,

Elazar

Elazar Broad Replied

5/14/2019 at 11:33 PM

So I've spun up a Sever 2016 Standard VM for the sole purpose of testing. Installed SmarterMail 7068 using the full installer. Configured a single test domain, and sent some messages to it using telnet. Sure enough, I'm seeing the same errors in the delivery log:

23:26:08.998 [82001] Delivery started for at 11:26:08 PM
23:26:08.998 [82001] Spool message was missing Return-Path; Also missing FROM header. If this is a system message this is normal behavior.
23:26:21.077 [82001] Added to SpamCheckQueue (1 queued; 0/30 processing)
23:26:21.077 [82001] [SpamCheckQueue] Begin Processing.
23:26:21.092 [82001] Starting Spam Checks.
23:26:21.092 [82001] Error checking SPF Record: Spf check failed due to null sender's domain
23:26:21.139 System.IO.IOException: The process cannot access the file 'C:\SmarterMail\Spool\SubSpool2\1139282001.eml' because it is being used by another process.
at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
at SmarterTools.SmarterMail.Mime.MimeReader.LoadHeader()
at MailService.Spam.SpamAssassin.MessageContext.Load(String filePath)
at MailService.Spam.SpamChecks.RunChecks(String[] checkList, SpamCheckArgs args, List`1 customRules)
23:26:21.139 [82001] Spam check results: [REVERSE DNS LOOKUP: 0,Passed], [BACKSCATTER: 0,passed], [CBL: 0,passed], [DNS REAL-TIME BLACKHOLE LIST: 0,passed], [HOSTKARMA - BLACKLIST: 0,passed], [HOSTKARMA - BROWNLIST: 0,passed], [MAILSPIKE L3: 0,passed], [MAILSPIKE L4: 0,passed], [MAILSPIKE L5: 0,passed], [MCAFEE: 0,passed], [SEM - BLACK: 0,passed], [SORBS - ABUSE: 0,passed], [SORBS - DYNAMIC IP: 0,passed], [SORBS - NO SERVER: 0,passed], [SORBS - NOMAIL: 0,passed], [SORBS - PROXY: 0,passed], [SORBS - RECENT: 0,passed], [SORBS - SOCKS: 0,passed], [SPAMCOP: 0,passed], [SPAMHAUS - CSS: 0,passed], [SPAMHAUS - PBL: 0,passed], [SPAMHAUS - SBL: 0,passed], [SPAMRATS: 0,passed], [SURRIEL: 0,passed], [TRUNCATE: 0,passed], [UCEPROTECT LEVEL 1: 0,passed], [UCEPROTECT LEVEL 2: 0,passed], [UCEPROTECT LEVEL 3: 0,passed], [_DKIM: TempFail], [SEM-URI: 0,passed], [URIBL BLACK: 0,passed], [URIBL GREY: 0,passed], [URIBL RED: 0,passed]
23:26:21.139 [82001] Spam Checks completed.
23:26:21.139 [82001] Removed from SpamCheckQueue (0 queued or processing)
23:26:24.248 [82001] Added to LocalDeliveryQueue (0 queued; 1/50 processing)
23:26:24.248 [82001] [LocalDeliveryQueue] Begin Processing.
23:26:24.248 [82001] Starting local delivery to administrator@testdomain.com
23:26:24.264 [82001] Delivery for to administrator@testdomain.com has completed (Delivered) Filter: None
23:26:24.264 [82001] End delivery to administrator@testdomain.com (MessageID: <88587fac0d934da9b6f17519b72ea889@com>)
23:26:24.264 [82001] Removed from LocalDeliveryQueue (0 queued or processing)
23:26:24.264 [82001] Delivery finished for at 11:26:24 PM [id:1139282001]

Kyle Kerst Replied

5/15/2019 at 10:29 AM

Employee Post

Quick update on this thread. We were able to confirm the access issues being reported here appears to stem from ClamAV's attempts at accessing EML files from the spool for scanning as this environment leverages a non-local deployment of ClamAV. We're investigating now to determine the root cause of the failure and will follow up here when complete.

Kyle Kerst IT Coordinator SmarterTools Inc. www.smartertools.com

Employee Replied

5/15/2019 at 11:23 AM

Employee Post

Elazar, can you verify whether or not you have ClamAV enabled?

Elazar Broad Replied

5/15/2019 at 11:44 AM

Hi Robert -

ClamAV is enabled. I've been using a remote ClamAV deployment on a Linux VM for several years with SM without issue. In order to work around this issue, I've configured SM to use it's local ClamAV instance instead.

Thanks,

Elazar

Employee Replied

5/15/2019 at 11:51 AM

Employee Post

Elazar,

Are you saying that the eml being locked because it is being used by another process does not happen for you after you configure SM to use local ClamAV? In Build 7053 we upgraded the ClamAV communication package, and we think it may be a contributing cause for the file locking. If you disabled ClamAV altogether (temporarily) does the file locking clear up from your logs?

Thanks,

Robert

Elazar Broad Replied

5/15/2019 at 12:56 PM

Hi Robert -

That's correct. If I disable the remote ClamAV setting, and use the local one(SM included) instead, the locking exceptions go away. I ran Wireshark to see if I can discern anything in the conversation between SM and my remote ClamAV instance, but everything seems to be OK: ClamAV returns STREAM OK for benign emails.

Thanks,

Elazar

Kyle Kerst Replied

5/15/2019 at 3:33 PM

Employee Post

Elazar, can you please install the following minor update per the included instructions and let us know how your remote ClamAV installation functions afterwards?

Download: http://www.smartertools.com/downloads/SmarterMail/CustomBuilds/100.0.7074.27591/SmarterMail_7074.exe

Instructions: https://portal.smartertools.com/kb/a2855/minor-upgrade-of-smartermail.aspx

I've tested this here and it does resolve the issue in my testing. Thanks in advance!

Kyle Kerst IT Coordinator SmarterTools Inc. www.smartertools.com

Ionel Aurelian Rau Replied

5/21/2019 at 1:04 AM

Hi all,

I found this thread so I though I`d have a look though our Delivery logs too and search for "access" - this is what I`ve come up with:

[2019.05.21] 03:02:59.955 [02732] Delivery started for user1@domain.com at 3:02:59 AM
[2019.05.21] 03:03:03.003 [02732] Added to SpamCheckQueue (1 queued; 2/60 processing)
[2019.05.21] 03:03:03.003 [02732] [SpamCheckQueue] Begin Processing.
[2019.05.21] 03:03:03.456 [02732] Starting Spam Checks.
[2019.05.21] 03:03:03.456 [02732] Skipping spam checks: User authenticated
[2019.05.21] 03:03:03.456 [02732] Spam Checks completed.
[2019.05.21] 03:03:03.456 [02732] Removed from SpamCheckQueue (2 queued or processing)
[2019.05.21] 03:03:06.003 [02732] Added to LocalDeliveryQueue (0 queued; 3/50 processing)
[2019.05.21] 03:03:06.003 [02732] [LocalDeliveryQueue] Begin Processing.
[2019.05.21] 03:03:06.003 [02732] Starting local delivery to user2@domain.com
[2019.05.21] 03:03:06.034 [02732] Add message to mailbox call failed.  Reason: Access to the grp file is locked, monitor enter failed.
[2019.05.21] 03:03:06.034 [02732] Delivery attempt to user2@domain.com to folder 'Inbox' failed.  Mailbox is locked.
[2019.05.21] 03:03:06.034 [02732] Removed from LocalDeliveryQueue (1 queued or processing)
[2019.05.21] 03:03:09.003 [02732] Added to LocalDeliveryQueue (0 queued; 1/50 processing)
[2019.05.21] 03:03:09.003 [02732] [LocalDeliveryQueue] Begin Processing.
[2019.05.21] 03:03:09.003 [02732] Starting local delivery to user2@domain.com
[2019.05.21] 03:03:09.034 [02732] Delivery for user1@domain.com to user2@domain.com has completed (Delivered) Filter: None
[2019.05.21] 03:03:09.034 [02732] End delivery to user2@domain.com (MessageID: <211c83fde752795de6bea88f9ce6bb20@swift.generated>)
[2019.05.21] 03:03:09.034 [02732] Removed from LocalDeliveryQueue (0 queued or processing)
[2019.05.21] 03:03:12.144 [02732] Removing Spool message: Killed: False, Failed: False, Finished: True
[2019.05.21] 03:03:12.144 [02732] Delivery finished for user1@domain.com at 3:03:12 AM	[id:273002732]

There are quite a few of these and it would appear that in the end the mails do get delivered - but I cannot check for all of these instances.

We are running the default ClavAV that comes with SmarterMail, along with Cyren Zero-Hour.

Kyle Kerst Replied

5/21/2019 at 3:12 PM

Employee Post

Ionel, can I have you confirm the full build number that you have installed currently?

Kyle Kerst IT Coordinator SmarterTools Inc. www.smartertools.com

Ionel Aurelian Rau Replied

5/22/2019 at 1:48 AM

100.0.7068.15779

It was accessible publicly on 18 May when we installed the update.

Back to Community Threads

Please leave this box unchecked

14 Replies

Reply to Thread

Tags

Related Knowledge Base Articles