serilog-sinks-file icon indicating copy to clipboard operation
serilog-sinks-file copied to clipboard

Support atomic append on .NET 7+

Open nblumhardt opened this issue 3 years ago • 14 comments

This is available now via FileSystemAclExtensions.Create(), added in .NET Core 3.

Some context in an earlier post: https://nblumhardt.com/2016/08/atomic-shared-log-file-writes/

Current status: https://github.com/dotnet/runtime/issues/53432#issuecomment-850532304

Thanks @adamsitnik for the nudge! :-)

nblumhardt avatar May 28 '21 21:05 nblumhardt

I have read everything in the links above. I see the pull request was open then closed then a new "Draft" style PR created and exists in the Done column of the System.IO - FileStream project the dotnet/runtime. @adamsitnik I don't understand what done means if no code is merged, could you shed some light on the progress, I just can't tell if atomic append is moving forward or not.

This is a feature I am hoping for. I have a need to write to a single log file using Serilog's simple file sink on Linux. All files are rolled by a Linux utility called Logrotate by convention in deployed environment. Logrotate truncates the original file and as Serilog continues to write the file is typically prefixed with NUL bytes.

Originally when I first noticed this I was not setting shared to true on the file sink. Mind you, I did not know about this current issue or Adam’s work on atomic appends. I just had this post from @nblumhardt and it was from 2016. So I set the flag and started experimenting by running two instances of an app appending to the same file for experiment. Looked good and was hoping it would play well with Logrotate on Linux.

So, I deployed to my Linux machine and put a load on the service to produce logs that would roll on schedule. Ran for a few hours and things looked pretty good, no more NUL characters. But after 12 plus hours I did encounter the problem again and this time Serilog file sync just stopped logging and the last file rolled ended with NUL characters prefixed in the rolled file. So, no it did not work,

My conclusion is to stop using the Linux Logrotate utility in the meantime. Just start using rolling file sink. But our convention is, all applications such as Java applications are to append to their own single file and as a convention let Logrotate handle rotation. .NET Core apps deployed to Linux are the new kids on the block and these behavioral differences make for a slow adoption.

I am really looking forward to real atomic append solution. Thank you to @nblumhardt and @adamsitnik for all the hard work you put in and sharing.

JoeShook avatar Dec 14 '21 00:12 JoeShook

Another solution I've had suggested for Linux is to use a syslog sink and log to syslog server and let that handle the log files as appropriate.

tjmoore avatar Feb 01 '22 14:02 tjmoore

I have lots of logging duplication/overlap between the host (linux + logrotate) and the server app (aspnet + serilog).

But this is a long-standing issue, so I assume it's complicated.

In the meantime, does anyone have a workaround (i.e. to get serilog and logrotate to work together)?

lonix1 avatar Jun 06 '22 01:06 lonix1

I'm using syslog now to handle writing to files and this syslog sink - https://github.com/IonxSolutions/serilog-sinks-syslog

.NET then is not clashing with logrotate as it doesn't write direct to log files.

Though there are limitations, such as requiring a syslog service or server running. Platform I'm using only has the basic syslog service running which doesn't support structured logging and the syslog sink doesn't support RenderedCompactJsonFormatter to format in NDJON messages for structured text logs (not sure if that would confuse serilog anyway).

tjmoore avatar Jun 06 '22 11:06 tjmoore

That's a pretty clever solution! Sadly in my environment we don't use it. Thanks for the good workaround.

lonix1 avatar Jun 06 '22 12:06 lonix1

I am redirecting ">>" all output from the dotnet app to a file. Like bash -x appname >> mylog.log 2>&1 Then I just log to console from dotnet and the logrotate NUL insert issue goes away. So I am letting bash handle the file write. :)

JoeShook avatar Jun 16 '22 18:06 JoeShook

@tjmoore

the syslog sink doesn't support RenderedCompactJsonFormatter to format in NDJON

Not out of the box, but formatters are pluggable! Just create your own implementation of ISyslogFormatter, with reference to the existing formatters - there's not to much to it, and they'd happily accept a PR too 👍

cocowalla avatar Jun 16 '22 19:06 cocowalla

@JoeShook That's quite smart. But when logging to console (and thus indirectly to file via bash redirection), it's human readable - don't you lose the structured logging?

lonix1 avatar Jun 17 '22 12:06 lonix1

@lonix1, in my case I am not using structured logging. I am not sure how structured logging issues are different between using a file sink vs console sink. Using a console sink and redirecting to file via bash just solved the linux "logrotate" utility issue by removing dotnet non-atomic writes from the flow.

JoeShook avatar Jun 17 '22 20:06 JoeShook

@JoeShook If I remember correctly, the console logger doesn't do structured logging. So although it's an excellent workaround, there is a tradeoff - native log rotation vs structured logging. Thanks for your advice.

lonix1 avatar Jun 18 '22 00:06 lonix1

I don't understand what done means if no code is merged, could you shed some light on the progress, I just can't tell if atomic append is moving forward or not.

I have failed to convince others on the .NET Team that FileMode.Append should use atomic appends by default because they believe that it should still allow for seeking:

https://github.com/dotnet/runtime/pull/55465#issuecomment-901830491

@JoeShook please send a new proposal to dotnet/runtime (you can see my old proposal here: https://github.com/dotnet/runtime/issues/53432)

adamsitnik avatar Jun 23 '22 12:06 adamsitnik

@adamsitnik That is an interesting problem. Maybe it could be solved with a new option, e.g. FileMode.AtomicAppend.

Also, I am now confused :) ... are you saying this feature in serilog is still impossible?

lonix1 avatar Jun 23 '22 14:06 lonix1

I've tried the solution using FileSystemAclExtensions.Create(), and it works. It seems that this API is broken in .NET 6, and resolved in .NET 7. So this solution only works on .NET 7 on Windows. Enable ATOMIC_APPEND and, in SharedFileSink.AtomicAppend.cs, replace new FileStream() with CreateFile():

        private static FileStream CreateFile(string path, FileMode mode, FileSystemRights rights, FileShare share, int bufferSize, FileOptions options)
        {
            // FileSystemRights.AppendData sets the Win32 FILE_APPEND_DATA flag. On Linux this is O_APPEND
#if NET48
            _fileOutput = new FileStream(path, mode, rights, share, bufferSize, options);
#else
            // In .NET 7 for Windows it's exposed with FileSystemAclExtensions.Create API
            if (System.Runtime.InteropServices.RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
            {
                var _fileOutput = FileSystemAclExtensions.Create(new FileInfo(path), mode, rights, share, bufferSize, options, new FileSecurity());

                // Inherit ACL from container
                var security = new FileSecurity();
                security.SetAccessRuleProtection(false, false);
                FileSystemAclExtensions.SetAccessControl(new FileInfo(path), security);

                return _fileOutput;
            }
            else
            {
                throw new NotSupportedException();
            }
#endif
        }

bocca avatar Jul 14 '23 14:07 bocca

Thanks for the investigation, @bocca! It would be great to be able to support this 😎

nblumhardt avatar Jul 19 '23 22:07 nblumhardt