Compressing rolled files

[lraulea]

I'm really struggling to find a way to zip the rolled old fromFile, at the moment that log4net decides to rollover on date. I don't see any direct way to get notified if a log file was rolled, only indirectly and incomplete.

My kind request is to implement ALT-3, if possible.

ALT-1: override RollOverRenameFiles() method

protected override void RollOverRenameFiles(string baseFileName)
{
    base.RollOverRenameFiles(baseFileName);
    //do zip
}

Result= NOK
-only works for rollover based on size
-for rollover based on date, this method is not called, no zip

ALT-2: override AdjustFileBeforeAppend() method

protected override void AdjustFileBeforeAppend()
{
   var currentFile = File;
   base.AdjustFileBeforeAppend();
   if (!currentFile.Equals(File))
   {
      //do zip
   }
}

Result= NOK
-works for rollover based on size on same day
-when crossing a date boundary, currentFile differs from File => zip OK
-when starting the main app the next day, it misses the previous day file => no zip

ALT-3: override RollFile(string fromFile, string toFile) method

protected override void RollFile(string fromFile, string toFile)
{
   base.RollFile(string fromFile, string toFile);
   //do zip on 'fromFile'
}

Cannot override now because method is not virtual

So, my request is: could this RollFile() be made virtual?

Thanks!

Greetings,
Liviu

[FreeAndNil]

@lraulea can you take a look at #205 and #206 ?
Does this solve your problem?

[lraulea]

@FreeAndNil thanks for replying!

Short answer = No

I was already aware of this feature (it is my ALT-1 above) but unfortunately it does not cover the rolling-on-date use case. Only works on rolling-on-size. As I saw during my testing.

So, I'd like to override a method that log4net calls exactly one time when log4net decides to roll (on size or on date). My impression is that this method is RollFile() but a different method that carries the fromFile is also ok for me.

[FreeAndNil]

@lraulea I got it.
Does #237 fix your problem?

[lraulea]

@FreeAndNil thanks for the quick modification of the code!

I've seen the code change, it is what I think it could solve my problem.

To be sure it fixes my problem, I need to test it in my environment and see the zips being created.

I'm using now a nuget package reference in my project, would it be possible to create a beta log4net nuget package for testing?

[FreeAndNil]

@lraulea I've published https://github.com/apache/logging-log4net/releases/tag/rc%2F3.0.5-preview.1
Nuget: https://www.nuget.org/packages/log4net/3.0.5-preview.1

[lraulea]

@FreeAndNil Excellent! Thank you.

Let me test it tomorrow. I'll get back with the test results.

[lraulea]

