Imageprocessor: I/O Exception as the file is being used by another process?

[kendallb]

Prerequisites

• [x] I have written a descriptive issue title
• [x] I have verified that I am running the latest version of ImageProcessor
• [x] I have verified if the problem exist in both DEBUG and RELEASE mode
• [x] I have searched open and closed issues to ensure it has not already been reported

Description

We get these errors cropping up from time to time on our server, but more recently we are seeing more and more of them. We have a high volume of traffic to the server so it serves a lot of images, but it also lives behind a CloudFlare CDN cache so it only gets hit when new images are needed. But now we see to get 1-2 of these a day. Below is the exception message and the stack trace.

Near as I can tell my suspicion is there is some kind of contention in the image cleanup code, at least that is my working theory? Any suggestions on where to look?

Message: The process cannot access the file 'C:\var\www\amain\images\ImageCache\0\6\b\b\6\2\06bb62e3f86280533c7a482047fb74dbcbe115b5.jpg' because it is being used by another process.

System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath):472
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):928
System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize):21

ImageProcessor.Web.Caching.DiskCache+<AddImageToCacheAsync>d__11.MoveNext():46
System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw():12
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task):40

ImageProcessor.Web.HttpModules.ImageProcessingModule+<ProcessImageAsync>d__34.MoveNext():2168
System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw():12
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task):40
System.Web.TaskAsyncHelper.EndTask(IAsyncResult ar):64
System.Web.HttpApplication+AsyncEventExecutionStep.OnAsyncEventCompletion(IAsyncResult ar):34

Steps to Reproduce

Hard to reproduce this one since it clearly depends on high traffic

System Configuration

• ImageProcessor version: 2.5.4
• ImageProcessor.Web version: 2.4.5
• Environment (Operating system, version and so on): Windows Server 2012 R2
• .NET Framework version: 4.6.2

[ZNS]

I'm seeing a few of these errors also. We are behind AWS CloudFront. Cache is outside of web directory but we have cache cleanup disabled.

Exception information: Exception type: IOException Exception message: The process cannot access the file 'D:\media\cache\pub\d\3\1\8\f\7\d318f72bb867009120900ea54ef3411cdad103fc.jpg' 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, Int32 bufferSize) at ImageProcessor.Web.Caching.DiskCache.<AddImageToCacheAsync>d__11.MoveNext() --- End of stack trace from previous location where exception was thrown ---

My guess is that this could happen if a a request is made for an image before it's finished writing the cached version to disk.

[kendallb]

Ok so if you have the cache cleanup stuff disabled then yeah, it makes more sense that it happens when a request is made for an image before it is finished writing. That could possibly happen if two requests came in for the same image at the same time and the image needed to be generated.

Seems to me if we can track down where this happens, the solution would be to have the code that is crashing out catch the exception, sleep for a bit and try again?

[JimBobSquarePants]

We're already locking within the code to prevent duplicate processing so something else is holding on to those files.

https://github.com/JimBobSquarePants/ImageProcessor/blob/develop/src/ImageProcessor.Web/HttpModules/ImageProcessingModule.cs#L545

Sleeping could be a workaround but I hate that TryFiveTimes approach to stuff.

[kendallb]

Sure but that's not the bit of code actually. That's the other side of it so I think we need a similar lock here?

https://github.com/JimBobSquarePants/ImageProcessor/blob/develop/src/ImageProcessor.Web/Caching/DiskCache.cs#L173

[JimBobSquarePants]

@kendallb That's inside the same lock, this is why it's confusing. 😖

[ZNS]

It seems to be locking by the raw request url. So if you have two requests for an uncached image with different parameters (different sizes for example) at the same time? Scratch that, different parameters will have different cached files. However if for some reason two different urls could return the same exact same image that could be an issue? Could different casing for example be enough?

[kendallb]

Yeah it is a bit of a mystery to me also. The cached files should be different based on the different URL parameters. In our case we are very specific about the case of the images that we serve up on our site so at least in our case I doubt the files are being accessed with a variance in the case.

I also do not think it is possible for IIS to directly read these files either, so it has to be something in that code path and it must be related to two requests coming in for the file at the same time. Or maybe it is not the same file at all, but a bug somewhere in the shared stream pool code?

[JimBobSquarePants]

My thought is some dodgy asynchronous use somewhere in my code. Despite locking something is not finished by the time I'm unlocking and accepting a new request.

[kendallb]

Ok so we are getting these several times a day now and it dawned on me that these all started when we recently upgraded the ImageProcessor code. I am going to dig into which version we were running previously so we can see if any major code changes were made in that prior version. I might also try rolling back to that in production to see if the issue goes away. We did not upgrade the version due to any issues, just that I was updating packages in NuGet and noticed it was old so I updated it.

