Process terminating on IBusClient.ShutdownAsync

[jchannon]

Hi,

We have an implementation of IBusClient and when we call ShutdownAsync it seems to be killing our process.

Shutting Down BusClient and its dependencies.
Shutting down Subscriber.
Shutting down Requester.
The consumer with tag 'amq.ctag-ERfQWSAX9DiQrs9D2bD6bg' has been cancelled.
Consumer amq.ctag-ERfQWSAX9DiQrs9D2bD6bg has been shut down.

It doesn't seem to get to logging anything out for the Responder as shown in the source code so I'm not sure if that is a lead or not https://github.com/pardahlman/RawRabbit/blob/6291e45b405d59e5f4f443949c3f000ffda2cd9c/src/RawRabbit/Common/BaseBusClient.cs#L65

One thing to note is we call ShutdownAsync on a synchronous app. I have split it out like below but it never hits the Wait line

 var t = client.ShutdownAsync();
 t.Wait();

Can you think of any reason why the process is getting terminated?

[pardahlman]

Hello @jchannon - thanks for reporting this!

That is odd. Are you running 1.10.3? Are you running on .NET Framework or Core? I tried to reproduce this myself, but the code you supplied works for me. Does it occur every time you call ShutdownAsync?

The only thing I can think of is that the requester will wait for the configured RequestTimeout if it is waiting for any responses. So.... theoretically.... if you would have a very long request timeout and then call ShutdownAsync you would get logs that looks like yours.

My gut feeling is that the process isn't terminated, but dead locked. Are you able to list the processes and see if it is running?

Could you try to await the task without the synchronization context and see if that helps?

busClient.ShutdownAsync()
    .ConfigureAwait(false)
    .GetAwaiter()
    .GetResult();

[jchannon]

We're on 1.10.2

.Net Core 1.1

It does occur everytime.

Using ps aux | grep -i myapp doesn't return a process of my app unfortunately so it seems to to be killing it.

I tried the code sample you provided but same issue as originally reported :(

[jchannon]

Just upgraded to 1.10.3 but same issue

[jchannon]

Have changed the RequestTimeout to 5 secs but still see the issue

[pardahlman]

That is annoying. I have tried to repro with .NET Core 1.1, but I'm on Windows and it works for me. I take it you don't have any other system logs that can shed more light over this?

Another option for you would be to try to use the Disposable BusClient and see if you get the same behavior. Chances are that you do, as it in turn uses ShutdownAsync, but could be worth trying nevertheless.

[jchannon]

Hi,

Found the culprit, a dodgy boolean in our console app telling it when to stop running.

[jchannon]

One thing I have noticed is that it takes about 11secs to shut down even though the logs are instant. Any ideas?

2017-02-03 12:42:16.743992 ThreadId:7 MessageBusLogger.LogDebug.Shutting Down BusClient and its dependencies.
2017-02-03 12:42:16.748162 ThreadId:7 MessageBusLogger.LogDebug.Shutting down Subscriber.
2017-02-03 12:42:16.752711 ThreadId:7 MessageBusLogger.LogDebug.Shutting down Requester.
2017-02-03 12:42:16.760895 ThreadId:7 MessageBusLogger.LogDebug.The consumer with tag 'amq.ctag--7uACHASV6yJ3BFKv9ehdA' has been cancelled.
2017-02-03 12:42:16.761648 ThreadId:7 MessageBusLogger.LogInformation.Consumer amq.ctag--7uACHASV6yJ3BFKv9ehdA has been shut down.
  Reason: 
  Initiator: Application
  Reply Text: Connection close forced
2017-02-03 12:42:16.779101 ThreadId:7 MessageBusLogger.LogDebug.Shutting down Responder.

-- 11 seconds wait here!!

2017-02-03 12:42:27.165642 ThreadId:7 MessageProcessor.Reset.Client shut down -- This is logged after client.ShutdownAsync().Wait() is called

[pardahlman]

Ok, glad the problem is solved. The reason for the long wait is that RawRabbit waits for the Responder to complete potential ongoing operations before shutting it down. It is implemented in a way that it first removes the subscription (that is, no more incomming messages), and then wait before continuing.

By default the wait period is 10 seconds, but it can be changed through config

[jchannon]

Just tried it and perfect!

Thanks for your help, great stuff!

On 3 February 2017 at 15:20, Pär Dahlman notifications@github.com wrote:

Ok, glad the problem is solved. The reason for the long wait is that RawRabbit waits for the Responder to complete potential ongoing operations https://github.com/pardahlman/RawRabbit/blob/stable/src/RawRabbit/Operations/Responder.cs#L117 before shutting it down. It is implemented in a way that it first removes the subscription (that is, no more incomming messages), and then wait before continuing.

By default the wait period is 10 seconds, but it can be changed through config https://github.com/pardahlman/RawRabbit/blob/stable/src/RawRabbit/Configuration/RawRabbitConfiguration.cs#L25

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/pardahlman/RawRabbit/issues/178#issuecomment-277274266, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGaps87aOD9SlOQZcezVpFTxH81CF0Wks5rY0W8gaJpZM4L1V-X .

[pardahlman]

No worries, buddy!