Unfortunately ALT-3, overriding RollFile(string fromFile, string toFile) does not work :-( pity

I see the new rolled files being created in File Explorer, but for some reason the RollFile() method is never called, not on rollover on size, not on rollover on time, . . .

I see the overriding of RollOverRenameFiles() method being called (only upon rollover on size, not on date).

@FreeAndNil Any thoughts? How to create a zip of the oldFile when log4net decides to roll (on size or date)?

[FreeAndNil]

@lraulea can you set a breakpoint in RollOverTime()?
Can you post your log4net configuration?

[lraulea]

@FreeAndNil Sure, let me check it tomorrow.

[lraulea]

Below the configuration data

Still TODO: set a breakpoint in RollOverTime()

class CustomRollingFileAppender : RollingFileAppender
{
    public CustomRollingFileAppender(CustomAppender customAppender)
    {
        //create new PaternLayout, .AddConverter, .ActivateOptions
        Name = customAppender.Name;
        AppendToFile = true;
        File = customAppender.File;
        DatePattern = "'-'yyyyMMdd"; //for testing = "'-'yyyyMMddHH"
        PreserveLogFileNameExtension = false;
        CountDirection = 0;
        Layout = patternLayout;
        ImmediateFlush = true;
        MaxSizeRollBackups = -1;  //managed outside log4net
        MaximumFileSize = "256MB";
        RollingStyle = RollingMode.Composite;
        StaticLogFileName = false;
    }

    protected override void RollFile(string fromFile, string toFile)
    {
        base.RollFile(fromFile, toFile);
        //log to a logfile1 fromFile param
        //logfile1 empty
    }

    protected override void RollOverRenameFiles(string baseFileName)
    {
        base.RollOverRenameFiles(baseFileName);
        //log to logfile2 baseFileName param
        //logfile2 only contains entries from rollover on size
    }

    protected override void AdjustFileBeforeAppend()
    {
        var currentFile = File;
        base.AdjustFileBeforeAppend();
        if (!currentFile.Equals(File))
        {
            //log to logfile3 currentFile, File params
            //logfile3 only contains entries from rollover on size
            //AdjustFileBeforeAppend called on rollover on time, but currentFile == File
        }
    }
}

[FreeAndNil]

@lraulea in AdjustFileBeforeAppend() "File" only changes when log4net already has a file open and decides to close it and create a new one.
Maybe in your case, you have a old log file which the current process never had opened (because an old instance created it). In this case there is no rollover.
I personally use a powershell script to compress the outdated log files. This has the advantage of not blocking the thread which just wants to log a line with compressing a maybe large logfile.

[lraulea]

@FreeAndNil Current process is running before and after the top-of-the-hour, but AdjustFileBeforeAppend misses the rollover on time => correction: it does not miss, sorry, just retested.

About the TODO: breakpoint added in RollOverTime() base, no hit after crossing the top-of-the-hour.

Any thoughts on why the RollOverTime() is never called upon rolling on date?

[FreeAndNil]

Current process is running before and after the top-of-the-hour

Does the process log something before top-of-the-hour?
Is the process stopped between?

[lraulea]

Yes, it logs.
The file *-202503301504.log.0 contains 3 KB
The next created file *-202503301505.log.0 contains 1 KB
No, the process is not stopped in between 15:04 and 15:05 o'clock.

I would expect that RollFile() is always called when rolling. But it seems not the case.

Thanks for your help. I'll continue debugging next week.

[lraulea]

@FreeAndNil Just to conclude the day with good news.

protected override void AdjustFileBeforeAppend()
{
    var currentFile = File;
    base.AdjustFileBeforeAppend();
    if (!currentFile.Equals(File))
    {
        //log currentFile, File params to logfile3        
        //logfile3 contains entries from rollover-on-size, and the rollover-on-date
        //I can async zip currentFile here
    }
}

Use-case 1: process is running

The above override of AdjustFileBeforeAppend() works actually just fine during my latest tests. Sorry for the confusion. I thought I've seen few times that the zip was not done, but I cannot reproduce the issue, I have to look further here.

Use-case 2: process (app) is restarted after the top-of-the-hour

A log file has been created, the app has been closed, after the rollover date moment the app is restarted. The AdjustFileBeforeAppend() has currentFile equal to File (!). Consequence of this is that the file created in previous instance, is left unzipped. @FreeAndNil any thoughts how I can use log4net to zip files between instances of the same process?

[FreeAndNil]

@lraulea You can override OpenFile() and check (before base.OpenFile()) whether the file already exists.
When it already exists, you can zip and delete it.

[lraulea]

@FreeAndNil override OpenFile(), interesting, I'll investigate it, thank you.

[lraulea]

@FreeAndNil as far as I'm concerned, you can reject #237

[lraulea]

@lraulea You can override OpenFile() and check (before base.OpenFile()) whether the file already exists. When it already exists, you can zip and delete it.

@FreeAndNil I've done some testing.

My existing files are all *-202503312012.log.0 and so on.

The fileName that comes in the override of OpenFile(string fileName, bool append) does not contain the DatePattern "'-'yyyyMMddHH" and the .log.0 extension.

As a result the fileName never exists.

I have StaticLogFileName = false; which means that the fully qualified file name is determined after base.OpenFile() by fileName = GetNextOutputFileName(fileName);

?

[lraulea]

Before base.OpenFile(), I probably need to get the list of existing files Directory.EnumerateFiles(Path.GetDirectoryName(fileName), $"{fileName}*.log.*") and just zip them.

[FreeAndNil]

Good idea.

[lraulea]

@FreeAndNil thanks for your help!

[lraulea]

@FreeAndNil may i share with you a test result?

overriding the OpenFile() looks promising, but I'm not there yet.

        protected override void OpenFile(string fileName, bool append)
        {
            ProcessFileBeforeOpen(fileName, append);

            base.OpenFile(fileName, append);
        }

        private void ProcessFileBeforeOpen(string baseFileName, bool append)
        {
            string traceFile = Path.Combine(_traceLogPath, "Logger-Log4net-OpenFile-Trace.log");
            string logEntry = $"{DateTime.Now}, ProcessFileBeforeOpen > (baseFileName = {baseFileName.Remove(0, baseFileName.LastIndexOf('\\') + 1)}, append = {append})" + Environment.NewLine;

            string tracesDirectory = baseFileName.Remove(baseFileName.LastIndexOf('\\'));
            var traceLogFiles = Directory.EnumerateFiles(tracesDirectory, $"*{baseFileName.Remove(0, baseFileName.LastIndexOf('\\') + 1)}*.log.*");

            foreach (var logFile in traceLogFiles)
            {
                if (!Path.GetExtension(logFile).Equals(".tip"))
                {
                    try
                    {
                        System.IO.File.Move(logFile, logFile + ".tip");
                        logEntry += $"{DateTime.Now}, ProcessFileBeforeOpen | logFile {logFile.Remove(0, logFile.LastIndexOf('\\') + 1)} (.tip added)" + Environment.NewLine;
                    }
                    catch (Exception ex)
                    {
                        logEntry += $"{DateTime.Now}, ProcessFileBeforeOpen | logFile {logFile.Remove(0, logFile.LastIndexOf('\\') + 1)} ({ex.Message.Remove(ex.Message.LastIndexOf('.'))})" + Environment.NewLine;
                    }
                }
                else
                {
                    logEntry += $"{DateTime.Now}, ProcessFileBeforeOpen | logFile {logFile.Remove(0, logFile.LastIndexOf('\\') + 1)} (nothing to be done)" + Environment.NewLine;
                }
            }

            logEntry += $"{DateTime.Now}, ProcessFileBeforeOpen < ()";

            using (StreamWriter outputStream = new StreamWriter(path: traceFile, append: true))
            {
                outputStream.WriteLine(logEntry);
            }
        }

You can override OpenFile() and check (before base.OpenFile()) whether the file already exists. When it already exists, you can zip and delete it.

Results:

4/1/2025 3:33:59 PM, ProcessFileBeforeOpen > (baseFileName = CM-Starter, append = True)
4/1/2025 3:33:59 PM, ProcessFileBeforeOpen < ()
4/1/2025 3:33:59 PM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = True)
4/1/2025 3:33:59 PM, ProcessFileBeforeOpen < ()
4/1/2025 3:33:59 PM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = True)
4/1/2025 3:33:59 PM, ProcessFileBeforeOpen | logFile LM-Starter-202504011533.log.0 (.tip added)
4/1/2025 3:33:59 PM, ProcessFileBeforeOpen < ()
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = False)
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen | logFile LM-Starter-202504011533.log.0 (The process cannot access the file because it is being used by another process)
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen | logFile LM-Starter-202504011533.log.0.tip (nothing to be done)
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen < ()
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen > (baseFileName = CM-Starter, append = False)
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen | logFile CM-Starter-202504011533.log.0 (The process cannot access the file because it is being used by another process)
4/1/2025 3:34:01 PM, ProcessFileBeforeOpen < ()