[kendallb]

Ok all these issues seemed to have started when we moved from 2.4.4 of ImageProcessor and 4.6.4 of ImageProcess.Web. I doubt it is related to 2.4.4 of ImageProcessor so the issue would be I expect something that changed from 4.6.4 and 4.8.5+ in ImageProcess.Web.

[kendallb]

Digging through the code I can see that this was added to the end request handler:

        private async Task OnEndRequest(object sender, EventArgs e)
        {
            if (this.imageCache != null)
            {
                // Trim the cache.
                await this.imageCache.TrimCacheAsync();

                // Reset the cache.
                this.imageCache = null;
            }
        }

Is it possible that the trimming of the cache on request end is causing contention for images if they are old enough that they need to be trimmed, but someone just requested the image at the same time?

Also the lock was changed. The lock used to be on:

                string combined = requestPath + fullPath;
                using (await Locker.LockAsync(combined))

While now it is locking on:

            string rawUrl = this.GetRequestUrl(request);
            using (await Locker.LockAsync(rawUrl))

This could be a problem also. If we are locking on the raw URL and you get a request for an SSL and a non-SSL image at the same time, the lock won't work? We need to be locking on the path to the image itself.

[kendallb]

Ok just debugged the code and the rawUrl does not have the host or scheme in it. It is just the URL to the image so SSL and non-SSL (or a different host accessing the same image) will work fine. So I am leaning toward thinking it is the on request end disk trimming?

I might comment that out in a build and see if that fixes it on our site.

[kendallb]

Never mind, I read the diff backwards. The on request end async trimming code was removed, so that cannot be it. Maybe someone more familiar with the code can look at the diffs of what changed from around last August 2016 and the current code?

[kendallb]

Ok well I am going back to 2.4.4 of ImageProcessor and 4.6.4 of ImageProcessor.Web for the moment. If the exceptions go away I think I will then update ImageProcessor itself to the latest version and leave ImageProcessor.Web at the back leveled version so we can rule out whether the issue lies in the core library or the web library at least.

[JimBobSquarePants]

@kendallb My thought is this. We're able to lock on individual requests per server but not able to lock if multiple instances are scaled and they're sharing a single cache outside the web root. (I'm assuming here that you are scaling instances due to high traffic)

The issue will most definitely be on the Web component, not the base library. I'm gonna run through the source again and see if there's something I've missed.

[kendallb]

I am not entirely clear what you mean by multiple instances? We certainly have multiple request handlers running, but none of them will run in parallel and will be in the same memory space so the lock should be valid across all requests. When we need to handle more load we spin up multiple full IIS servers and load balance them for the web site, but for the image server we only have one server since the bulk of the image traffic is cached by CloudFlare first.

[JimBobSquarePants]

@kendallb Ok, so it's a single image server then. That simplifies things. I'll start debugging.

[JimBobSquarePants]

@kendallb We're not locking by the string. Identical strings are two different objects so it was letting both requests through.

[kendallb]

Ahh, nice catch! I will give this a try when an official build is ready.

[JimBobSquarePants]

Will ship one asap. 😄

[kendallb]

Cool. Let me know when it is ready and I will give it a try. So far no errors have cropped up since going back to the earlier version.

[JimBobSquarePants]

Here you go. I've replaced the implementation with a smarter version and added much needed unit tests.

https://www.nuget.org/packages/ImageProcessor.Web/4.8.7

[kendallb]

Awesome I will give this a try tomorrow!

[kendallb]

Ok since we deployed this we have had no issues with the locks anymore, however we have noticed a bunch of resized images were not updating. In fact when we touched the file so it's timestamp was changed, the resized images still did not get processed. I reverted back to the version of ImageProcessor that was working (4.6.4 of ImageProcessor.Web) and the images all immediately updated.

So something got broken here. Should we open a new ticket for this?

[JimBobSquarePants]

Yes please but you're pretty much gonna be on your own for this as I won't be able to debug and replicate.

[kendallb]

Yah I am not entirely sure how to reproduce it. We can reproduce it on demand on our live server, but I will have to get creative on a way to do that on my local system. We have it logged in our bug tracker so I will see if I can dig into it at some point.

[JimBobSquarePants]

Brilliant. Hopefully we can get to the bottom of it. I only changed the locker so not sure what could be happening.

[kendallb]

Well we are using quite a back leveled version of the library so it is entirely possible that this bug existed without the locking code changes but we didn't notice.