Endpoint on Azure web job stops processing ASB queue

nservicebus
azureservicebus

(Kimmo Puranen) #1

We’re running NSB endpoints on Azure web jobs and we have had issues with endpoint occasionally stopping to process messages from Azure Service Bus queue. Seems like the endpoint or web job freezes and the messages just stays in ASB queue.

Only when the Azure web job is restarted the endpoint starts to process messages again. Basicly the endpoint is configured in similar way than in this Particular’s show case: https://docs.particular.net/samples/show-case/cloud-azure/.


(Sean Feldman) #2

Hi Kimmo,

To help, would need a bit more of information.
Do you have any information in your log files?


(Kimmo Puranen) #3

I tried to upload full web job’s log file as a ZIP here, but seems like new users aren’t allowed to do this, so here’s one part of the log. This might not be related to the problem, but I have not found any else errors from the web job log.

[02/09/2018 01:41:20 > d6fac0: INFO] X.Y.Z.MyEndpoint1 host started.
[02/09/2018 02:40:40 > d6fac0: SYS INFO] WebJob is still running
[02/09/2018 03:23:19 > d6fac0: SYS INFO] WebJob is stopping due to website shutting down
[02/09/2018 03:23:19 > d6fac0: SYS INFO] Status changed to Stopping
[02/09/2018 03:23:20 > d6fac0: ERR ]
[02/09/2018 03:23:20 > d6fac0: ERR ] Unhandled Exception: System.Threading.Tasks.TaskCanceledException: A task was canceled.
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.Host.Protocols.PersistentQueueWriter`1.d__0.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.Host.Loggers.CompositeFunctionInstanceLogger.d__8.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.d__1.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.Host.Executors.HeartbeatFunctionExecutor.d__0.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.Host.Executors.AbortListenerFunctionExecutor.d__0.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.Host.Executors.ShutdownFunctionExecutor.d__0.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.JobHost.d__7.MoveNext()
[02/09/2018 03:23:20 > d6fac0: ERR ] — End of stack trace from previous location where exception was thrown —
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[02/09/2018 03:23:20 > d6fac0: ERR ] at Microsoft.Azure.WebJobs.JobHost.Call(MethodInfo method)
[02/09/2018 03:23:20 > d6fac0: ERR ] at X.Y.Z.MyEndpoint1.Program.Main() in C:\agent_work\1\s\X.Y.Z.MyEndpoint1\Program.cs:line 33
[02/09/2018 03:23:21 > d6fac0: SYS ERR ] Job failed due to exit code -532462766
[02/09/2018 03:23:21 > d6fac0: SYS INFO] Status changed to Stopped
[02/09/2018 03:23:49 > 14ce59: SYS INFO] Status changed to Starting
[02/09/2018 03:23:49 > 14ce59: SYS INFO] WebJob singleton setting is False
[02/09/2018 03:23:59 > 14ce59: SYS INFO] Run script ‘X.Y.Z.MyEndpoint1.exe’ with script host - ‘WindowsScriptHost’
[02/09/2018 03:23:59 > 14ce59: SYS INFO] Status changed to Running
[02/09/2018 03:24:39 > 14ce59: INFO] Starting X.Y.Z.MyEndpoint1 host…
[02/09/2018 03:24:39 > 14ce59: INFO] Found the following functions:
[02/09/2018 03:24:39 > 14ce59: INFO] X.Y.Z.MyEndpoint1.Program.AsyncMain
[02/09/2018 03:24:39 > 14ce59: INFO] Executing: ‘Program.AsyncMain’ - Reason: ‘This function was programmatically called via the host APIs.’
[02/09/2018 03:24:39 > 14ce59: INFO] 2018-02-09 05:24:24.515 INFO DefaultFactory Logging to ‘D:\local\Temp\jobs\continuous\X-Y-Z-MyEndpoint1\fy10srx5.qff’ with level Info
[02/09/2018 03:24:39 > 14ce59: INFO] 2018-02-09 05:24:33.843 INFO NServiceBus.LicenseManager Selected active license from D:\local\Temp\jobs\continuous\X-Y-Z-MyEndpoint1\fy10srx5.qff\NServiceBus\License.xml
[02/09/2018 03:24:39 > 14ce59: INFO]
[02/09/2018 03:24:39 > 14ce59: INFO] 2018-02-09 05:24:33.999 INFO NServiceBus.PerformanceMonitorUsersInstaller Did not attempt to add user ‘IIS APPPOOL\MyDemoSite__357c’ to group ‘Performance Monitor Users’ since the process is not running with elevated privileges. Processing will continue. To manually perform this action, run the following command from an admin console:
[02/09/2018 03:24:39 > 14ce59: INFO] net localgroup “Performance Monitor Users” “IIS APPPOOL\MyDemoSite__357c” /add


(Kimmo Puranen) #4

A view from web job details:


(Kimmo Puranen) #5

Also the next web job issue seems somewhat similar, so at this stage I’m not sure is the problem related to Azure web job or NServiceBus configuration or both of those working together. https://github.com/Azure/azure-webjobs-sdk/issues/590


(Sean Feldman) #6

Could you please post NServiceBus log?
Azure ServiceBus transport is not using webjobs trigger, but has its own receiving mechansim. If it’s the one that is failing, NServiceBus logs will contain the information that might help.


(Kimmo Puranen) #7

Here’s content of one NSB log file:

2018-02-08 16:05:51.912 INFO NServiceBus.Unicast.UnicastBus Initiating shutdown.
2018-02-08 16:05:52.849 INFO NServiceBus.ForwardingTopology Closing messaging factories
2018-02-08 16:05:59.630 INFO NServiceBus.Unicast.UnicastBus Shutdown complete.
2018-02-08 16:06:02.271 INFO DefaultFactory Logging to ‘D:\home\site\wwwroot\App_Data’ with level Info
2018-02-08 16:06:03.583 INFO DefaultFactory Logging to ‘D:\home\site\wwwroot\App_Data’ with level Info
2018-02-08 16:06:16.114 FATAL NServiceBus.Features.LicenseReminder Failed to initialize the license
System.IO.IOException: The specified registry key does not exist.
at Microsoft.Win32.RegistryKey.Win32Error(Int32 errorCode, String str)
at Microsoft.Win32.RegistryKey.CreateSubKeyInternal(String subkey, RegistryKeyPermissionCheck permissionCheck, Object registrySecurityObj, RegistryOptions registryOptions)
at Microsoft.Win32.RegistryKey.CreateSubKey(String subkey, RegistryKeyPermissionCheck permissionCheck)
at Microsoft.Win32.RegistryKey.CreateSubKey(String subkey)
at Particular.Licensing.TrialStartDateStore.GetTrialStartDate()
at Particular.Licensing.ActiveLicense.Find(String applicationName, LicenseSource[] licenseSources)
at NServiceBus.LicenseManager.InitializeLicense(String licenseText, String licenseFilePath)
at NServiceBus.Features.LicenseReminder.Setup(FeatureConfigurationContext context)
2018-02-08 16:06:16.333 INFO NServiceBus.PerformanceMonitorUsersInstaller Did not attempt to add user ‘IIS APPPOOL\MyDemoSite__357c’ to group ‘Performance Monitor Users’ since the process is not running with elevated privileges. Processing will continue. To manually perform this action, run the following command from an admin console:
net localgroup “Performance Monitor Users” “IIS APPPOOL\MyDemoSite__357c” /add
2018-02-08 16:06:16.536 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs pulled from the input queue /sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:06:16.536 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs successfully processed / sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:06:16.552 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs failures / sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:06:16.896 FATAL NServiceBus.Features.LicenseReminder Failed to initialize the license
System.IO.IOException: The specified registry key does not exist.
at Microsoft.Win32.RegistryKey.Win32Error(Int32 errorCode, String str)
at Microsoft.Win32.RegistryKey.CreateSubKeyInternal(String subkey, RegistryKeyPermissionCheck permissionCheck, Object registrySecurityObj, RegistryOptions registryOptions)
at Microsoft.Win32.RegistryKey.CreateSubKey(String subkey, RegistryKeyPermissionCheck permissionCheck)
at Microsoft.Win32.RegistryKey.CreateSubKey(String subkey)
at Particular.Licensing.TrialStartDateStore.GetTrialStartDate()
at Particular.Licensing.ActiveLicense.Find(String applicationName, LicenseSource[] licenseSources)
at NServiceBus.LicenseManager.InitializeLicense(String licenseText, String licenseFilePath)
at NServiceBus.Features.LicenseReminder.Setup(FeatureConfigurationContext context)
2018-02-08 16:06:17.036 INFO NServiceBus.PerformanceMonitorUsersInstaller Did not attempt to add user ‘IIS APPPOOL\MyDemoSite__357c’ to group ‘Performance Monitor Users’ since the process is not running with elevated privileges. Processing will continue. To manually perform this action, run the following command from an admin console:
net localgroup “Performance Monitor Users” “IIS APPPOOL\MyDemoSite__357c” /add
2018-02-08 16:06:17.239 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs pulled from the input queue /sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:06:17.239 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs successfully processed / sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:06:17.255 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs failures / sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:06:39.161 INFO NServiceBus.Unicast.UnicastBus Initiating shutdown.
2018-02-08 16:06:39.208 INFO NServiceBus.ForwardingTopology Closing messaging factories
2018-02-08 16:06:39.318 INFO NServiceBus.Unicast.UnicastBus Shutdown complete.
2018-02-08 16:29:48.589 INFO DefaultFactory Logging to ‘D:\home\site\wwwroot\App_Data’ with level Info
2018-02-08 16:30:06.450 FATAL NServiceBus.Features.LicenseReminder Failed to initialize the license
System.IO.IOException: The specified registry key does not exist.
at Microsoft.Win32.RegistryKey.Win32Error(Int32 errorCode, String str)
at Microsoft.Win32.RegistryKey.CreateSubKeyInternal(String subkey, RegistryKeyPermissionCheck permissionCheck, Object registrySecurityObj, RegistryOptions registryOptions)
at Microsoft.Win32.RegistryKey.CreateSubKey(String subkey, RegistryKeyPermissionCheck permissionCheck)
at Microsoft.Win32.RegistryKey.CreateSubKey(String subkey)
at Particular.Licensing.TrialStartDateStore.GetTrialStartDate()
at Particular.Licensing.ActiveLicense.Find(String applicationName, LicenseSource[] licenseSources)
at NServiceBus.LicenseManager.InitializeLicense(String licenseText, String licenseFilePath)
at NServiceBus.Features.LicenseReminder.Setup(FeatureConfigurationContext context)
2018-02-08 16:30:06.732 INFO NServiceBus.PerformanceMonitorUsersInstaller Did not attempt to add user ‘IIS APPPOOL\MyDemoSite__357c’ to group ‘Performance Monitor Users’ since the process is not running with elevated privileges. Processing will continue. To manually perform this action, run the following command from an admin console:
net localgroup “Performance Monitor Users” “IIS APPPOOL\MyDemoSite__357c” /add
2018-02-08 16:30:07.013 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs pulled from the input queue /sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:30:07.013 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs successfully processed / sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:30:07.028 INFO NServiceBus.PerformanceCounterHelper NServiceBus performance counter for ‘# of msgs failures / sec’ is not set up correctly. To rectify this problem, consult the NServiceBus performance counters documentation.
2018-02-08 16:30:24.895 INFO NServiceBus.Unicast.UnicastBus Initiating shutdown.
2018-02-08 16:30:25.145 INFO NServiceBus.ForwardingTopology Closing messaging factories
2018-02-08 16:30:25.332 INFO NServiceBus.Unicast.UnicastBus Shutdown complete.


(Sean Feldman) #8

Thank you Kimmo.

This one unfortunately doesn’t reveal the issue. It starts with NServiceBus logging that shutdown is initialized, but not the reason for the shutdown that took place earlier. Could you share those logs?


(Sean Feldman) #9

Hi Kimmo,

Have you had a chance to look at the log files to see what error is causing endpoint to shutdown?


(Kimmo Puranen) #10

Hi Sean,

Could I email the full log straight to you? I got the same situation now on one of the environments. This problem is hard to track because it’s so infrequent.


(Sean Feldman) #11

Hi Kimmo,

Absolutely. sean.feldman@particular.net.