-
Notifications
You must be signed in to change notification settings - Fork 22
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
Q: Can't understand LogLevel settings. #11
Comments
I must have forgot to delete the log at one point. |
Hi! First of all, thanks for the kind words. :) I think your understanding of log level settings are fundamentally correct. There's one important thing to keep in mind. Log level switches defined at log file level (
This is a limitation of the Microsoft.Extensions.Logging framework I cannot do anything about as it's out of my control. However, in your case this cannot cause any problems at all (theoretically). That is, your configuration should work. I put together a simplified imitation of your environment based on your description but I failed to reproduce the issue. It just works as expected. Please take a look at my attempt and try to figure out if there's some relevant differences between my simulated and your real environment which I don't see. |
Hi! I will take a look, I promise! Thank you! Just letting you know I saw this. I will edit this post before monday (25. May)! Sorry for the delay! So, I've tested it more and I've noticed something strange. This is probably not the main issue, but this might be the one that confused me most initially. If I edit the log settings during runtime, the framework will reload it. ( At this point I just wanted to see "something happening". I do know that
So it seems they get stuck somewhere? :/ "Log level switches defined at log file level (MinLevel option) can only make the log level switches defined at higher levels (global level or log provider level) stricter." Now I thought "File": {
"BasePath": "logs",
"FileAccessMode": "KeepOpenAndAutoFlush",
"MaxFileSize": 10485760,
"CounterFormat": "000",
"IncludeScopes": true,
"MaxQueueSize": 10000,
"Files": [
{
"Path": "integra-persistence-<counter>.log",
"MinLevel": {
"Default": "None",
"NHibernate": "Information",
"NHibernate.Type": "Information",
"NHibernate.Cfg.XmlHbmBinding": "Warning",
"NHibernate.Cfg.XmlHbmBinding.Binder": "Information",
"Itg.Persistence": "Trace"
}
},
{
"Path": "integra-<counter>.log",
"MinLevel": {
"Default": "Debug",
"Microsoft": "Warning",
"Microsoft.AspNetCore.Authentication": "Debug",
"Microsoft.AspNetCore.Authorization": "Debug",
"Microsoft.AspNetCore.Server": "Debug",
"NHibernate": "None",
"Itg.Persistence": "None",
"Itg.Mailing": "Information"
}
}
]
} Nothing's changed.
I also took a look at your repro, but I'm using something a bit more complicated. protected override async Task ExecuteAsync(CancellationToken ct)
{
this._logger.LogInformation("Queued Hosted Service is starting.");
// ^ this is logged properly in the integra-<counter> file from the category "Itg.Services.Tasks" ^
await this.BackgroundProceessing(ct);
}
private async Task BackgroundProceessing(CancellationToken ct)
{
while (!ct.IsCancellationRequested)
{
var workOrder = await this._taskQueue.DequeueAsync(ct);
using var scope = this._services.CreateScope();
var workerType = workOrder
.GetType()
.GetInterfaces()
.First(t => t.IsConstructedGenericType && t.GetGenericTypeDefinition() == typeof(IBackgroundWorkOrder<,>))
.GetGenericArguments()
.Last();
// Getting a specific worker based on the generic type defined for the received Order.
var worker = scope.ServiceProvider
.GetRequiredService(workerType);
var task = (Task) workerType
.GetMethod("DoWork")
.Invoke(worker, new object[] { workOrder, ct });
await task;
}
} The lifetime of the related services: ...
services.AddScoped<IKeyValueStore<ArticleCollection>, FileKeyValueStore<ArticleCollection>>();
services.AddSingleton<IBackgroundTaskQueue, BackgroundTaskQueue>();
services.AddHostedService<QueuedHostedService>();
// Task implementations
services.AddScoped<CreateCollectionBackgroundWork.Worker>();
...
public static class CreateCollectionBackgroundWork
{
public class Order : IBackgroundWorkOrder<Order, Worker>
{ ... /* contains parameters for it's worker*/ ... }
public class Worker : IBackgroundWorker<Order, Worker>
{
public Worker(
ILoggerFactory loggerFactory,
ShopArticleService articleService,
/* ^ logging works inside this; into integra-<counter> ^ */
IKeyValueStore<ArticleCollection> collectionStore
/* ^ the logger in this (FileKeyValueStore) is the one not logging to the file, but does to console, and logs also appear when the config file is reloaded ^ */)
{
this._logger = loggerFactory.CreateLogger(nameof(CreateCollectionBackgroundWork));
// ^ this is actually still logging to integra-<counter> file ^
}
}
} The logger in // Maybe generic TModel messing with the category?
private readonly ILogger<FileKeyValueStore<TModel>> _logger;
public FileKeyValueStore(
...
ILogger<FileKeyValueStore<TModel>> logger)
{
this._logger = logger;
} My ConfigureLogging call in .ConfigureLogging((context, logging) =>
{
logging.AddConfiguration(context.Configuration.GetSection("Logging"));
logging.ClearProviders();
logging.AddConsole();
#if DEBUG
logging.AddDebug();
#endif
logging.AddFile(o => o.RootPath = context.HostingEnvironment.ContentRootPath);
}) Thank you very much in advance! I do realize this is a lot, and at the same time too little. Also, please remember, I'm not using current versions of anything (well except for C# 8)! Might seem odd, but I would first like to identify this problem, or at least pinpoint it before upgrading anything... |
I think the key momentum here is the blockage of the Itg.Services.* messages. However, I cannot see yet how they can get stuck for minutes. I suspect though it has something to do with the relatively high logging traffic of NHibernate. Could you do a test where you fire a single(!) request and check the logs after some minutes if the Itg.Services.* entries are still missing? I'd just like to make sure that we're dealing with just one or two issues here (that is, whether there's also something regarding configuration reloading or not). If the test failed (no Itg.Services.* entries after say 5 minutes), then please try the following:
This will take some time of yours, but I'm afraid we cannot do anything else. We have to narrow down the possible causes of your issue to be able to track it down. |
I updated my repro app according to the new details you supplied. It feeds 10k log entries into the logger and does some occasional logging in the background. All entries land in the log as expected and I experienced no blocking. ( |
Hi, and thank you again! Interesting 1.: The non-persistence file seems to always work correctly, though I did not edit it's settings. I am of course doing the same (single!) request in every case, with same parameters, so logs should be - and are - the same, and I've also been doing the waiting thing. 🤔 I wait on average 10~15 minutes for the logs, they just never come. A bit of a confusion-correction: Right now, the correct behaviour is happening, which is that NHibernate lines go into the Persistence file, and Note: Here are the cases you requested:
This feels so weird. Why the I'm going to wait for some kind of a response, and am going to update to |
It's my bad. Using v3.0 you have to specify a negative number (like -1) to get unbounded queues (or just remove that setting altogether). v3.1 changed this: 0 is also treated as unbounded.
I think we're getting somewhere. I don't see yet how your code could interfere with the log writer but it seems this is the case. Is there any chance that your app opens the log files being written? BTW, please upgrade to 3.1.1, repeat the tests and let's see if the issue persists. In the meantime, I'll also do a few tests by adding some file access simulation to the repro app. |
Just a thought flashed through my mind. Do you run some anti-virus software? If so, do a test with the AV software disabled. There's not much chance that it can cause interference but let's eliminate that for sure. |
Hi! But actually, I've had a multiple build update through an in-place reinstall since opening the issue, and it still did not change! Also - while all this is still happening by chance which is crazy - at first I didn't have any antivirus! I had Windows Defender, and it just went dead and unnoticed. I couldn't start it because of some Windows Update corruption mess... That's why I then reinstalled Windows, and I'm now proudly using Malwarebytes. So, I've actually tried this with almost all possibilities in terms of an antivirus and OS version! 😂😂 If you're thinking what if all this madness played a part... My OS drive is not my work drive (which I have this project on). Nothing really happed on the work drive...
That's not good... 😢 |
Upgraded to
This is my whole About 2kb of binary serialized data into store file per request. Now deleting the store file and doing it again. |
Sorry for the delay, I've just found time for continuing the investigation. I created a much more sophisticated repro app. I used the code snippets you provided and did my best to fill in the gaps and reconstruct your context as close as possible. This was the good news. The bad news is that I still cannot reproduce the problem... It works as expected. So please examine my new attempt and try to identify the differences between that and your real-life app. After starting the repro app, you can simulate a request by visiting http://localhost:5000/Test. Please debug through the application and check for relevant differences. The entry point is Let's see if this brings us a result. |
Hi! I'm so sorry for the delay on my part as well. So I've been trying to reproduce the issue in the repro app you created. I've gone ahead and made it closer and closer to my actual flow and implementation, but I've kind of given up. The only thing I did not modify yet is the setup in the Program class. Mine is a lot different because I'm not using the default builder. (Host.CreateDefaultBuilder) I'm doing it manually. Will check this out, but I think I've found a lot better lead just now. I've removed the filelogger NuGet package reference, went ahead and added the source project as dependency! Currently I'm debugging through filelogger, and I've already identified the symptom. The log file is successfully identified and everything actually goes smooth through If I just let the debug through and perform another request, I can actually see that all the previous entries are still in the Queue. Then I saw that every exception is swallowed in
I've put up a static InstancesCount field which I'm incrementing in the constructor, and decrementing at the end of At this point I don't really have a clue how that could happen. Logging is registered as Singleton for a good reason. Do you think the following line in my using var scope = this._services.CreateScope(); Seems pretty strange... Docs say;
Do you have an idea about where I could go deeper into this? I'm a complete newbie to debugging IO and Threading to be honest. Also, pretty please... Could we have some kind of an indication about the exceptions? 😢😢😢😢 Again, I deeply appreciate your time and effort in this adventure! |
After failing to reproduce the issue, this would have been my last resort as well. I'm glad that you've already done that. 👍
This explains why Now the question is how on earth you end up with two
I'm aware of this issue but I haven't figured out yet how to solve it. The crux of it is that we want to do logging in a logger component. Calls to |
Hi! I'm not using multiple DI containers. At the same time, I have a breakpoint in the constructor of The first one is created by the (I put the instance index as a field onto them...) Update: I made the DI crash when requesting another Once I removed the faulty injection (and took out NHibernate logging with it...) No other instances are created. Will update again, once I resolved this whole situation, but that'll have to come on another day again. At the time I made the conscious decision to stick with the old one, as I went through the source of the new methods and thought I could just pretty much copy / paste most of what they do. At least they seemed easy enough... but hey, seems like there's some hardcore internal reflection or something which won't allow this. |
I don't think this is a good idea, at least, it's nonstandard. The framework allows injecting these services in
I suspect that during your customized host setup an intermediate DI container is built somewhere. When you inject I recommend dropping the custom solution and migrating to the ASP.NET Core 3-style (generic host) setup. AFAIK, logging should be configured through public static void Main(string[] args)
{
var host = CreateHostBuilder(args).Build();
ConfigureLoggerFactory(host.Services.GetRequiredService<ILoggerFactory>());
host.Run();
}
private static void ConfigureLoggerFactory(ILoggerFactory loggerFactory)
{
loggerFactory.AddProvider(...);
} |
Hi!
This is just a question, or maybe an enhancement for the docs if it's not just me.
First of all, thank you for this library! Good job! I've been using it for about 6 months, had no problem!
Context:
Library Version: 3.0.0 (I'll probably update soon...)
Target framework: .NET Core 3.0 (Upgrade coming as well...)
It's a complex ASP.NET Core project, with background tasks etc.
So the one thing I've been messing around is setting up my logs to be "just perfect".
I have some Global LogLevel settings:
Then I have a Console provider which is most probably irrelevant.
And lastly I have my File provider settings:
The thing I can't seem to understand is the following:
I'd like my app-persistence-<counter>.log to contain only
NHibernate
andItg.Persistence
categories, the other one mostly everything else.On my initial run I had
"Default": "None"
on my persistence file, which I thought must be right, because I didn't want anything else to land in there, only the ones I specified (and more specific ones!).Now based on these, after reading through Microsoft's logging tutorial, and this repo's readme, the category
"Itg.Persistence.Secondary"
should have been written to the persistence file, but it did not! (it's "under""Itg.Persistence"
which I set to"Trace"
)The logging worked, as I could find my entries on the console, but nowhere else.
To be exact, this is the line I was looking for:
crit: Itg.Persistence.Secondary.FileKeyValueStore[LoadFailed]
And to be more exact, this line is logged by a queued background task!
Now I set
"Default": "Trace"
on my persistence file, and here I thought, now everything should show up. Not just the ones I specified. To my surprise the one I was looking for DID show up ("Itg.Persistence.Secondary"
) BUT not at all everything... This is the only new category in my persistence log. Which is just about the effect I wanted, but I can't imagine these settings are any good...Could you help me out please? What am I missing? I'm so confused... :(
The text was updated successfully, but these errors were encountered: