projectkudu / kudu

Kudu is the engine behind git/hg deployments, WebJobs, and various other features in Azure Web Sites. It can also run outside of Azure.
Apache License 2.0
3.12k stars 655 forks source link

"Unable to acquire Singleton lock" after Webjobs deployment #3133

Closed GermanCoca closed 4 months ago

GermanCoca commented 4 years ago

For deployment issues, please provide us with the following information:

Repro steps.

your project built successfully on your dev machine but failed on Azure?

Yes

please write down your build tools and their versions (ie Msbuild 15.1.0.0)

VSBuild 15.0

When deploying our Webjob solution to the staging environment, we observe from the Kudu logs that the singleton locks are not being released for timer triggers. This in turn result in multiple errors "Unable to acquire Singleton lock" when these Webjobs are initialized again.

This deployment is done in Azure Pipelines. To avoid dll locks that resulted in deployment failures, we are:

From Webjobs SDK issues we found that these errors could be caused by hard shutdowns of the Webjobs, and from the Kudu documentation that the restarting of the Web App could be the culprit. However, from the Kudu logs we observe that when performing the shutdown the Webjobs are gracefully stopped.

The log/error given by the failure.

[03/17/2020 17:35:31 > a22e53: SYS INFO] WebJob is still running
[03/17/2020 17:36:48 > 7c9ba5: SYS INFO] WebJob is still running
[03/17/2020 17:37:26 > 270010: SYS INFO] WebJob is still running
[03/17/2020 19:09:49 > 7c9ba5: SYS INFO] Status changed to Disabling
[03/17/2020 19:10:03 > 7c9ba5: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:10:03 > 7c9ba5: SYS INFO] Status changed to Stopping
[03/17/2020 19:10:03 > 7c9ba5: INFO] Job host stopped
[03/17/2020 19:10:03 > 7c9ba5: SYS INFO] Status changed to Success
[03/17/2020 19:10:03 > 7c9ba5: SYS INFO] Status changed to Stopped
[03/17/2020 19:10:03 > 270010: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:10:03 > 270010: SYS INFO] Status changed to Stopping
[03/17/2020 19:10:03 > 270010: INFO] Job host stopped
[03/17/2020 19:10:03 > 270010: SYS INFO] Status changed to Success
[03/17/2020 19:10:04 > 270010: SYS INFO] Status changed to Stopped
[03/17/2020 19:10:09 > a22e53: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:10:09 > a22e53: SYS INFO] Status changed to Stopping
[03/17/2020 19:10:09 > a22e53: SYS INFO] Status changed to Success
[03/17/2020 19:10:09 > a22e53: SYS INFO] Status changed to Stopped
[03/17/2020 19:20:39 > a22e53: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:20:39 > 270010: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:20:39 > 7c9ba5: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:21:50 > a22e53: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:21:50 > a22e53: SYS INFO] Status changed to Starting
[03/17/2020 19:21:51 > a22e53: SYS INFO] Job directory change detected: Job file 'xxxx.Entities.dll' timestamp differs between source and working directories.
[03/17/2020 19:22:35 > 270010: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:22:36 > 270010: SYS INFO] Status changed to Starting
[03/17/2020 19:22:40 > 7c9ba5: SYS INFO] Detected WebJob file/s were updated, refreshing WebJob
[03/17/2020 19:22:43 > 7c9ba5: SYS INFO] Status changed to Starting
[03/17/2020 19:22:43 > 270010: SYS INFO] Job directory change detected: Job file 'xxxx.Entities.dll' timestamp differs between source and working directories.
[03/17/2020 19:22:44 > 7c9ba5: SYS INFO] Job directory change detected: Job file 'xxxx.Entities.dll' timestamp differs between source and working directories.
[03/17/2020 19:24:30 > 7c9ba5: SYS INFO] Run script 'xxxx.Jobs.KnowledgeCenterPump.exe' with script host - 'WindowsScriptHost'
[03/17/2020 19:24:30 > 7c9ba5: SYS INFO] Status changed to Running
[03/17/2020 19:24:36 > a22e53: SYS INFO] Run script 'xxxx.Jobs.KnowledgeCenterPump.exe' with script host - 'WindowsScriptHost'
[03/17/2020 19:24:37 > a22e53: SYS INFO] Status changed to Running
[03/17/2020 19:24:37 > 270010: SYS INFO] Run script 'xxxx.Jobs.KnowledgeCenterPump.exe' with script host - 'WindowsScriptHost'
[03/17/2020 19:24:38 > 270010: SYS INFO] Status changed to Running
[03/17/2020 19:25:02 > a22e53: INFO] Running in region: 'West Europe'
[03/17/2020 19:25:02 > a22e53: INFO] Development settings applied
[03/17/2020 19:25:02 > a22e53: INFO] Found the following functions:
[03/17/2020 19:25:02 > a22e53: INFO] xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessMessage
[03/17/2020 19:25:02 > a22e53: INFO] xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessTimer
[03/17/2020 19:25:02 > a22e53: INFO] Unable to acquire Singleton lock (staging/xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessTimer.staging.Listener).
[03/17/2020 19:25:02 > a22e53: INFO] Job host started
[03/17/2020 19:25:14 > 270010: INFO] Running in region: 'West Europe'
[03/17/2020 19:25:14 > 270010: INFO] Development settings applied
[03/17/2020 19:25:14 > 270010: INFO] Found the following functions:
[03/17/2020 19:25:14 > 270010: INFO] xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessMessage
[03/17/2020 19:25:14 > 270010: INFO] xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessTimer
[03/17/2020 19:25:14 > 270010: INFO] Unable to acquire Singleton lock (staging/xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessTimer.staging.Listener).
[03/17/2020 19:25:14 > 270010: INFO] Job host started
[03/17/2020 19:25:17 > 7c9ba5: INFO] Running in region: 'West Europe'
[03/17/2020 19:25:17 > 7c9ba5: INFO] Development settings applied
[03/17/2020 19:25:17 > 7c9ba5: INFO] Found the following functions:
[03/17/2020 19:25:17 > 7c9ba5: INFO] xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessMessage
[03/17/2020 19:25:17 > 7c9ba5: INFO] xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessTimer
[03/17/2020 19:25:17 > 7c9ba5: INFO] Unable to acquire Singleton lock (staging/xxxx.Jobs.KnowledgeCenterPump.KnowledgeCenterPumpProgram.ProcessTimer.staging.Listener).
[03/17/2020 19:25:17 > 7c9ba5: INFO] Job host started

As a consequence, we have to manually break the leases in azure-webjobs-hosts/locks/staging. Any info on why these errors could be happening?

jvano commented 4 months ago

Hi

If the problem persists and is related to running it on Azure App Service, please open a support incident in Azure: https://learn.microsoft.com/en-us/azure/azure-portal/supportability/how-to-create-azure-support-request

This way we can better track and assist you on this case

Thanks,

Joaquin Vano Azure App Service