Optimization errors do not contain the media path in the logs

[ahinc711]

Version of Dianoga

5.3.0

Environment description

Sitecore 9.3 - local single instance as well as environments with one CM and multiple CD servers.

What configs you have enabled

• Dianoga.DisableForSites.config
• Dianoga.Jpeg.config
• Dianoga.Png.config
• Dianoga.Strategy.GetMediaStreamSync.config
• Dianoga.Svg.config

Reproducible steps (1... 2... 3...) that cause the issue

Cause image optimization to throw an exception. Here is one way to do this:

1. Download an existing PNG or JPEG image in the Media Library
2. Change its file extension to either png or jpg (whichever is incorrect for that image)
3. Reupload it to the Media Library
4. Add the image to some content for a page
5. Clear the media cache
6. Load the page
7. Open the Sitecore logs

What you expected to see, versus what you actually saw

Expected: The logs should contain the error message from the optimization as well as the image's path in the media library, or at least something to identify which image produced an error.

Observed: The logs contain the error message, but the message does not contain any information that can help identify the image (such as the media path). It does have the temp file path, but that file gets deleted.

Some more context: We recently upgraded from version 4.0.0 to version 5.3.0 so that if exceptions occur, the original image is served instead of no image, as mentioned here: #68

However, after the upgrade, we noticed that the error messages in the logs no longer contain the media path. So if we ever need to identify which images aren't being optimized (or have to troubleshoot issues with images in production), we could no longer do so by viewing the logs.

Relevant logs

Version 5.3.0 (image path missing)

76164 11:34:08 ERROR Dianoga: Unable to optimize due to a processing error! It will be unchanged.
Exception: System.InvalidOperationException
Message: "C:\inetpub\wwwroot\website.dev.local\App_Data\Dianoga Tools\mozjpeg\jpegtran.exe -optimize -copy none -progressive -outfile "C:\WINDOWS\TEMP\tmpA53.tmp" "C:\WINDOWS\TEMP\tmpA52.tmp"" exited with unexpected exit code 1. Output: Not a JPEG file: starts with 0x89 0x50


Source: Dianoga
   at Dianoga.Optimizers.CommandLineToolOptimizer.ExecuteProcess(String arguments)
   at Dianoga.Optimizers.CommandLineToolOptimizer.ProcessOptimizer(OptimizerArgs args)
   at Dianoga.Optimizers.OptimizerProcessor.Process(OptimizerArgs args)

Version 4.0.0, which had the image path:

58244 11:50:34 ERROR Dianoga: Unable to optimize /MediaFolder/TestImage due to a processing error! It will be unchanged.
Exception: System.InvalidOperationException
Message: C:\inetpub\wwwroot\website.dev.local\App_Data\Dianoga Tools\mozjpeg_3.1_x86\jpegtran.exe exited with unexpected exit code 1. Output: Not a JPEG file: starts with 0x89 0x50


Source: Dianoga
   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, Boolean failIfNotExists)
   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, Boolean failIfNotExists)
   at Sitecore.Pipelines.DefaultCorePipelineManager.Run(String pipelineName, PipelineArgs args, String pipelineDomain)
   at Dianoga.MediaOptimizer.Process(MediaStream stream, MediaOptions options)

[SudhirKumar2254]

Issue is with OptimizerProcessor.cs in Process method. It's catch section contains below (I validated the issue)

Log.Error($"Dianoga: Unable to optimize due to a processing error! It will be unchanged.", ex, this);

In version 4.0 this logging was not there but in version 5.3.0 it is there.
I will send a pull request with exact fix.

[SudhirKumar2254]

If you comment the log at line around 48 in OptimizerProcessor.cs in Process method, you will get an error like below. (which is similar like version 4.0)

21896 14:48:29 INFO Dianoga: optimized /Default Website/sc_logo.png [original size: 4081 bytes] [final size: 3235 bytes] [saved 846 bytes / 20.73%] [Optimized in 201ms] [Extension png]
21896 14:48:29 INFO "C:\inetpub\wwwroot\demosc.dev.local\App_Data\Dianoga Tools\pngquant\pngquant.exe --force --ext .png "C:\WINDOWS\TEMP\tmp980E.png""

OR
If you want to keep that log statement, then need to pass the Media path during logging. Hope this helps. @markgibbons25 @AustinHinckley

[ahinc711]

@SudhirKumar2254 Thanks for the response. In the first option, those INFO-level logs are what I see when the optimization works. I don't think those would help point out the cases where optimization doesn't work.

I think the second option of keeping the log statement would be better. It also gives the flexibility of changing the logging level to "WARN" or higher and still being able to see which images aren't getting optimized.

Maybe the media path can be passed through OptimizerArgs so it can be used in the log statement in OptimizerProcessor.cs? Looks like this could be passed from ExtensionBasedOptimizer.cs since it has args.InputStream.MediaItem.MediaPath.

[SudhirKumar2254]

@AustinHinckley - Thanks for your response. I have done the code changes to log Media Path.
Please let me know the next steps.

@markgibbons25

[markgibbons25]

@SudhirKumar2254 open a PR?

[SudhirKumar2254]

@SudhirKumar2254 open a PR?
@markgibbons25
Done. Please let me know if it works. Thanks

[markgibbons25]

Thanks @SudhirKumar2254 ! Merged and released.

[SudhirKumar2254]

Thanks @SudhirKumar2254 ! Merged and released.

Welcome. @markgibbons25 Any other issue I can help with?

[ahinc711]

@markgibbons25 @SudhirKumar2254 Thank you both!