Access to the path 'C:\Windows\TEMP\tmpXXXX.tmp' is denied.

[eat-sleep-code]

I am running Dianoga 3.0.2.0 on Sitecore 8.2 Update 2.

I noticed that on our Content Management instance that I am getting periodic errors like:

3272 14:07:17 ERROR Dianoga: Unable to optimize /MySite/Infographics/Thumbnails/News infographic 4 due to a processing error! It will be unchanged.
Exception: System.UnauthorizedAccessException
Message: Access to the path 'C:\Windows\TEMP\tmpDBE6.tmp' is denied.
Source: mscorlib
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.File.InternalDelete(String path, Boolean checkHost)
   at Dianoga.Unmanaged.DynamicLinkLibrary.Dispose()
   at Dianoga.Optimizers.Pipelines.DianogaPng.PngOptimizer.ProcessOptimizer(OptimizerArgs args)
   at Dianoga.Optimizers.OptimizerProcessor.Process(OptimizerArgs args)
   at (Object , Object[] )
   at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.Processors.Pipelines.DianogaOptimize.ExtensionBasedOptimizer.ProcessOptimize(ProcessorArgs args)
   at (Object , Object[] )
   at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.MediaOptimizer.Process(MediaStream stream, MediaOptions options)

These errors are periodic. Some images process fine.

After five of these occur in five minutes my W3WP process fails and restarts. This wreaks all kind of havoc on folks that are trying to utilize the CM instance.

[kamsar]

Does the IIS app pool user have rights to read and write and delete in c:\windows\temp?

I gather that the PNG optimizer internally writes some temp files there despite my using a method that optimizes a stream.

On Tue, Jan 24, 2017 at 2:27 PM, eat-sleep-code notifications@github.com wrote:

I am running Dianoga 3.0.2.0 on Sitecore 8.2 Update 2.

I noticed that on our Content Management instance that I am getting periodic errors like:

3272 14:07:17 ERROR Dianoga: Unable to optimize /MySite//Infographics/Thumbnails/News infographic 4 due to a processing error! It will be unchanged. Exception: System.UnauthorizedAccessException Message: Access to the path 'C:\Windows\TEMP\tmpDBE6.tmp' is denied. Source: mscorlib at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath) at System.IO.File.InternalDelete(String path, Boolean checkHost) at Dianoga.Unmanaged.DynamicLinkLibrary.Dispose() at Dianoga.Optimizers.Pipelines.DianogaPng.PngOptimizer.ProcessOptimizer(OptimizerArgs args) at Dianoga.Optimizers.OptimizerProcessor.Process(OptimizerArgs args) at (Object , Object[] ) at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args) at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain) at Dianoga.Processors.Pipelines.DianogaOptimize.ExtensionBasedOptimizer.ProcessOptimize(ProcessorArgs args) at (Object , Object[] ) at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args) at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain) at Dianoga.MediaOptimizer.Process(MediaStream stream, MediaOptions options)

These errors are periodic. Some images process fine.

After five of these occur in five minutes my W3WP process fails and restarts. This wreaks all kind of havoc on folks that are trying to utilize the CM instance.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/kamsar/Dianoga/issues/18, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGU_ZxgDlUWyIDfJ2ttg1qoTytXjZizks5rVnq2gaJpZM4Ls3a7 .

[eat-sleep-code]

Yes, app pool user does, System does, Network Service does, and Everyone does.

Some images process fine, but I would need to check the logs tomorrow to see if it is only PNG images that are failing.

[kamsar]

@patocl you're fast, I just came here to mention you 😁

Make sure to undo the reformatting and leave just the relevant changes before PRing, please.

[patocl]

I will do tomorrow

[kamsar]

Sounds great. Appreciate your contributions :)

@eat-sleep-code @patocl has a fix he's cooked up. I'll review it and send out a new release as soon as we get it merged and tested :)

[eat-sleep-code]

Sounds good. So should I expect it next week sometime?

[kamsar]

Of note however the exception you posted would not cause the triggering of rapid fail protection. RFP is triggered when the app pool has had to be terminated due to an unhandled background exception - and the exception you posted was handled and logged right here.

Check your windows application event logs for events that are logged as the pool terminating due to an unhandled exception.

[kamsar]

@patocl 's fix is in Dianoga 3.0.3-beta01 on NuGet now. Note that the fix requires manual configuration of the temp path to some location of your choosing that the app pool has read/write access to; if your deployment process does not try to clear files in ~/temp that is probably a good location to try. See Dianoga.Png.config for comments on setting the temp path.

[eat-sleep-code]

FYI, I tried the beta release but something is still not quite right. No errors are logged, but I am getting a process restart right after dianoga optimizes an image -- even JPGs.

Last lines of first log:

ManagedPoolThread #4 11:16:40 INFO  Job started: Index_Update_IndexName=sitecore_marketing_asset_index_master
ManagedPoolThread #4 11:16:40 INFO  Job ended: Index_Update_IndexName=sitecore_marketing_asset_index_master (units processed: )
3816 11:16:40 INFO  AUDIT (sitecore\Admin): Attach: master:/sitecore/media library/MySite/Miscellaneous/At A Glance Thumbnail, language: en, version: 1, id: {0908FDDE-CC70-4207-8CD3-AAD8CE0EA96C}, file:At A Glance Thumbnail.jpg
4200 11:16:40 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance Thumbnail.jpg [original size] (final size: 90435 bytes) - saved 27284 bytes / 23.18 %. Optimized in 356ms.
4424 11:16:40 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance Thumbnail.jpg [original size] (final size: 90435 bytes) - saved 27284 bytes / 23.18 %. Optimized in 300ms.
ManagedPoolThread #9 11:16:42 INFO  Job ended: Index_Update_IndexName=sitecore_master_index (units processed: )
ManagedPoolThread #9 11:16:42 INFO  Job started: Index_Update_IndexName=sitecore_master_index
3816 11:16:42 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance Thumbnail.jpg [640mw x 128h (thumb)] (final size: 16053 bytes) - saved 2496 bytes / 13.46 %. Optimized in 74ms.
ManagedPoolThread #9 11:16:42 INFO  Job ended: Index_Update_IndexName=sitecore_master_index (units processed: )
ManagedPoolThread #9 11:16:42 INFO  Job started: Index_Update_IndexName=sitecore_master_index
3816 11:16:42 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance Thumbnail.jpg [32w x 32h (thumb)] (final size: 1023 bytes) - saved 201 bytes / 16.42 %. Optimized in 35ms.
4424 11:16:42 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance Thumbnail.jpg [16w x 16h (thumb)] (final size: 406 bytes) - saved 118 bytes / 22.52 %. Optimized in 49ms.
ManagedPoolThread #9 11:16:42 INFO  Job ended: Index_Update_IndexName=sitecore_master_index (units processed: )
4200 11:16:45 INFO  AUDIT (sitecore\Admin): Save item: master:/sitecore/media library/MySite/Miscellaneous/At A Glance Thumbnail, language: en, version: 1, id: {0908FDDE-CC70-4207-8CD3-AAD8CE0EA96C}

Last lines of second log:

ManagedPoolThread #8 11:17:17 INFO  Cache created: 'system[xsl]' (max size: 50MB, running total: 14148MB)
ManagedPoolThread #8 11:17:17 INFO  Cache created: 'system[filtered items]' (max size: 10MB, running total: 14158MB)
ManagedPoolThread #8 11:17:17 INFO  Cache created: 'publisher[html]' (max size: 0 bytes, running total: 14158MB)
ManagedPoolThread #8 11:17:17 INFO  Cache created: 'publisher[registry]' (max size: 25MB, running total: 14183MB)
ManagedPoolThread #8 11:17:17 INFO  Cache created: 'publisher[viewstate]' (max size: 25MB, running total: 14208MB)
ManagedPoolThread #8 11:17:17 INFO  Cache created: 'publisher[xsl]' (max size: 50MB, running total: 14258MB)
ManagedPoolThread #8 11:17:17 INFO  Cache created: 'publisher[filtered items]' (max size: 10MB, running total: 14268MB)
ManagedPoolThread #8 11:17:17 WARN  No subscription for Device Detection service. Could not check for updates.
ManagedPoolThread #8 11:17:17 INFO  Job ended: Update device detection DB (units processed: )
1328 11:18:48 INFO  Cache created: 'clientData' (max size: 25MB, running total: 14293MB)
1328 11:18:48 INFO  Cache created: 'UserProfileCache' (max size: 5MB, running total: 14298MB)
1328 11:18:57 INFO  Cache created: 'ItemCloningRelations' (max size: 50MB, running total: 14348MB)
1328 11:18:57 INFO  Cache created: 'scripts' (max size: 800KB, running total: 14348MB)
1328 11:18:58 INFO  Cache created: 'SqlDataProvider - Prefetch data(master)' (max size: 100MB, running total: 14448MB)
1328 11:19:03 INFO  Cache created: 'WebUtil.QueryStringCache' (max size: 19KB, running total: 14448MB)
4180 11:19:08 INFO  HttpModule is being initialized
4112 11:19:08 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance.jpg [32w x 32h (thumb)] (final size: 1209 bytes) - saved 288 bytes / 19.24 %. Optimized in 42ms.
3396 11:19:08 INFO  Dianoga: optimized /MySite/Miscellaneous/At A Glance.jpg [640mw x 128h (thumb)] (final size: 10330 bytes) - saved 1496 bytes / 12.65 %. Optimized in 82ms.

