Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

New file is created every 30 minutes #334

Open
Falco20019 opened this issue Jan 24, 2025 · 9 comments · May be fixed by #337
Open

New file is created every 30 minutes #334

Falco20019 opened this issue Jan 24, 2025 · 9 comments · May be fixed by #337
Labels
bug

Comments

@Falco20019
Copy link

Falco20019 commented Jan 24, 2025 •
edited
Loading

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.
@Falco20019 Falco20019 added the bug label Jan 24, 2025
@yoav-melamed
Copy link

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
Copy link
Author

Falco20019 commented Jan 27, 2025 •
edited
Loading

@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
Copy link
Author

Falco20019 commented Jan 29, 2025 •
edited
Loading

@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
Copy link
Member

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
Copy link
Author

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

@yoav-melamed
Copy link

@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
Copy link
Author

Falco20019 commented Feb 18, 2025 •
edited
Loading

@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
Copy link
Member

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
Copy link
Author

Falco20019 commented Feb 20, 2025 •
edited
Loading

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.

@Falco20019 Falco20019 linked a pull request Feb 20, 2025 that will close this issue
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix issue with force-reopen after 30 minutes Falco20019/serilog-sinks-file
3 participants
@nblumhardt @Falco20019 @yoav-melamed