Move to Microsoft.Extensions.Logging

[jkulubya]

Hi,
We'd like to 1. pipe the QF logs through our existing log pipeline based on MS.Extensions.Logging, and 2. eventually add more context to the structured logs that will come out of QF when using MS Logging. It doesn't seem like these two issues (#205, #679) were resolved so here's a PR to get that moving along.

There's a new dependency on Microsoft.extensions.logging.abstractions, and all the logging is happening via an ILogger. When messages are logged, they're logged with the message type in the scope (where possible), to allow heartbeats and such to be filtered out downstream.

Instead of passing in an ILogFactory, end-users should now pass an ILoggerFactory. Exisiting ILogFactory's and ILog's should work, via an adapter, but all that has been marked obsolete with a note telling the user to migrate to MS Logging.

There are a few questions to resolve, like what levels things should be logged at, what event IDs should be used for logs, what category names should be used.

[VAllens]

While I personally would love to do this,
it would be too destructive and invasive and cause QuickFIX/n to create external dependencies.

I prefer to use an extension library implementation,
e.g. QuickFIXn.Extensions.Logging.

[jkulubya]

If taking on an external dependency is a hard no, then that leaves two options, keep the current logging as-is, or implement an extension package QF.extensions.logging as you suggest.

The downside with making a "QF.Extensions.Logging" package that eventually hooks into ms.extensions is that it would require improving the current QF logging abstraction to produce all the data that a user of ms.extensions.logging might require, at which point you're rewriting ms.extensions.logging, without getting 100% there in terms of performance and ergonomics.

The problem with maintaining the status quo is that users are asking for better logging, and the current system isn't meeting their needs.

I'm partial to just going with ms.extensions.logging, and the .net world has coalesced around it, so I'd be comfortable with that choice. But even an extension package would be an improvement over what we have now.

[VAllens]

If taking on an external dependency is a hard no, then that leaves two options, keep the current logging as-is, or implement an extension package QF.extensions.logging as you suggest.

The downside with making a "QF.Extensions.Logging" package that eventually hooks into ms.extensions is that it would require improving the current QF logging abstraction to produce all the data that a user of ms.extensions.logging might require, at which point you're rewriting ms.extensions.logging, without getting 100% there in terms of performance and ergonomics.

The problem with maintaining the status quo is that users are asking for better logging, and the current system isn't meeting their needs.

I'm partial to just going with ms.extensions.logging, and the .net world has coalesced around it, so I'd be comfortable with that choice. But even an extension package would be an improvement over what we have now.

Yes, either way, it's better than the status quo.

[gbirchmeier]

I'm starting to digest this PR this week. I have to admit that I am not familiar with Microsoft.Extensions.Logging. (Can I call it MEL going forward?) My work with .NET is very FIX-centric, so somehow I'm able to stay oblivious to certain aspects of the greater .NET ecosystem. I need to download this branch and it and see how it works.

My first impulse is "aaughhh! So much change!" Which is of course not a legitimate criticism, and also betrays my ignorance of what this extension can offer.

Let me start with one dumb question, however: Why not just write an QF ILog implementation that defers all its functionality to MEL?

[jkulubya]

I'm starting to digest this PR this week. I have to admit that I am not familiar with Microsoft.Extensions.Logging. (Can I call it MEL going forward?) My work with .NET is very FIX-centric, so somehow I'm able to stay oblivious to certain aspects of the greater .NET ecosystem. I need to download this branch and it and see how it works.

My first impulse is "aaughhh! So much change!" Which is of course not a legitimate criticism, and also betrays my ignorance of what this extension can offer.

I'll try my best to help. The happy path of MEL is that library authors, write logs using an ILogger from MEL. The concrete implementation of ILogger will be provided by the library consumer/application developer. The benefit of this is that on the consumer side, there are purpose-built logging libraries the plug straight into MEL to do all you'd ever want to do with logs, like log to a Db, log to a file, log to a rolling file etc. The thinking is a quickfix developer wants to spend their time building quickfix, not become an expert in logging.

Let me start with one dumb question, however: Why not just write an QF ILog implementation that defers all its functionality to MEL?

A QF ILog that writes into MEL is easy. In fact, in this PR, there's an adapter to pipe logs from existing ILog and ILogFactory into MEL so as not to break folks. But that's just piping plain text logs, while MEL can do so much more (e.g. structured logging/scopes/high performance logging). A QF ILog that can do the extras that MEL can do is a bit more work (I'm not an expert so i can't say exactly how much) and ends up looking a whole lot like MEL.

[jkulubya]

https://learn.microsoft.com/en-us/dotnet/core/extensions/logging-library-authors

[Rob-Hague]

I am in favour of this change. I skimmed it and left some comments inline

[Rob-Hague]

breaking change?

[jkulubya]

Wasn't supposed to be - it's been reverted. What do you think of what it is now together with #909?

[jkulubya]

Please verify that the levels at which stuff is logged makes sense. I went with Information for the inbound/outbound messages, and error/debug/trace for the rest

[Rob-Hague]

I am seeing quite a lot of test failures locally which I don't seem to get on master, e.g.:

    C:\src\quickfixn\QuickFIXn\ThreadedSocketAcceptor.cs(79): error TESTERROR:
      Fix50sp2Test("SessionReset.def") (54ms): Error Message: OneTimeSetUp: QuickFix.ConfigError : Configuration failed:
       The process cannot access the file 'C:\src\quickfixn\AcceptanceTest\bin\Debug\net8.0\log\FIXT.1.1-ISLD-TW.message
      s.current.log' because it is being used by another process.
        ----> System.IO.IOException : The process cannot access the file 'C:\src\quickfixn\AcceptanceTest\bin\Debug\net8
      .0\log\FIXT.1.1-ISLD-TW.messages.current.log' because it is being used by another process.
      Stack Trace:
         at QuickFix.ThreadedSocketAcceptor..ctor(IApplication application, IMessageStoreFactory storeFactory, SessionSe
      ttings settings, ILoggerFactory loggerFactory, IMessageFactory messageFactory) in C:\src\quickfixn\QuickFIXn\Threa
      dedSocketAcceptor.cs:line 79
         at AcceptanceTest.TestBase.Setup() in C:\src\quickfixn\AcceptanceTest\TestBase.cs:line 38
         at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructo
      r)
         at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
      --IOException
         at Microsoft.Win32.SafeHandles.SafeFileHandle.CreateFile(String fullPath, FileMode mode, FileAccess access, Fil
      eShare 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 sha
      re, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
         at System.IO.Strategies.FileStreamHelpers.ChooseStrategyCore(String path, FileMode mode, FileAccess access, Fil
      eShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
         at System.IO.StreamWriter.ValidateArgsAndOpenPath(String path, Boolean append, Encoding encoding, Int32 bufferS
      ize)
         at System.IO.StreamWriter..ctor(String path, Boolean append)
         at QuickFix.Logger.FileLog..ctor(String fileLogPath, SessionID sessionId) in C:\src\quickfixn\QuickFIXn\Logger\
      FileLog.cs:line 42
         at QuickFix.Logger.FileLoggerProvider.CreateLogger(String categoryName) in C:\src\quickfixn\QuickFIXn\Logger\Fi
      leLoggerProvider.cs:line 30
         at Microsoft.Extensions.Logging.LoggerInformation..ctor(ILoggerProvider provider, String category)
         at Microsoft.Extensions.Logging.LoggerFactory.CreateLoggers(String categoryName)
         at Microsoft.Extensions.Logging.LoggerFactory.CreateLogger(String categoryName)
         at QuickFix.Session..ctor(Boolean isInitiator, IApplication app, IMessageStoreFactory storeFactory, SessionID s
      essId, DataDictionaryProvider dataDictProvider, SessionSchedule sessionSchedule, Int32 heartBtInt, ILoggerFactory
      loggerFactory, IMessageFactory msgFactory, String senderDefaultApplVerId) in C:\src\quickfixn\QuickFIXn\Session.cs
      :line 247
         at QuickFix.SessionFactory.Create(SessionID sessionId, SettingsDictionary settings) in C:\src\quickfixn\QuickFI
      Xn\SessionFactory.cs:line 103
         at QuickFix.ThreadedSocketAcceptor.CreateSession(SessionID sessionId, SettingsDictionary dict) in C:\src\quickf
      ixn\QuickFIXn\ThreadedSocketAcceptor.cs:line 151
         at QuickFix.ThreadedSocketAcceptor..ctor(IApplication application, IMessageStoreFactory storeFactory, SessionSe
      ttings settings, ILoggerFactory loggerFactory, IMessageFactory messageFactory) in C:\src\quickfixn\QuickFIXn\Threa
      dedSocketAcceptor.cs:line 74

[jkulubya]

I can't reproduce this using dotnet test on a fresh clone. Are you running the tests in VS/Rider?

[gbirchmeier]

@jkulubya Are you running on windows? This looks like an error that would not occur on Linux/Mac, but would occur on Windows. (I ran into this myself with some recent PRs)