Loosing logs in rabbitmq

Hi, (its a little bit complicated, please read carefully :innocent: ).

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;
             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.

  1. 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)

  2. 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

That’s highly unlikely, only StackOverflowException can’t be caught, if you had an AccessViolationException that should be reported in the Windows Event Viewer.

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.

Thank you.
I will prepare a repo.

Is PushProperty thread-aware?
I mean, maybe the entire thing is static and I’m running over it without knowing?

What do you mean by Thread aware? It just delegates to the underlying logging provider. What logging provider are you using?

im using serilog (btw its a docker deployment).

Serilog requires Serilog.Enrichers.Thread package where it delegates it to:

this is how I initialize it (Enrich.FromLogContext):

            var log = new LoggerConfiguration().Enrich.FromLogContext()
                    sinkOptions: config
            LogManager.LogFactory = new SerilogFactory(log);

That’s the important part to be able to make use of this feature in Serilog.

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?

Actually no. I am going to try that.

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.

Ok. problem solved.

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.

Thanks for the help.

1 Like