You will note that a Dianoga action is the last thing that happens each time.

[kamsar]

Check the windows application event log for errors, please. It should log the pool termination reason even if the termination causes sitecore's logs to not be writeable.

[eat-sleep-code]

Faulting application name: w3wp.exe, version: 8.5.9600.16384, time stamp: 0x5215df96
Faulting module name: xkpif1pz.04j_unloaded, version: 2.3.0.0, time stamp: 0x536d0e7e
Exception code: 0xc0000005
Fault offset: 0x000000000000a28a
Faulting process id: 0x12e8
Faulting application start time: 0x01d27b2361c6a52e
Faulting application path: c:\windows\system32\inetsrv\w3wp.exe
Faulting module path: xkpif1pz.04j
Report Id: 402195eb-e718-11e6-80e4-005056917698
Faulting package full name: 
Faulting package-relative application ID: 

Faulting application name: w3wp.exe, version: 8.5.9600.16384, time stamp: 0x5215df96
Faulting module name: iovtem0f.v0z_unloaded, version: 2.3.0.0, time stamp: 0x536d0e7e
Exception code: 0xc0000005
Fault offset: 0x000000000001a28a
Faulting process id: 0x49c
Faulting application start time: 0x01d27b2503c9fe3e
Faulting application path: c:\windows\system32\inetsrv\w3wp.exe
Faulting module path: iovtem0f.v0z
Report Id: 97533c1a-e718-11e6-80e4-005056917698
Faulting package full name: 
Faulting package-relative application ID: 

I am not sure what the randomly named modules are all about.

[kamsar]

usually randomly named modules are from some sort of generated code, like razor views or something. Were there any warnings prior to the faults of .net exceptions?

[eat-sleep-code]

No warning.

[eat-sleep-code]

I do note that if I disable the PNG optimizer pipeline references it stops this behavior.

[patocl]

Hi, I was reading all your comments, it's a bit weird because I can't reproduce this behavior... Could you verify if the random files that are generating on temp folder are being removed, or still remaining there? Maybe the problem could be when the process is being disposed and the GC is trying to delete those files?

[eat-sleep-code]

There are no files in the temp folder.

[patocl]

do you have some PNG files on Medicache library? ~\App_Data\MediaCache

or the optimizer is not working on PNG files?

[eat-sleep-code]

There are PNGs in the subfolders under the MediaCache but not sure if those were created with or without the PNG optimization enabled (I have it off for right now so as not to annoy the crap out of my content editors).

The odd thing is that I was attaching a couple of updated JPGs when it cycled the IIS processes. But it stopped doing it after I disabled the PNG optimization.

[eat-sleep-code]

Not sure if this helps at all, but I have memory dumps and a windows error report from when it crashed both times yesterday.

[kamsar]

Sure dumps could be useful. I still haven't been seeing this in my daily usage.

[kamsar]

I found a reproduction of this today! It appears that it was caused by a native bug in PngOptimizerDll, which was doing naughty things with memory accesses. The win32 exception was bypassing the managed try/catch blocks and terminating the app pool. In my case I reproduced it by uploading a bunch of PNGs all at the same time.

