Bug workaround for Issue #28 The process cannot access the file

[LeeReid1]

This is designed to make the logger a bit more robust to files being busy. See Issue #28. It's not a full solution as I did not manage to fully diagnose the issue.

The changes are thus:

• There is a new option called SkipUnopenableLogFiles which is true by default
• If this is off or the solution only writes to a single log file, behaviour is similar to before
• If this is on and multiple log files is allowed, it attempts to open the log file to write to as normal. However, upon an IOException it recovers and moves to attempting to use the next log file.
• If it cannot open any files for writing, it throws an AggregateException containing the IOExceptions.

Other minor changes:

• FileWriter now implements IDisposable (because it opens a stream). Although this is unlikely to change behaviour meaningfully it's a tad more 'correct' and might help with some more advanced debugging at some point(?).
• Removed logic regarding "// if file does not exist or file size limit is not reached - do not add rolling file index" as it caused problems with the new logic (forces retrying to open busy files). The overall behaviour seems to be unchanged due to the circumstances in which this is now called.
• Added in tests for the new behaviour
• Slightly more defensive programming for a few disposes in case of Exception in Dispose, but again unlikely to explain the issue fully.

What I have not done is check whether concurrency issues could explain the issue at hand, somehow. It could be worth a think and I might revisit this if I can get the issue to be reproducible locally in the future.

Tests all pass locally.

[VitaliyMF]

@LeeReid1 first of all, thank you for the contribution!

I've reviewed the changeset and from the first sight I'm not sure that existing behavior remains the same in all cases. In particular, this change in "GetNextFileLogName" method, removed code snippet:

                // if file does not exist or file size limit is not reached - do not add rolling file index
                if (!System.IO.File.Exists(baseLogFileName) || 
                    FileLogPrv.FileSizeLimitBytes <= 0 || 
                    new System.IO.FileInfo(baseLogFileName).Length< FileLogPrv.FileSizeLimitBytes)
                    return baseLogFileName;

This condition is needed to prevent adding a suffix if no size limit or size limit is not reached for the current file. Have you tried to start .NET program several times without this code? It should create new log files on each start, even if rolling files are not used at all.

Also not sure that I understand the purpose of making "Close" method public -- since FileLoggerProvider implements IDisposable that makes graceful shutdown.

A lot of changes in the logic, I need more time to review them to ensure that backward compatibility is preserved. Will do that a bit later.

[LeeReid1]

I see the point you're making. I've tried to make a fix but I'm not sure it's right. Could you please clarify this for me:

The readme says that only one file will ever be made unless there's a file limit. I can keep that backwards compatible. It also reads that if MaxRollingFiles=2 there would be "log.txt" and "log1.txt". OK. Presumably, then, MaxRollingFiles=1 would create "log.txt" only. What does MaxRollingFiles=0 mean? (I would expect an OutOfRangeException or similar as -1 often signifies no limit, but doesn't appear to be the case)

Thanks!

[LeeReid1]

The commit above assumes MaxRollingFiles=0 means no limit on the number of files, but this is easy to change if MaxRollingFiles=0 has the same meaning as MaxRollingFiles=1.

[VitaliyMF]

@LeeReid1 I'm afraid it is not enough to have

                if (FileLogPrv.FileSizeLimitBytes <= 0) {
                    // Rolling files is disabled
                    // Always use the same file
                    return baseLogFileName;
                }

to get full backward compatibility. Even if FileSizeLimitBytes is set, anyway very-first log file doesn't have a suffix. For example, if baseLogFileName is "log.txt" then the following files are created:

• "log.txt"
• "log1.txt"
• "log2.txt" etc

This is why !System.IO.File.Exists(baseLogFileName) condition is checked. Another situation when FileSizeLimitBytes is set, but only one file exists "log.txt" but it doesn't reach the limit - so it can be used on the app start instead of creation "log1.txt". This is the purpose of condition new System.IO.FileInfo(baseLogFileName).Length< FileLogPrv.FileSizeLimitBytes.

In other words, to keep this logic the following code snippet should remain as-is:

                // if file does not exist or file size limit is not reached - do not add rolling file index
                if (!System.IO.File.Exists(baseLogFileName) || 
                    FileLogPrv.FileSizeLimitBytes <= 0 || 
                    new System.IO.FileInfo(baseLogFileName).Length< FileLogPrv.FileSizeLimitBytes)
                    return baseLogFileName;

