4

I have an odd issue with my implementation of Rebus which has been working for the past couple of years without any issue, and I am trying to figure out the scope of the problem and where to focus my troubleshooting effort. A little context:

  • We have been running version 0.99.66
  • Moved to version 3.1.5 last week, then saw the issues appear
  • Rolled back to 0.99.66, issues continue
  • Using MSMQ for the transport
  • Running Windows Server 2016
  • Identical code running on other server instances without issue

So, we are experiencing seemingly random instances where messages are failing, ending up in the error queue with a Rebus error saying that the message could not be dispatched to any handlers. This could happen once, but then when an identical message type comes through the next time, it gets handled correctly.

Here is a snippet of the code in question:

public class ProcessManagerService
{
    public ProcessManagerService()
    {
        ...

        BusAdapter = new BuiltinHandlerActivator();
        BusAdapter.Handle<FileEventMessage>(async msg => await StartProcess(msg));
        BusAdapter.Handle<ProcessRequest>(async msg => await StartProcess(msg));

        Bus = Configure.With(BusAdapter)
                .Logging(l => l.ColoredConsole(LogLevel.Error))
                .Transport(t => t.UseMsmq(ConfigurationManager.AppSettings["Queue"]))                   
                .Start();            
    }

    ...

    public async Task StartProcess(FileEventMessage msg)
    {
        var svc = new StepManager() { FileEvent = msg.FileEvent };
        await svc.Run();
    }

    public async Task StartProcess(ProcessRequest msg)
    {
        var svc = new StepManager();
        await svc.Run(msg);
    }
}

And here is an example of the exception that is thrown:

5 unhandled exceptions: 12/18/2018 7:53:00 AM -06:00: Rebus.Exceptions.RebusApplicationException: Message with ID c72a8b6d-e31c-4a88-937e-612bf1db8b11 and type ClearStone.Messages.Monitoring.File.FileEventMessage, ClearStone.Messages could not be dispatched to any handlers at Rebus.Pipeline.Receive.DispatchIncomingMessageStep.d__1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Rebus.Sagas.LoadSagaDataStep.d__7.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Rebus.Pipeline.Receive.ActivateHandlersStep.d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Rebus.Pipeline.Receive.DeserializeIncomingMessageStep.d__2.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Rebus.Pipeline.Receive.HandleDeferredMessagesStep.d__12.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Rebus.Retry.Simple.SimpleRetryStrategyStep.d__8.MoveNext()

UPDATE: Here is a more detailed stack trace after wiring in Rebus source:

5 unhandled exceptions: 12/20/2018 9:39:05 AM -06:00: Rebus.Exceptions.RebusApplicationException: Message with ID 84c3605a-41de-4300-9596-97e7288d2bcb and type ClearStone.Messages.Monitoring.File.FileEventMessage, ClearStone.Messages could not be dispatched to any handlers at Rebus.Pipeline.Receive.DispatchIncomingMessageStep.d__1.MoveNext() in C:\Temp\rebus_0_99_66_archive\Rebus\Pipeline\Receive\DispatchIncomingMessageStep.cs:line 61 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.GetResult() at Rebus.Sagas.LoadSagaDataStep.d__7.MoveNext() in C:\Temp\rebus_0_99_66_archive\Rebus\Sagas\LoadSagaDataStep.cs:line 77 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.GetResult() at Rebus.Pipeline.Receive.ActivateHandlersStep.d__3.MoveNext() in C:\Temp\rebus_0_99_66_archive\Rebus\Pipeline\Receive\ActivateHandlersStep.cs:line 48 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.GetResult() at Rebus.Pipeline.Receive.DeserializeIncomingMessageStep.d__2.MoveNext() in C:\Temp\rebus_0_99_66_archive\Rebus\Pipeline\Receive\DeserializeIncomingMessageStep.cs:line 36 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.GetResult() at Rebus.Pipeline.Receive.HandleDeferredMessagesStep.d__12.MoveNext() in C:\Temp\rebus_0_99_66_archive\Rebus\Pipeline\Receive\HandleDeferredMessagesStep.cs:line 114 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.GetResult() at Rebus.Retry.Simple.SimpleRetryStrategyStep.d__8.MoveNext() in C:\Temp\rebus_0_99_66_archive\Rebus\Retry\Simple\SimpleRetryStrategyStep.cs:line 105

Assuming the obvious and that it is something in this particular server instance/enviornment, I am trying to figure out why Rebus is behaving this way, and what in my environment may be causing this. Any direction as to where to start looking would be greatly appreciated!

Tom Miller
  • 536
  • 1
  • 4
  • 14

1 Answers1

3

Sounds pretty weird :) when people have this problem, it's almost always because they have somehow set up multiple Rebus instances to consume messages off of the same queue.

In some rare cases, it's because .Start() is called on the bus before handlers are added to the container/built-in handler activator, but that doesn't seem to be the problem in your case.

Can you tell me more about your setup? If it's about as simple as what you're showing above, maybe you can reproduce it in a separate application?

mookid8000
  • 18,258
  • 2
  • 39
  • 63
  • Thanks for getting back to me! So, it is really is that simple. What makes this particularly difficult is that the same code is running in 2 other instances with no issues. At this point I am trying to rule out what I can--is there anything you can think of that MSMQ could be causing? I need to rule out environmental factors before chasing code. The snippet above is literally the extent of the Rebus implementation. It sure feels environmental, with MSMQ being the one external dependency. Our plan has been to move to the SQL provider, which might be our next step to look at in this case. – Tom Miller Dec 19 '18 at 15:20
  • As for multiple instances, this is the only instance consuming these messages/pointing to this queue. Start() is being called last ;-) -- I ran into that scenario several years ago when starting to work with Rebus. – Tom Miller Dec 19 '18 at 15:21
  • It would be pretty cool if you could take the code that sometimes gives you that error, and then remove all irrelevant bits one by one. When you've distilled out the code that causes the problem, then you can send it to me – I'll be happy to debug it :) – mookid8000 Dec 19 '18 at 19:06
  • I just updated the original post with more detailed stack trace after referencing Rebus source vs nuget pkg. I am continuing to work on stepping into Rebus to see if I can find anything, but if you see something in the additional trace info, I would love to know what you think. One additional note: it seems to be happening when more than one message is received at a time, which in our case is when more than one file is picked up by a FileSystemWatcher running in a service. – Tom Miller Dec 20 '18 at 21:25
  • Would it be possible for you to reproduce the issue and put the code somewhere, e.g. on GitHub? Then I will figure out what's tricking you – mookid8000 Dec 21 '18 at 10:53
  • 2
    I sorted out the issue. 2 bus instances were sharing the same queue--one used it for sending and the other receiving. The instance that uses the queue to receive exists in a class that is instantiated by an instance of another class that uses that queue to send messages. I modified the "receiving" instance to use another queue and issue was resolved. Now I just need to get clarity around why that behavior was happening for my own understanding ;-) – Tom Miller Jan 24 '19 at 15:29
  • 1
    Perfect, thanks for taking the time to update the issue with your findings :) one thing, though: When you say "using a queue for sending", it sounds like your understanding is a little bit off to me... if you have a bus instance that only SENDS messages, there's no reason for it to have an input queue, and therefore you should configure it as a one-way client (`.Transport(t => t.UseMsmqAsOneWayClient())`) – mookid8000 Jan 25 '19 at 18:47
  • 1
    Thank you for the clarification--that makes total sense and answers questions I have had for a while Marking this as the answer as it actually was multiple instances consuming messages from the same queue. – Tom Miller Jan 27 '19 at 16:45