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.

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

KeepOpen and KeepOpenAndAutoFlush are not working #30

Closed
srivathsanvlb opened this issue Sep 17, 2024 · 10 comments
Closed

KeepOpen and KeepOpenAndAutoFlush are not working #30

srivathsanvlb opened this issue Sep 17, 2024 · 10 comments

Comments

@srivathsanvlb
Copy link

When I use the logger with Open Temporarily, is working fine. The issue I am facing in that is when I write lot of logs parallely I loose some logs.

Hence I just changed FileAccessMode to KeepOpen or KeepOpenAndAutoFlush. I didn't change anything else in my app.

I ran my console app for quite a while that writes a lot of logs. When I use KeepOpenAndAutoFlush, I see only the first log. When I tried with KeepOpen I see no logs. I also tried stopping the console app gracefully and waited for a while to see if logs get written. But no luck.

What am I missing?

@adams85
Copy link
Owner

adams85 commented Sep 17, 2024

This sounds like you have two competing file logger provider instances in your application. A situation like the one that was discussed here. Misconfiguration of DI can lead to such issues.

If this is not the case for you, then please send me some more details about your setup: OS type, OS version, .NET version, logger package version, etc. It would be the best if you could send me an MRE (minimial, reproducible example), that is, a simplified, working version of your application that's able to produce the issue.

@adams85
Copy link
Owner

adams85 commented Sep 17, 2024

One more thing that came to my mind in the meantime: have you tried the DiagnosticEvent callback as it's suggested here? If there happen to be two queues that want to write to the same file, this will show you (you'll get some IO errors).

@srivathsanvlb
Copy link
Author

srivathsanvlb commented Sep 18, 2024

Thanks for the prompt reply @adams85

Let me try the above. When I said "no logs" in the issue, I see the log file created but its empty. Just wanted to add that information here. Let me get back with results.

@srivathsanvlb
Copy link
Author

Hi @adams85

Regarding your request for MRE, sorry to say it is not possible since your library is integrated to one of our corporate libraries and I am in turn using that corporate library to one of the console apps. But I can say the corporate library team has followed your documentation

Here are my observations so far

  1. As I said in the issue Open Temporarily works ie I am able to see logs in the log file but with some logs lost. For example when I use the below code snippet. I don't see all 1000 logs.

         var numbers = Enumerable.Range(0, 1000).ToList();
         Parallel.ForEach(numbers, async x =>
         {
             _logger.Log(LogLevel.Information, $"{x} Execution started");
    
             await Task.Delay(1000);
         });
    
  2. I switched to the below setting. It did not work without the BasePath for some obvious reason. I was either getting an empty file of 0 byte size or a file with only the first log statement written, but the file was of size 154 b always for some reason. Once I had the base path it worked and I had all logs written into it. But I executed from VS 2022. My computer is a windows 10 machine. I can give you more info on it if you need.

"File": {
"BasePath": "bbb",
"FileAccessMode": "KeepOpenAndAutoFlush",
"FileEncodingName": "utf-8",
"DateFormat": "yyyyMMdd",
"CounterFormat": "000",
"MaxFileSize": 52428800,
"LogLevel": { "Default": "Trace" },
"IncludeScopes": true,
"MaxQueueSize": 0,
"Files": [
{
"Path": "File-date:yyyy-date:MM-date:dd-.log"
}
]
},
"EventLog": {
"LogLevel": {}
}
},

  1. Now since step 2 went fine, I had the same settings in place and did a release build and also did a publish and executed the executable through command prompt by using the .exe command and also with the dotnet run .dll command. In both these cases I found that the log file had only the first log statement written, but the file was of size 154 b always. I can make it work via the published executable I think I should be good. Can you please tell me what I could be missing?

System.Diagnostics.Debug.WriteLine("# of file logger providers in root scope: " + app.ApplicationServices.GetRequiredService<IEnumerable>().OfType().Count());
using (var scope = app.ApplicationServices.CreateScope())
System.Diagnostics.Debug.WriteLine("# of file logger providers in child scope: " + scope.ServiceProvider.GetRequiredService<IEnumerable>().OfType().Count());

This gave me the count as 1 always.

I will get back with rest of the results meanwhile.

@srivathsanvlb
Copy link
Author

When I used your code and executed the executable after release build

FileLoggerContext.Default.DiagnosticEvent += e =>
{
    // examine the diagnostic event here:
    // print it to the debug window, set a breakpoint and inspect internal state on break, etc.
    Debug.WriteLine(e);
};

I get the error

Writing log entry 'dbug: Microsoft.Extensions.Hosting.Internal.Host[Starting] @ 2024-09-18T13:29:05.9421409+05:30
      Hosting starting
' created at 9/18/2024 7:59:05 AM +00:00 to log file "File-<date:yyyy>-<date:MM>-<date:dd>-<counter>.log" failed. System.IO.IOException: The process cannot access the file 'c:\temp2\bbb\File-2024-09-18-000.log' because it is being used by another process.
   at Microsoft.Win32.SafeHandles.SafeFileHandle.CreateFile(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options)
   at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
   at System.IO.Strategies.OSFileStreamStrategy..ctor(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
   at System.IO.Strategies.FileStreamHelpers.ChooseStrategyCore(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, Int64 preallocationSize)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
   at Karambolo.Extensions.Logging.File.PhysicalFileAppender.CreateAppendStream(IFileInfo fileInfo)
   at Karambolo.Extensions.Logging.File.FileLoggerProcessor.LogFileInfo.Open(IFileInfo fileInfo)
   at Karambolo.Extensions.Logging.File.FileLoggerProcessor.WriteEntryAsync(LogFileInfo logFile, FileLogEntry entry, CancellationToken forcedCompleteToken)

I don't get the error when running connected to Visual Studio 2022.

@adams85
Copy link
Owner

adams85 commented Sep 19, 2024

This points in the direction of two competing file queues, caused by either DI or logger misconfiguration.

Let's check DI configuration first. Set FileAccessMode to OpenTemporarily, add the piece of diagnostic code below and run your app until you lose some log entries.

var serial = 0;
var logProcessorNumbers = new ConcurrentDictionary<object, int>();

FileLoggerContext.Default.DiagnosticEvent += e =>
{
    var logProcessorNumber = logProcessorNumbers.GetOrAdd(e.Source, _ => Interlocked.Increment(ref serial));
    Console.WriteLine($"[#{logProcessorNumber}] {e}");
};

If your DI configuration is ok, you should not see any diagnostic message that starts with [#2] or greater.

@srivathsanvlb
Copy link
Author

srivathsanvlb commented Sep 20, 2024

I ran with the below setting by publishing the app. I found that there was no loss of logs to my surprise.

"File": {
      "BasePath": "Logs",
      "FileAccessMode": "OpenTemporarily",
      "FileEncodingName": "utf-8",
      "DateFormat": "yyyyMMdd",
      "CounterFormat": "000",
      "MaxFileSize": 52428800,
      "LogLevel": { "Default": "Trace" },
      "IncludeScopes": true,
      "MaxQueueSize": 0,
      "Files": [
        {
          "Path": "File-<date:yyyy>-<date:MM>-<date:dd>-<counter>.log"
        }
      ]
    },
    "EventLog": {
      "LogLevel": {}
    }
  },

I had the below type of log two times when I ran the process for few mins. Both times the serial number was[#1]only. I couldn't find any [#2] or greater

[12:16:40,361] [#1] Writing log entry 'trce: Service[0] @ 2024-09-20T12:16:40.3555937+05:30
      Process execution started
' created at 9/20/2024 6:46:40 AM +00:00 to log file "File-<date:yyyy>-<date:MM>-<date:dd>-<counter>.log" failed. System.IO.IOException: The process cannot access the file 'c:\temp\Logs\File-2024-09-20-000.log' because it is being used by another process.
   at Microsoft.Win32.SafeHandles.SafeFileHandle.CreateFile(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options)
   at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
   at System.IO.Strategies.OSFileStreamStrategy..ctor(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
   at Karambolo.Extensions.Logging.File.PhysicalFileAppender.CreateAppendStream(IFileInfo fileInfo)
   at Karambolo.Extensions.Logging.File.FileLoggerProcessor.LogFileInfo.Open(IFileInfo fileInfo)
   at Karambolo.Extensions.Logging.File.FileLoggerProcessor.WriteEntryAsync(LogFileInfo logFile, FileLogEntry entry, CancellationToken forcedCompleteToken)

@srivathsanvlb
Copy link
Author

srivathsanvlb commented Sep 20, 2024

I ran the published app from command prompt by using the below setting

"File": {
  "BasePath": "Logs",
  "FileAccessMode": "KeepOpenAndAutoFlush",
  "FileEncodingName": "utf-8",
  "DateFormat": "yyyyMMdd",
  "CounterFormat": "000",
  "MaxFileSize": 52428800,
  "LogLevel": { "Default": "Trace" },
  "IncludeScopes": true,
  "MaxQueueSize": 0,
  "Files": [
    {
      "Path": "File-<date:yyyy>-<date:MM>-<date:dd>-<counter>.log"
    }
  ]
},

I see [#1] and [#2]. The log file has just only one log with 154b size.

If I run from Visual Studio in Release mode I see only [#1] and there are no logs lost.

Questions summary

  1. What is difference between running in Release Mode from VS and from command prompt?
  2. Why is [#2] appearing only when executed from command prompt?
  3. What would happen when the console app is converted into a Windows Service?
  4. Can I stick to the below when I convert into a Windows Service?
"File": {
      "BasePath": "Logs",
      "FileAccessMode": "OpenTemporarily",
      "FileEncodingName": "utf-8",
      "DateFormat": "yyyyMMdd",
      "CounterFormat": "000",
      "MaxFileSize": 52428800,
      "LogLevel": { "Default": "Trace" },
      "IncludeScopes": true,
      "MaxQueueSize": 0,
      "Files": [
        {
          "Path": "File-<date:yyyy>-<date:MM>-<date:dd>-<counter>.log"
        }
      ]
    },
    "EventLog": {
      "LogLevel": {}
    }
  },

Please advice

@adams85
Copy link
Owner

adams85 commented Sep 22, 2024

I see [#1] and [#2]. The log file has just only one log with 154b size.

This clearly shows that there is some problem with the DI configuration in your application. Somehow you end up with two instances of the file logger provider in your DI container while there should be only one.

I advise revising the DI setup logic in your application. Check for multiple AddFile calls first. If there aren't more of them, you probably have a more subtle issue. In that case, you will need to do some debugging to find out what causes the creation of multiple providers. You can try something like this:

Temporarily replace the AddFile call with AddFile<MyFileLoggerProvider> and add this class:

[ProviderAlias(Alias)]
public class MyFileLoggerProvider : FileLoggerProvider
{
    public MyFileLoggerProvider(FileLoggerContext context, IOptionsMonitor<FileLoggerOptions> options, string optionsName)
        : base(context, options, optionsName) {
   } // set a breakpoint here
}

Then run your application with a debugger attached and examine the callstack when the breakpoint is hit.

What is difference between running in Release Mode from VS and from command prompt?

Without having more details on your application, I can't tell. Maybe it runs in different environments (e.g. Development vs. Production) in the two case and there are differences in the configuration between those environments.

Why is [#2] appearing only when executed from command prompt?

I answered this at the beginning of my comment.

What would happen when the console app is converted into a Windows Service?

If your application is configured correctly, nothing should happen, i.e. it should work as expected. One thing to pay attention to: services may run under a restricted user account. You need to make sure that account has write permission to the folder where the logs are written.

Can I stick to the below when I convert into a Windows Service?

That logger configuration looks good. However, I'd rather go with KeepOpenAndAutoFlush unless there is a specific circumstance that suggests otherwise.

@srivathsanvlb
Copy link
Author

srivathsanvlb commented Sep 23, 2024

"File": {
  "BasePath": "Logs",
  "FileAccessMode": "KeepOpenAndAutoFlush",
  "FileEncodingName": "utf-8",
  "DateFormat": "yyyyMMdd",
  "CounterFormat": "000",
  "MaxFileSize": 52428800,
  "LogLevel": { "Default": "Trace" },
  "IncludeScopes": true,
  "MaxQueueSize": 0,
  "Files": [
    {
      "Path": "File-<date:yyyy>-<date:MM>-<date:dd>-<counter>.log"
    }
  ]
}

I used the above setting in published apps in VMs. It seems to work fine. So closing this issue. I will reopen if required.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants