microsoft
Rework the logging infrastructure.
How the logging works now:
Kiota's logging is based on C#'s logging support which uses factories to create loggers with specific categories. The categories are meant to provide a way to add log filters to the infrastructure. Kiota implements a manual FileLogLoggerProvider which creates FileLogLogger instances on demand. The FileLogLogger instances have a file they use to write the logs and close the file on cleanup. The challenge is that you can't have multiple FileLogLoggers writing to the same file since each instance locks the file on creation and the next instance can't access it. If we have shared file access, there's the risk of synchronizing accesses to the file. Right now, Kiota works because it only uses 1 logger that's created on startup for all logging.
Why I want to change it
Logging is a QoL improvement for language writers and potentially users of Kiota. When implementing a language, implementers might want to log messages to the log file at different stages of generation. Using Console.WriteLine would work but is undesirable since the logged messages can't be disabled or easily written to files and other sinks. It will also help us in troubleshooting since users of kiota can provide logs of their runs that might help find bugs faster.
As part of #4208, I would like to provide the logging infrastructure to the language writer classes when needed and allow users to configure logging filters based on components. This isn't a trivial change unless we rework the FileLogLoggerProviders.
How I want it to behave
The components that need to log should accept a constructor parameter of type ILogger<T> and use that to perform logging throughout the kiota code base. A decision to be made is whether this constructor parameter is optional or required. Whenever a component logs a message, that message should go into the centralized file logger. The expected output is that messages are printed in the order they were submitted.
How I would implement it
The 1st thing I would do is move the file management code into the FileLogLoggerProvider. This would fix the issue with logger instances failing to access the log file. It would also simplify the FileLogLogger type and make it cheap to create.
I would then introduce a concurrent message queue to the FileLogLoggerProvider type. The FileLogLogger would send any log messages to the provider for processing.
These messages in the queue would be removed from the queue in batches and written to the disk once a specific quota is reached.
When disposing the FileLogLoggerProvider, any messages in the queue would be written to the disk one final time.
Open areas
Error handling (What happens in the case of an IO error? e.g. If the disk is full when there are still messages in the queue) Backpressure control (does a thread block or are messages discarded when the queue is full?)
Thanks for starting the discussion on this. I'm still unclear on WHY we'd need to do this work at this point? Do you expect people to log to multiple different files? why? how would they configure that aspect? Do you expect people to be able to configure log levels per "major component" (builder, refiner, writers,...)? what would the experience look like? Why do you think this is needed?
This will be a QoL improvement for the CLI. When implementing the language, I can't log anything unless I use Console.WriteLine which I don't think is ideal. There are a lot of times when I've needed to do it during development but had to instead either use a debugger or add a Console.WriteLine then remove it before pushing the code. In all these cases, the experience was sub-optimal. I think since we've gone through the trouble of adding a logging library, we should let language writers use it easily.
To address your questions:
-
Do you expect people to log to multiple different files No. The request is to use 1 file, but allow users to create multiple loggers with their own categories. That way, I can turn off Kiota Builder logs and enable logs for only my component. The logging library we're using already supports this feature.
-
Do you expect people to be able to configure log levels per "major component" Yes. This is how the logging library was designed to be used. If we use a configuration provider, we get the ability to configure log levels for free, otherwise we'd have to read logging configuration provided by the user e.g. from a command option
- Why do you think this is needed? I think filtering log output is an important part of troubleshooting a product. It will also allow us to ask for log output from users of kiota to help with logging. This makes it faster to track down problems in some situations.
Thanks for the additional information here. How do you expect people to configure logging per component? (besides maybe with app settings)
So, what I would do is use the application host & configuration providers already provided by the .NET team with our defaults configured in code. This allows us to support file configuration(json, xml, ini), command args and environment variables without writing much code for it.
Thanks for the additional context. And so you're not expecting any changes to the CLI interface? (or the vscode configuration) Overall I think it'd be beneficial to increase observability, especially since we're thinking about telemetry and other aspects (see #3264 ), I'd like @sebastienlevert to weigh in on the priority here before we start working on this.
I don't expect any changes to the CLI. Most of the changes will be internal to kiota. Also, I think most libraries needed for this are already in use in kiota at the moment. We just need to properly configure them. One thing that may change is the logging categories.
In relation to open telemetry, the .NET docs say that you can plug in an OpenTelemetry exporter for free. I've never tried it though.
yes, that (and the prior version with Application Insights) works out of the box. I've explored that when implementing observability for kiota generated clients. In dotnet the two steps that are required are:
- start listening to the categories (specific to dotnet, other languages are turned on by default)
- add an exporter for OT tracing.
The main gist I get from this is the concerns around the FileLogLoggerProvider and FileLogLogger implementations with regards to extensibility/performance.
Assuming we cleanup the logging to pass around ILogger<T> to constructors and follow best practices, and given that dotnet does not provide a LoggerProvider for file logging in the framework, would it make sense to take advantage of 3rd party logging sinks like serilog and async rather than have the functionality like message queueing built-in by ourselves?
Serilog can bring on a lot of dependencies and infrastructure the last time I checked. I'm ok with using the file sink as long as we only use serilog APIs to register/manage the file sink. I don't want other parts of kiota taking dependencies on their APIs in case we'd need to switch it in the future.
+1 for enabling to specify log level per category for the different classes to be able to focus only on a small portion of the process in the log file which is not supported today.
For this, we shall be able to leverage the standard .NET infrastructure. Which, just by looking on our code in BaseKiotaCommandHandler, FileLogLogger and FileLogLoggerProvider etc. will require some significant code changes.
Looks like a good candidate for a decision record (ADR) to consider multiple options. Creating a custom queue and persistence shall not be the only option to look at.
Few options we may want to consider:
- Using Dependency Injection to set a logger to be used in all core classes by using host with .NET configuration support (as Caleb suggested above), https://learn.microsoft.com/en-us/dotnet/core/extensions/logging?tabs=command-line#integration-with-hosts-and-dependency-injection
- Or pass ILoggerFactory down instead of ILogger, so that each class can create a logger with a specified category.
- Refactor BaseKiotaCommandHandler,GetLoggerAndFactory() to set a level to one or multiple (few) classes from appsettings.json - simple implementation without many code changes which still might meet the key requirement without exposing the full flexibility of .NET logging configuration to the user though.
Also, we can consider
- Using compile-time logging source generation, https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator
- Not adding a dependency on 3rd party framework unless necessary as it might not be the choice of our users.
Just to keep things simple, why not have an in-memory logger that flushes to a file every 30 seconds or when disposed?
connecting that to the ILogger infrastructure with all its goodies (filtering per category eg.) should not be a problem.
