New file is created every 30 minutes

[Falco20019]

Description
Related to #152
If using hooks that do not allow reopening a file, it force-creates a new one every 30 minutes for no real reason.

Reproduction
Use the following hook with a RollingFileSink with any big filesize limit (i.e. 1 GB) and inifite interval rolling:

public override Stream OnFileOpened(Stream underlyingStream, NetEncoding encoding)
{
    if (underlyingStream is { CanRead: false, Position: not 0 })
    {
        throw new IOException("It's not possible to reuse the log file since this requires ReadWrite permission on the stream.");
    }

    return underlyingStream;
}

Wait for 30 minutes and create a log entry after that (or just reduce the time to 1 millisecond here):

serilog-sinks-file/src/Serilog.Sinks.File/Sinks/File/RollingFileSink.cs

Lines 115 to 117 in 5e3ff41

	// We only try periodically because repeated failures
	// to open log files REALLY slow an app down.
	_nextCheckpoint = _roller.GetNextCheckpoint(now) ?? now.AddMinutes(30);

Due to the checkpoint being checked on the next log being written, it will enforce a reload, leading to the hook failing in this location:

serilog-sinks-file/src/Serilog.Sinks.File/Sinks/File/RollingFileSink.cs

Lines 95 to 108 in 5e3ff41

	else if (nextSequence || now >= _nextCheckpoint.Value)
	{
	int? minSequence = null;
	if (nextSequence)
	{
	if (_currentFileSequence == null)
	minSequence = 1;
	else
	minSequence = _currentFileSequence.Value + 1;
	}
	CloseFile();
	OpenFile(now, minSequence);
	}

Expected behavior
The log file will correctly be used until something goes wrong. It will NOT try to reopen the file every 30 minutes and create a new log file messing up the retention.

Relevant package, tooling and runtime versions
Serilog.Sinks.File 6.0.0 but also tried to self-compile it from dev

Additional context
Due to the issue from #152 it's not possible to reopen files just leasurely. As encryption would need to remove the padding and re-read the IV, it requires ReadWrite permission. This needs to be enforced for it to work at all. But due to the RollingFileSink just setting the next checkpoint to 30 minutes if not needed at all, this leads to the issue of retention deleting needed files. There is currently no workaround possible with encryption enabled and using a rolling file sink right now.

Please either fix #152 to support ReadWrite or at least make sure that the checkpoint is set in a way that does not reopen the file without need to only run into it on restarts instead of every 30 minutes on runtime :) This will at least hit the retention less as restarts aren't happening often.

[yoav-melamed]

Hi @Falco20019
I built a new sink called AsyncFile (https://github.com/yoav-melamed/serilog-sinks-asyncfile)
Can you please share your use-case so I can check if I'm currently supporting it on my sink?

[Falco20019]

@yoav-melamed The use case is to wrap the file stream into a new CryptoStream(stream, Algorithm.CreateEncryptor(key, iv), CryptoStreamMode.Write) call (using Aes.Create() as Algorithm and a per-file seeded iv = Algorithm.GenerateIV() with configured application-wide key). Since AES CBC uses padding when closing/flushing the file, on re-open you would have to remove the padding first (checking the last two blocks, where the first is the sequence IV and the last is the padded block, that needs to be re-written without padding).

To be able to continue writing to this file, you would seek back to that position, and wrap the stream with this IV and re-write the block, returning that stream for further writes. Therefore ReadWrite is technically required to a) get the IV and b) remove the padding. As there's also no way to access the file i.e. through a different stream since the path is not propagated. I tried checking for FileStream which has the path to create a second read-stream to get this information since Seek is supported. But the passed stream is wrapped with (internal only class) WriteCountingStream if size-rotation is enabled and that has no parent property. So it's not working reliable for all configurations as-well.

So I run out of ideas, and avoiding the re-opening (which seems like an unintended side-effect of the recheck if multiple opens fail) would already solve the issue during runtime, while it still is no solution for continuation on startup.

#152 shows more details on a similar use-case with some code. I tried to focus in this bug ticket only on the reopening issue.

[Falco20019]

@nblumhardt If you could acknowledge that the reopening of non-faulted streams is not intentional, I could offer to work on a PR fulfilling this assumption. I just wanted to wait to not implement something that doesn't fulfill the correct boundary.

[nblumhardt]

Thanks for checking in @Falco20019.

that the reopening of non-faulted streams is not intentional

Unfortunately I'd need to spend some time digging into this; it's possible that the the reopening mechanism currently provides some level of recovery/resilience we'd lose making the change. I agree that the current behavior has some drawbacks 🤔 .. I'll try to loop back this week, unfortunately out of time today.

[Falco20019]

@nblumhardt Friendly ping since it had been 3 weeks :)

[yoav-melamed]

@Falco20019 Sorry, somehow I missed the comment you left for me!
Your goal is to encrypt the log file? encrypt it and add the public key or the signature at the end of the file before closing the stream? or I got it all wrong?

[Falco20019]

@yoav-melamed AES is symmetric encryption. So you have an IV and not a public key. In CBC it's always IV + Enc Data + Enc Data + ... so you have to read the initial block. Each previous block is used as IV for the next one. At the end you might have padding to get the last block to expected length. That needs to be removed and rewritten to the stream to be able to continue writing afterwards as you might ended on length % BlockSize != 0 byte.

[nblumhardt]

Hi @Falco20019,

I think we do want to fix this issue 👍

But, if the file is unable to be opened, I think the fix needs to retain the property that we'll retry opening it every 30 minutes as we do today. Hopefully that way, we'll have our cake and eat it too :-)

What do you think?

[Falco20019]

Absolutely correct and what the comment suggests. I would just have assumed there to be a flag to mark IF the opening failed. Doing the check ever 30 minutes even if it didn't fail is fine, as long as it's only reopening if necessary.