Skip to content
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

Instance is not terminating/recovering when audit queue does not exist #3536

Closed
ramonsmits opened this issue May 24, 2023 · 2 comments · Fixed by #3589
Closed

Instance is not terminating/recovering when audit queue does not exist #3536

ramonsmits opened this issue May 24, 2023 · 2 comments · Fixed by #3589
Labels
Milestone

Comments

@ramonsmits
Copy link
Member

Describe the bug

Description

A audit instance keeps running and not terminating when the audit queue does not exist.

Expected behavior

Startup to fail

Actual behavior

Instance keeps running and does not recover.

Versions

4.30.0 with MSMQ

Steps to reproduce

  1. Create audit instance
  2. Stop instance
  3. Delete audit queue
  4. Start instance

Observe errors in log file and Windows event log but the instance to remain running.

Relevant log output

2023-05-24 10:19:46.5002|11|Fatal|NServiceBus.Raw.StartableRawEndpoint|Receiver failed to initialize.
System.Exception: The queue FormatName:DIRECT=OS:ZOLDER\private$\audit2 does not exist. Run the CreateQueues.ps1 script included in the project output, or enable queue creation on startup using EndpointConfiguration.EnableInstallers(). ---> System.Messaging.MessageQueueException: The queue does not exist or you do not have sufficient permissions to perform the operation.
   at System.Messaging.MessageQueue.MQCacheableInfo.get_Transactional()
   at System.Messaging.MessageQueue.get_Transactional()
   at NServiceBus.Transport.Msmq.MessagePump.QueueIsTransactional() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 188
   --- End of inner exception stack trace ---
   at NServiceBus.Transport.Msmq.MessagePump.QueueIsTransactional() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 201
   at NServiceBus.Transport.Msmq.MessagePump.Init(Func`2 onMessage, Func`2 onError, CriticalError criticalError, PushSettings settings) in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 42
   at NServiceBus.Transport.Msmq.CompositePump.<Init>d__3.MoveNext() in /_/src/NServiceBus.Transport.Msmq/CompositePump.cs:line 19
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Raw.StartableRawEndpoint.<InitializeReceiver>d__14.MoveNext()
2023-05-24 10:19:46.5084|11|Error|ServiceControl.Audit.Auditing.AuditIngestion|Error while trying to start audit message ingestion. Starting will be retried in 00:01:00.
System.Exception: The queue FormatName:DIRECT=OS:ZOLDER\private$\audit2 does not exist. Run the CreateQueues.ps1 script included in the project output, or enable queue creation on startup using EndpointConfiguration.EnableInstallers(). ---> System.Messaging.MessageQueueException: The queue does not exist or you do not have sufficient permissions to perform the operation.
   at System.Messaging.MessageQueue.MQCacheableInfo.get_Transactional()
   at System.Messaging.MessageQueue.get_Transactional()
   at NServiceBus.Transport.Msmq.MessagePump.QueueIsTransactional() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 188
   --- End of inner exception stack trace ---
   at NServiceBus.Transport.Msmq.MessagePump.QueueIsTransactional() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 201
   at NServiceBus.Transport.Msmq.MessagePump.Init(Func`2 onMessage, Func`2 onError, CriticalError criticalError, PushSettings settings) in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 42
   at NServiceBus.Transport.Msmq.CompositePump.<Init>d__3.MoveNext() in /_/src/NServiceBus.Transport.Msmq/CompositePump.cs:line 19
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Raw.StartableRawEndpoint.<InitializeReceiver>d__14.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Raw.StartableRawEndpoint.<Start>d__1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at ServiceControl.Transports.TransportCustomization.QueueIngestor.<Start>d__1.MoveNext() in /_/src/ServiceControl.Transports/TransportCustomization.cs:line 88
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at ServiceControl.Audit.Auditing.AuditIngestion.<EnsureStarted>d__6.MoveNext() in /_/src/ServiceControl.Audit/Auditing/AuditIngestion.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at ServiceControl.Audit.Infrastructure.Watchdog.<<Start>b__11_0>d.MoveNext() in /_/src/ServiceControl.Audit/Infrastructure/WatchDog.cs:line 46
2023-05-24 10:19:46.5310|7|Info|Microsoft.Hosting.Lifetime|Application started. Hosting environment: Production; Content root path: C:\Program Files (x86)\Particular Software\Particular.msmq3.Audit\

Additional Information

Workarounds

Possible solutions

Additional information

Using MSMQ transport

@ramonsmits ramonsmits added the Bug label May 24, 2023
@ramonsmits
Copy link
Member Author

ramonsmits commented May 24, 2023

FYI: When the queue does exist but there is a MSMQ permission issue then eventually the transport circuit breaker trips and the SC instance tries to shutdown.

However, this isn't actually happening. The process stays alive

First part shutting down SC components