The following line is unexpected:

4/1/2025 3:33:59 PM, ProcessFileBeforeOpen | logFile LM-Starter-202504011533.log.0 (.tip added)

because LM-Starter-202504011533.log.0 has just been created just two lines above.

It seems there are two OpenFile() calls on opening LM-Starter-202504011533.log.0

The second OpenFile() call zips it (tips it in this test) but the second OpenFile() still creates LM-Starter-202504011533.log.0

@FreeAndNil do you recognize this double OpenFile()? It looks intermitent, not always.

[FreeAndNil]

@lraulea can you check whether this also occurs with the changes from #232 ?
There is an important fix for RollingFileAppender.

[lraulea]

can you check whether this also occurs with the changes from #232 ?

Sure!
Is there a preview nuget version I can consume?

@lraulea I've published https://github.com/apache/logging-log4net/releases/tag/rc%2F3.0.5-preview.1 Nuget: https://www.nuget.org/packages/log4net/3.0.5-preview.1

I've tested with 3.0.5-preview.1, probably #232 is not part of this

[FreeAndNil]

@lraulea I've published https://github.com/apache/logging-log4net/releases/tag/rc%2F3.0.5-preview.2 with the relevant changes.

[lraulea]

@FreeAndNil unfortunately not much better

I've noticed that these 191 bytes are actually empty files.

