AuditTo has limited configuration options

[jods4]

It seems we can't write an "audit" (i.e. "safe") log to a rolling file.

You can do:
config.WriteTo.File("audit.txt", rollingInterval: rollingInterval.Day, retainedFileCountLimit: 7)

But those options are not exposed in
config.AuditTo.File("audit.txt", ???)
which has much more limited options.

Could we have the same options in both situations?

[nblumhardt]

Hi!

I think the rolling options are lacking simply because no one has dug into what's required, yet - there would need to be some changes to the rolling file implementation to deal with this, although probably nothing huge. Some investigation would be great if anyone has time to look/come up with a proposal.

For some of the concurrency-related options, I don't think auditing will make sense or work correctly (IIRC).

Cheers,
Nick

[jods4]

Hi Nick!

I'm not sure I understand.

The main difference of audit logs is that they don't swallow failures, right?
Normally failure to log is silent (because app is more important than log);
but with AuditTo, failure to log is fatal (because audit logs can't be missing).

(And possibly more aggressive flushing? maybe?)

So if re-throwing exceptions is the key difference, how does it impact the feature set / exposed options of sinks?

The problem with file sink is that you can't have an ever-growing log. In real production usage you need some kind of rolling strategy.
Lack of clean-up makes file sink non-usable in production (with AuditTo).

[nblumhardt]

Hi @jods4 - not sure we're on the same page, I might not have been very clear in my reply.

The problem with file sink is that you can't have an ever-growing log. In real production usage you need some kind of rolling strategy. Lack of clean-up makes file sink non-usable in production (with AuditTo).

It sounds like we agree - it's just that no one has done the work. We were surprised after shipping AuditTo that almost no one uses it - there are only maybe three sinks in the whole Serilog ecosystem that have had support added (this one, the Seq sink, another that slips my memory), so coming back to add functionality hasn't made it to the top of the list, yet :-)

So if re-throwing exceptions is the key difference, how does it impact the feature set / exposed options of sinks?

The sinks need to be synchronous and unbuffered in order for the "auditing" guarantee to be met. In the case of the file sink, it would be inappropriate to expose buffered: true here, for example, since the write could then return without the event actually being recorded.

In the case of the rolling file sink, exceptions on file operations are suppressed at various points, so some work is needed to make sure that only the right exceptions propagate (we wouldn't want auditing to fail just because cleaning up an old file failed, for example).

[jods4]

OK I think I get it.
It's because you need to handle cleanup exceptions differently than logging exceptions.

I agree with you: it seems better if failure to clean up an old file doesn't crash the app, even in audit mode.

Good to know that in audit mode everything is sync-flushed 👍 .

[nblumhardt]

Unless someone beats me to it, I'll try to find some time in the near future to run through the code and figure out what's required. It would be very nice to round this feature out properly :-)

[maciejw]

@nblumhardt, I have spare time and I have some questions regarding this issue.

summary of current state of code:

on WriteTo we have two methods, one with ITextFormatter and the other that uses former with MessageTemplateTextFormatter

AuditTo has the same convention, it misses following:

            FileLifecycleHooks hooks = null,
            long? fileSizeLimitBytes = DefaultFileSizeLimitBytes,
            bool shared = false,
            RollingInterval rollingInterval = RollingInterval.Infinite,
            bool rollOnFileSizeLimit = false,
            int? retainedFileCountLimit = DefaultRetainedFileCountLimit

I removed buffered and flushToDiskInterval since is is not applicable in this case.

questions:

1. is it important to preserve parameter ordering between WriteTo and AuditTo? I think this will break contract now if we add those parameters is right places.
2. have you considered creation of builder class that could split this all this parameters in to meaningful groups. it would be nice to share some resemblance between write and audit, with this builder we could move differences to builder constructor and then similar configuration could follow?
3. do we want to to allow set shared to true? and in this case use SharedFileSink?
4. have you considered different orientation of api, now File hides 4 sinks maybe it would be better to make it more explicite (3 dedicated methods not one) since configuration parameters depend heavily on it? PeriodicFlushToDiskSink is just a decorator.
   5, Am I free to propose whatever change I like, or you want to constrain me in some way? :)

todo:

1. modify public configuration extension methods on LoggerAuditSinkConfiguration
2. audit code for proper exception handling in RollingFileSink - only
   exceptions related to writing events to file should be thrown.
3. ...

[nblumhardt]

Hi Maciej! Thanks for jumping in. Before your questions, just some brief commentary on those missing params:

            // Not sure about this one, think it's good for auditing 👍
            FileLifecycleHooks hooks = null,

            // Don't think this one is applicable unless `rollOnFileSizeLimit` is `true`:
            // the default behavior of dropping events would be inappropriate.
            long? fileSizeLimitBytes = DefaultFileSizeLimitBytes,

            // Think this is okay 🤔
            bool shared = false,

            // These seem fine, though the dependency between
            // `fileSizeLimitBytes` and `rollOnFileSizeLimit` suggest we should combine
            // them into a single `rollOnFileSizeBytes`, perhaps?
            RollingInterval rollingInterval = RollingInterval.Infinite,
            bool rollOnFileSizeLimit = false,

            // Unsure about this one, should the sink ever delete audit logs? Normally
            // another process would archive them... thoughts?
            int? retainedFileCountLimit = DefaultRetainedFileCountLimit

1. is it important to preserve parameter ordering between WriteTo and AuditTo? I think this will break contract now if we add those parameters is right places.

A new overload will be needed anyway, since any signature change (including the addition of defaulted params) is a binary breaking change in .NET. Seems like making the new overload use consistent parameter order is reasonable.

2. have you considered creation of builder class that could split this all this parameters in to meaningful groups. it would be nice to share some resemblance between write and audit, with this builder we could move differences to builder constructor and then similar configuration could follow?

Oddities like the rollOnFileSizeLimit thing could make this a bit arbitrary- ?

3. do we want to to allow set shared to true? and in this case use SharedFileSink?

Seems reasonable, though I'm not sure what the details look like.

4. have you considered different orientation of api, now File hides 4 sinks maybe it would be better to make it more explicite (3 dedicated methods not one) since configuration parameters depend heavily on it? PeriodicFlushToDiskSink is just a decorator.

Would like to avoid API churn at this stage, but it would have been a reasonable direction to consider back in the earlier stages of implementation :-)

5, Am I free to propose whatever change I like, or you want to constrain me in some way? :)

:-) certainly propose the changes you think will best suit the project goals. The bar for merging new functionality into this sink is high in terms of backwards-compatibility, minimal exposed API surface, and minimal future maintenance requirements, since it's very widely depended upon.g

Changing anything substantial also tends to have a long, time-consuming tail of work updating docs and answering questions on Stack Overflow (someone's always broken, etc. :-)) so the most conservative approach is usually the preferred one. We're always keen to spin up completely new sinks to try out the more radical ideas.

HTH!!

[maciejw]

this helps definitely,

I'll move current method and mark is as obsolete editor browsable never. As I understand source breaking change is acceptable? in this case I'll make sure that File parameters order in WriteTo and AuditTo are the same.
Overload with Action<FileConfiguration> would be definitely less painful, aspnetcore configuration is done this way and is pretty nice to me ;) FileConfiguration could have methods that change groups of parameters in logical manner. but this way of doing this is not present currently in Serilog l think.

            // Not sure about this one, think it's good for auditing 👍
            // M: I think so its good, but, exceptions from hooks should not propagate I think 
            FileLifecycleHooks hooks = null,

            // Don't think this one is applicable unless `rollOnFileSizeLimit` is `true`:
            // the default behavior of dropping events would be inappropriate.
            // M: 👍
            long? fileSizeLimitBytes = DefaultFileSizeLimitBytes,

            // Think this is okay 🤔
            // M: 👍
            bool shared = false,

            // These seem fine, though the dependency between
            // `fileSizeLimitBytes` and `rollOnFileSizeLimit` suggest we should combine
            // them into a single `rollOnFileSizeBytes`, perhaps?
            // M: 👍 this `rollOnFileSizeBytes` should be corrected in WriteTo also?
            RollingInterval rollingInterval = RollingInterval.Infinite,
            bool rollOnFileSizeLimit = false,

            // Unsure about this one, should the sink ever delete audit logs? Normally
            // another process would archive them... thoughts?
            // M: 👍, I'm sure it is bad idea to do cleanup here, since we have no way to know if files were backed up, I guess robocopy has convention that copies only files with archive attribute set and can reset it at the end, but it is too many assumptions... responsibility of cleanup should be elsewhere I think.
            int? retainedFileCountLimit = DefaultRetainedFileCountLimit

I'me sure I will come up with some issues during my work :) wish me luck :)

[nblumhardt]

👍 good luck! :-)

[maciejw]

@nblumhardt is there a reason why FileSink SharedFileSink RollingFileSink opens file differently?
I think it is better to open file in constructor, because I will be obvious that something is wrong during configuration phase, now for FileSink and SharedFileSink it is during configuration and for RollingFileSink during Emit.

is it ok to make it consistent across all sinks that create files, directly or indirectly?

[maciejw]

@nblumhardt another strange thing for infinite interval we will have _nextCheckpoint set to 30 minutes form now

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

Line 116 in 5b52dd2

_nextCheckpoint = _roller.GetNextCheckpoint(now) ?? now.AddMinutes(30);

after more then 30 minutes when we log something, file will be closed and opened again

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

Line 94 in 5b52dd2

else if (nextSequence || now >= _nextCheckpoint.Value)

because of second part of condition.

this means directory scanning, and when there is a lot of files in directory this could be an issue.

also what was a scenario for this comment

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

Lines 114 to 115 in 5b52dd2

	// We only try periodically because repeated failures
	// to open log files REALLY slow an app down.

when OpenFile throws after setting _nextCheckpint and _currentFile will not be set this comment means that we do not want to thow and catch on every OpenFile and there is no logs for 30 minutes?

[nblumhardt]

Hi @maciejw - thanks for the update.

Regarding the consistency of construction, and checkpointing open/close issue, it'd be great to explore and potentially address those as separate PRs, since including many changes/refactorings in the one large PR will make the review more difficult and slower. It's possible you've spotted some opportunities to improve - the codebase has evolved over time so we may have missed some things! Thanks for taking a look.

RE pausing for 30 minutes, that would be the case if there's no other rolling interval set; perhaps we can tighten this up 👍

[maciejw]

@nblumhardt I'll make absolutelly minimal changes to this PR, since I cannot swallow exception in AuditTo some change I have to make, to be sure we have a successfully logged event or error. for now I have started a draft PR #119, I noticed some problems in CI... I there was some problems in ubuntu configuration, but this error is not related to core I think, it is an error in msbuild git task...