2023-05-24 10:27:38.9365|28|Warn|NServiceBus.Transport.Msmq.MessagePump|MSMQ receive operation failed
System.Messaging.MessageQueueException (0x80004005): Access to Message Queuing system is denied.
   at System.Messaging.MessageQueue.MQCacheableInfo.get_ReadHandle()
   at System.Messaging.MessageEnumerator.get_Handle()
   at System.Messaging.MessageEnumerator.MoveNext(TimeSpan timeout)
   at NServiceBus.Transport.Msmq.MessagePump.<InnerProcessMessages>d__6.MoveNext() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 131
2023-05-24 10:27:39.6486|9|Warn|NServiceBus.Transport.Msmq.RepeatedFailuresOverTimeCircuitBreaker|The circuit breaker for MsmqPeek will now be triggered
2023-05-24 10:27:39.6486|9|Fatal|NServiceBus|Failed to peek audit2@ZOLDER
System.Messaging.MessageQueueException (0x80004005): Access to Message Queuing system is denied.
   at System.Messaging.MessageQueue.MQCacheableInfo.get_ReadHandle()
   at System.Messaging.MessageEnumerator.get_Handle()
   at System.Messaging.MessageEnumerator.MoveNext(TimeSpan timeout)
   at NServiceBus.Transport.Msmq.MessagePump.<InnerProcessMessages>d__6.MoveNext() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 131
2023-05-24 10:27:39.6486|26|Warn|ServiceControl.Audit.Auditing.AuditIngestion|OnCriticalError. 'Failed to peek audit2@ZOLDER'
System.Messaging.MessageQueueException (0x80004005): Access to Message Queuing system is denied.
   at System.Messaging.MessageQueue.MQCacheableInfo.get_ReadHandle()
   at System.Messaging.MessageEnumerator.get_Handle()
   at System.Messaging.MessageEnumerator.MoveNext(TimeSpan timeout)
   at NServiceBus.Transport.Msmq.MessagePump.<InnerProcessMessages>d__6.MoveNext() in /_/src/NServiceBus.Transport.Msmq/MessagePump.cs:line 131
2023-05-24 10:27:39.6486|26|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore acquiring
2023-05-24 10:27:39.6486|26|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore acquired
2023-05-24 10:27:39.6486|26|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Infrastructure shut down commencing
2023-05-24 10:27:39.6486|26|Info|NServiceBus.Raw.RunningRawEndpointInstance|Stopping receiver.
2023-05-24 10:27:39.9420|12|Info|NServiceBus.Raw.RunningRawEndpointInstance|Receiver stopped.
2023-05-24 10:27:39.9420|12|Info|NServiceBus.Raw.StoppableRawEndpoint|Initiating shutdown.
2023-05-24 10:27:39.9420|12|Info|NServiceBus.Raw.StoppableRawEndpoint|Shutdown complete.
2023-05-24 10:27:39.9420|12|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Infrastructure shut down completed
2023-05-24 10:27:39.9420|12|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore releasing
2023-05-24 10:27:39.9420|12|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore released

Second part shutting down actual application

2023-05-24 10:33:51.1817|27|Info|Microsoft.Hosting.Lifetime|Application is shutting down...
2023-05-24 10:33:51.1817|7|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore acquiring
2023-05-24 10:33:51.1817|7|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore acquired
2023-05-24 10:33:51.1817|7|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Infrastructure shut down commencing
2023-05-24 10:33:51.1817|7|Info|NServiceBus.Raw.RunningRawEndpointInstance|Stopping receiver.
2023-05-24 10:33:51.3880|6|Info|NServiceBus.Raw.RunningRawEndpointInstance|Receiver stopped.
2023-05-24 10:33:51.3880|6|Info|NServiceBus.Raw.StoppableRawEndpoint|Initiating shutdown.
2023-05-24 10:33:51.3880|6|Info|NServiceBus.Raw.StoppableRawEndpoint|Shutdown complete.
2023-05-24 10:33:51.3880|6|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Infrastructure shut down completed
2023-05-24 10:33:51.3880|6|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore releasing
2023-05-24 10:33:51.3880|6|Info|ServiceControl.Audit.Auditing.AuditIngestion|Shutting down. Start/stop semaphore released
2023-05-24 10:33:51.3880|21|Info|NServiceBus.RunningEndpointInstance|Initiating shutdown.
2023-05-24 10:33:51.3880|21|Info|NServiceBus.RunningEndpointInstance|Shutdown complete.

@ramonsmits
Copy link
Member Author

Likely the application life time isn't triggered to shutdown the application which keeps the process alive.

@jpalac jpalac added this to the 4.32.0 milestone Jun 13, 2023
@jpalac jpalac changed the title Instance is not terminating when audit queue does not exist Instance is not terminating/recovering when audit queue does not exist Jun 21, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
2 participants