[LeeReid1]

@VitaliyMF sorry, I don't follow entirely. I think you're saying that, if baseLogFileName is "log.txt", the desired behaviour is that the files created are "log.txt", "log1.txt", "log2.txt" so long as FileSizeLimitBytes is >0. If FileSizeLimitBytes <= 0, then you would only want log.txt to be created. Is that what you're saying? If so, please take a look at the tests I've added, particularly "ResumesToCorrectFile", which confirms that this behaviour remains unchanged. If I've misunderstood the desired behaviour or the test is wrong somehow, please let me know in what way I have misunderstood so I can fix it up :)

[VitaliyMF]

@LeeReid1 this is the case that, it seems, is not covered by your test. I remember about it because these conditions were added as a bugfix for:

• FormatLogFileName delegate is set and log file names are determined in run-time. Let's assume this is simply "log.txt" initially.
• when app is started initially DetermineLastFileLogName works fine and LogFileName value is correct ("log.txt")
• then, when app writes adds a log entry, WriteMessage calls CheckForNewLogFile which can call GetNextFileLogName where these conditions are needed to preserve the same behavior as in DetermineLastFileLogName

Without these conditions in the GetNextFileLogName may not use existing log file (overwrite it) even if should be used. Also, since GetNextFileLogName may return the same value, I'm a bit nervous about this logic in OpenNextAvailableFile:

                while (true)
                {
                    if (rotateFilename)
                    {
                        LogFileName = GetNextFileLogName();
                    }
......
                    if (!attempted.Add(LogFileName))
                    {
                        // We have tried this name before
                        // We have now tried all possible file names
                        throw new AggregateException("All log files returned IO exceptions", exceptions);
                    }
                    if (TryOpenFile(append, out IOException e))
                    {
                        return;
                    }

I understand that cycle will break when "GetNextFileLogName" will return the same file name twice (at least once), but what if it will return a lot of new files and all of them will fail to open (say, because a folder has incorrect permissions)? We should limit number of 'retries' no doubt here.

As for me, reuse of "GetNextFileLogName" to get another file name in case of File.Open failure is not the best solution in all situations, and as you see this may interfere with other features like FormatLogFileName. I understand that you already spend significant time for this code, but maybe it would be better to move File.Open failures outside of FileLoggingProvider at all? It is natural that things like that are application specific and may be handled in very different ways. This could be a delegate that is called on File.Open error and that can provide a new LogFileName (or handle an exception in its own way and simply disable file logging, or re-throw it whatever).

For example, in my application that uses NReco.Logging.File it is ok if .NET app fails when log file cannot be opened: anyway this means that something goes wrong on the server, and since app is under monitor I'll get an alert and will investigate the reason. This means that I simply don't want retry-logic enabled by default.

It seems NReco.Logging.File is used in many .NET Core apps (176k downloads on nuget.org) and I feel responsible to keep it fully backward compatible and do not allow any potential instability (it's easy to get bad side effects with changes that are added with a good will - like in log4j).

[LeeReid1]

Having a maximum number of re-attempts is easy but it sounds like you're not interested in dealing with the overall bug in this codebase even if I were to push that change. That's fine, I'll just use my branch personally. It's just been that NReco.Logging.File was crashing my Azure site several times per day (presumably whenever Azure chooses to restart the the process, which is commonplace) and I would be shocked if I were the only one because my set up is effectively vanilla. "Just not having logging" is not really a solution for me. As I said, the problem is gone for me using this merge so I'll continue to use it and stop trying to push the fix upon your work.

Thanks tons for the library anyway.

All the best.

[VitaliyMF]

@LeeReid1 I really appreciate all your efforts you made in this PR -- however it makes a lot of sense to discuss changes first (especially if these changes are potentially may break compatibility and affect stability) and only after the discussion implement an approach that will work not only for you but also for other lib users.

It is normal to use a fork - this is how github works, actually!

I've implemented another approach to deal with file errors here: https://github.com/nreco/logging/commit/59fc884cd687c5d5bf1643aa80aed2e32035e140

For now "HandleFileError" is only about files opening, however in the future it potentially may be used also for errors that may happen on file writes (for example, when disk is full and no free space).