Hi, (its a little bit complicated, please read carefully ).
I have a lot of operations running in the rabbit queue.
For safety reasons, I have wrapped all of the executions with my own function in order to try/catch and write to the log.
var service = container.Resolve<Service>();
mqServer.RegisterHandler<ServiceModel>(x =>service.Execute(b => service.RunService(x),x));
Service is inheriting from my BaseQueueService to get access to the Execute method.
So Execute a method that wraps everything and invoke.
This is the Execute:
public object Execute<T>(Action<object> method, IMessage<T> p) where T : BaseApiQueueModel
{
var service = this.GetType().Name;
var body = p.GetBody();
using (Log.PushProperty("Service", service))
using (Log.PushProperty("Target", body.RequestDetails.LogId))
using (Log.PushProperty("Env", body.RequestDetails.Environment))
{
var requestDetails = body.RequestDetails;
body.RequestDetails = null;
Log.InfoFormat("Executing with data {@data}", body);
body.RequestDetails = requestDetails;
try
{
method(p); /// invoking RunService
}
catch (Exception e)
{
Log.ErrorFormat("Running Queue failed with error: {@e}", e);
return null;
}
Log.Info("Done executing the message successfully");
return null;
}
}
The problems.
I have reason to believe that not all the exceptions are caught in the try/catch block. I see tasks that are not executed without anything on the log. in general I think that this Execute method is loosing some logs. since all the queue is a synced operation, the catch block must catch everything. (I also made sure that the service itsself not hiding/catching exceptions)
some time PushProperty is working and sometimes it is not. is this a good practice to push a property this way? can it be get lost this way?
Please note that this is not something that happens every time. it one out of 20-50 queue runs
Thanks
The PushProperty APIs were community contributed where they essentially delegate to the underlying logging provider, currently only Serilog, NLog & Log4Net logging providers is supported.
In order to investigate any issues I’d need a stand-alone repro, it’s ok if it requires multiple runs to reproduce, but it needs to be reproducible.
this is how I initialize it (Enrich.FromLogContext):
var log = new LoggerConfiguration().Enrich.FromLogContext()
.WriteTo.GoogleCloudLogging(
sinkOptions: config
).Destructure.JsonNetTypes()
.CreateLogger();
LogManager.LogFactory = new SerilogFactory(log);
If the issue is missing logs I’m assuming it’s related to how it syncs logs to GoogleCloudLogging if that’s the service you’re using. Have you tried logging to a local file to check if the issue is limited to your GoogleCloudLogging syncing?
Hi,
Another question, what might be the reason for seeing NullDebugLogger inside the Execute function I posted above?
When I stop with the debugger, I see that Log is NullDebugLogger.
The initialization of the logger is within the same assembly.
Again, this is happening inside rabbit message execution…
(the source code is in the original post).
Note, that inside the Action - method(p); I see the correct serilog logger.
Even when I try to get the logger inside the Execute method I see NullDebugLogger:
The NullLogFactory and its NullDebugLogger should only be used if the LogManager.LogFactory hasn’t been initialized. Make sure it’s initialized once on Startup, not at runtime.
The log was initialized in the startup after the queue decleration, so in case of restart while tasks was pending inside the queue, there was a race between the log initilization and queue execution.
I just put the log at the begining of the startup.
).