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...

[dbones]

hi

This has gone a bit quiet on this thread, I had posted here origonally #175, which looks to be an overlap.

It would be excellent to use Serilog to support Audit.NET (thepirat000/Audit.NET#324)

If it helps, the concept is to host a service in a K8s Pod. The service will write is audit to the local file (using these libraries), and then use a sidecar to watch the file. we need the file to be rolling and not long-lived, as the contents are exported via FluentD to a main Centralised Auditing SEIM solution

side car pattern- https://kubernetes.io/docs/concepts/cluster-administration/logging/#using-a-sidecar-container-with-the-logging-agent

[jods4]

Reviving this old issue because I just had some trouble in production caused by it.

@nblumhardt Is there any hope of fixing at least the first point below? Can I try to open a PR for that, any specific directions? I note there was a PR previously opened but it was never merged, could we revive that?

Two settings stand out as issues for me:

1. Most important one is the absence of rolling files.
   This means data is never deleted, which is just unacceptable for production.
   Notice that it can't even be manually deleted (e.g. after being archived by another process), because everything is written in a single file (this is, by definition, part of the rolling file feature regardless of cleaning period).

2. Less important but annoying is the lack of shared: true support, because by default IIS performs overlapped recycles, which then crash because of exclusive access to an audit log file.
   EDIT: rolling files is a work-around here, as it would add a suffix to the filename when the target file is locked, so it creates a new file and doesn't crash. As there is no rolling file support, audit logs just crash.

[nblumhardt]

Thanks for the ping, @jods4!

I'm not sure about the final state of the PR - IIRC there was still some work to do. Paging that back in now could take some time. Still very much open to it, but would need to be attempted in a minimal/nonbreaking way, e.g. by creating a new RollingAuditFileSink type in the background so as to avoid issues in RollingFileSink, and to make correctness easier to review.

RE 1), a reasonable option right now might be to add AuditTo.Map(), where in this case the map key selection would be e.g. the date part of the filename:

    .AuditTo.Map(
        le => le.Timestamp.Date.ToString("yyyy-MM-dd"),
        (date, auditTo) => auditTo.File($"audit-{date}".txt)) 

The open file limit arg to Map() can be used to ensure old files aren't kept open. (WriteTo.Map() already exists, it's part of Serilog.Sinks.Map.)

Not a perfect long-term solution, but should work pretty well - let me know if I haven't done a great job of explaining this!

RE 2), could be interesting to tackle separately, I'm not sure what's involved.

No time at my end to try these in the short term, unfortunately. HTH!

[jods4]

Hi Nicholas!

Thanks for the quick reply, it's very appreciated.

As I needed some quick fix in production and creating a new PR would probably add much delay, I decided to pursue a different route.
As our app recycles every night, when it starts up I have coded some manual clean up:

• We have IIS configured with non-overlapped recycling, so no sharing/locking issues;
• When the app restarts I rename the current file, then delete all files that match the pattern and are older than some threshold.

In the long term, addressing this issue would be a better solution, especially for users that don't have the luxury of frequent restarts.

It's also worth noting that there is no error or warning when your configuration file (JSON format here), specifies unsupported options like rollingInterval or retainedFileCountLimit. So you may believe you're all good but you're not (this is not an issue with API-based configuration, as there simply is no overload with those parameters).

[TheStopsign]

Definitely looking for this configuration as well (bump)

[smakitech]

I've recently faced the requirement to maintain audit logs for app in healthcare domain. Audit capabilities of File sink are considered as decent and simplistic option to leverage, but lack of rolling settings prevents customer from giving agreement to integrate this. I vouch that rolling configuration for audit file is essential and craved so as to start efficient usage of this capability in the production. Are there any plans of implementing rolling configuration in the near term?

[nblumhardt]

Needs a high-quality PR with a nonbreaking implementation. Definitely open to supporting this, but not currently able to allocate any time to it. Thanks for the nudge, though!