To fix it, I've released Dianoga 3.0.3-beta02. This release solves the problem by dropping PngOptimizerDll and all the native p/invoke shenanigans thereof (notably it's not available for download any longer as of the latest PNGOptimizer version), and instead using the command line version through the same pathways as the JPEG and SVG optimizers are using.

With this change I had no issue accepting a large influx of new media items, and it also gets rid of the need to support any p/invoke code as well as being simpler to maintain.

Give it a shot, and lemme know if you run into issues. And thanks @eat-sleep-code for spending the time to debug and take memory dumps and such.

Ref: https://github.com/kamsar/Dianoga/commit/380e0f61d2f977337df5c158716b1463fe481c64

[eat-sleep-code]

I will check it out when I am back in the office on Monday.

[eat-sleep-code]

After deploying this latest beta, I noticed that the option to specify a temp directory is now gone.

I get the following in my logs:

4832 08:47:54 ERROR Dianoga: Unable to optimize /MySite/Company Logos/DHL due to a processing error! It will be unchanged.
Exception: System.ComponentModel.Win32Exception
Message: The system cannot find the file specified
Source: System
   at System.Diagnostics.Process.StartWithCreateProcess(ProcessStartInfo startInfo)
   at Dianoga.Optimizers.CommandLineToolOptimizer.ExecuteProcess(String arguments)
   at Dianoga.Optimizers.CommandLineToolOptimizer.ProcessOptimizer(OptimizerArgs args)
   at Dianoga.Optimizers.OptimizerProcessor.Process(OptimizerArgs args)
   at (Object , Object[] )
   at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.Processors.Pipelines.DianogaOptimize.ExtensionBasedOptimizer.ProcessOptimize(ProcessorArgs args)
   at (Object , Object[] )
   at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.MediaOptimizer.Process(MediaStream stream, MediaOptions options)

4832 08:47:54 INFO  Dianoga: /MySite/Company Logos/DHL is not something that can be optimized, either because of its file format or because it is excluded.
3768 08:47:54 ERROR Dianoga: Unable to optimize /MySite/Company Logos/Walgreens due to a processing error! It will be unchanged.
Exception: System.ComponentModel.Win32Exception
Message: The system cannot find the file specified
Source: System
   at System.Diagnostics.Process.StartWithCreateProcess(ProcessStartInfo startInfo)
   at Dianoga.Optimizers.CommandLineToolOptimizer.ExecuteProcess(String arguments)
   at Dianoga.Optimizers.CommandLineToolOptimizer.ProcessOptimizer(OptimizerArgs args)
   at Dianoga.Optimizers.OptimizerProcessor.Process(OptimizerArgs args)
   at (Object , Object[] )
   at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.Processors.Pipelines.DianogaOptimize.ExtensionBasedOptimizer.ProcessOptimize(ProcessorArgs args)
   at (Object , Object[] )
   at Sitecore.Pipelines.CorePipeline.Run(PipelineArgs args)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.MediaOptimizer.Process(MediaStream stream, MediaOptions options)

3768 08:47:54 INFO  Dianoga: /MySite/Company Logos/Walgreens is not something that can be optimized, either because of its file format or because it is excluded.

[kamsar]

Check the config file against what's in the package as the need for the temp dir setting was eliminated and the path to execute was also changed.

[eat-sleep-code]

Correct. When I updated it the package it automatically removed my config transform file (weird). So I have the configs exactly as you provided them in the package.

But anyway, I think eliminating the temp directory setting reintroduced the first problem.

[kamsar]

You said jpegs were working, right? The PNG path is now identical to that. On Mon, Feb 20, 2017 at 7:10 PM eat-sleep-code notifications@github.com wrote:

Correct. When I updated it the package it automatically removed my config transform file (weird). But anyway, I think eliminating the temp directory setting reintroduced the first problem.

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/kamsar/Dianoga/issues/18#issuecomment-281233448, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGU_boKAuW8AEPXIHng_bPYO93OkxS3ks5relW6gaJpZM4Ls3a7 .

[eat-sleep-code]

Yes. I never saw issues with JPEGs and it wasn't consistent with PNG (some would throw the access denied errors, some wouldn't). I guess as long as the thing isn't blowing up W3C process I could live with a few errors being thrown into the logs. :-)

[kamsar]

This is now part of 3.1