Quite many empty files are created, sometimes I get the impression that the empty files are re-created because the creation data changes.

4/2/2025 10:11:03 AM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = True)
4/2/2025 10:11:03 AM, ProcessFileBeforeOpen < ()
4/2/2025 10:11:03 AM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = True)
4/2/2025 10:11:03 AM, ProcessFileBeforeOpen | logFile LM-Starter-202504021011.log.0 (Moved to .tip succeeded, file size 191)
4/2/2025 10:11:03 AM, ProcessFileBeforeOpen < ()
...
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = True)
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen | logFile LM-Starter-202504021011.log.0 (Move to .tip failed: Cannot create a file when that file already exists, file size 191)
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen | logFile LM-Starter-202504021011.log.0.tip (Nothing to be done to .tip file)
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen < ()
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen > (baseFileName = LM-Starter, append = True)
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen | logFile LM-Starter-202504021011.log.0 (Move to .tip failed: Cannot create a file when that file already exists, file size 191)
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen | logFile LM-Starter-202504021011.log.0.tip (Nothing to be done to .tip file)
4/2/2025 10:11:07 AM, ProcessFileBeforeOpen < ()
...
4/2/2025 10:12:00 AM, ProcessFileBeforeOpen > (baseFileName = PF-System, append = False)
4/2/2025 10:12:00 AM, ProcessFileBeforeOpen | logFile PF-System-202504021011.log.0 (Move to .tip failed: The process cannot access the file because it is being used by another process, file size 192)
4/2/2025 10:12:00 AM, ProcessFileBeforeOpen | logFile PF-System-202504021011.log.0.tip (Nothing to be done to .tip file)
4/2/2025 10:12:00 AM, ProcessFileBeforeOpen < ()
4/2/2025 10:12:41 AM, ProcessFileBeforeOpen > (baseFileName = EM-Starter, append = False)
4/2/2025 10:12:41 AM, ProcessFileBeforeOpen | logFile EM-Starter-202504021011.log.0 (Move to .tip failed: The process cannot access the file because it is being used by another process, file size 191)
4/2/2025 10:12:41 AM, ProcessFileBeforeOpen < ()
...

Let's get a step back and see what the use case was:

a log file has been created, the app has been closed, after the rollover date moment the app is restarted. The AdjustFileBeforeAppend() has currentFile equal to File (!). Consequence of this is that the file created in previous instance, is left unzipped.

@FreeAndNil could this new zip-old-rolled-file feature be cleanly built inside log4net? Hooking into log4net with overrides seems too complex.

[FreeAndNil]

@lraulea it is possible to implement this feature inside log4net.
But it will take some time.

You can consider sponsoring me.

[lraulea]

Great!
Sure, let me see what are the possibilities.

[lraulea]

let me see what are the possibilities.

@FreeAndNil I'll have to come back on this next week

[lraulea]

@FreeAndNil still on going, next week I know more.
Do you already know how much time it will take you?
And approximately when it will be ready?

[FreeAndNil]

@lraulea I’m planning to dive deeper into the topic this week and next. Once I’ve had a proper look, I’ll be in a better position to estimate how long it might take.

[lraulea]

@FreeAndNil thanks 🙏