Azure webroles recycle after configuration change despite handling the RoleEnvironment.Changing event and setting Cancel to false

When changing some of the configuration settings of a webrole, the RoleEnvironment.Changing event is triggered. As far as I understand it, if Cancel is set to false in the RoleEnvironmentChangingEventArgs, the role should not recycle and the changes are just accepted and should be applied as soon as the RoleEnvironment.Changed event fires.

However, our roles are recycling despite setting Cancel to false.

This is the content of the event handler:

public static void onRoleEnvironmentChanging(object sender, 
RoleEnvironmentChangingEventArgs e)
{
    try
    {
        List<RoleEnvironmentConfigurationSettingChange> configurationChanges = e.Changes.OfType<RoleEnvironmentConfigurationSettingChange>().ToList();
        e.Cancel = configurationChanges.Any(c => (c.ConfigurationSettingName == "settingThatShouldRecycleRole")))
    }
    catch (Exception)
    {
        e.Cancel = false;
    }
}

I've added the try catch here just to be sure, but it has never been triggered as far as I've been able to tell.

The setting that triggers e.Cancel = true was not changed. I've logged the final result of this event handler and the role recycles even if e.Cancel was set to false.

Examining the logs of the roles has not yielded a reason for the recycle, unfortunately.

According to this old blog post things might go wrong if the event does not respond in a timely fassion: https://alexandrebrisebois.wordpress.com/2013/09/29/handling-cloud-service-role-configuration-changes-in-windows-azure/

However, I cannot imagine that this code takes very long to execute. Measuring it yielded about 150ms, which is rather slow, but that includes the code that logs the timings to table storage. The claim that handling the event is time sensitive is also not documented anywhere else as far as I have been able to find.

Edit: Relevant contents of WaHostBootstrapper.log

12:27:26.254, INFO ] Getting status from client WaIISHost.exe (2728).
12:27:26.254, INFO ] Client reported status 0.
12:27:26.254, INFO ] Getting status from client w3wp.exe (3424).
12:27:26.254, INFO ] Client reported status 0.
12:27:30.183, INFO ] Sending update notification to client WaIISHost.exe (2728).
12:27:30.183, INFO ] Sending update notification to client w3wp.exe (3424).
12:27:30.261, INFO ] Sending update completion notification to client WaIISHost.exe (2728).
12:27:30.293, INFO ] Sending update completion notification to client w3wp.exe (3424).
12:27:41.271, INFO ] Getting status from client WaIISHost.exe (2728).
12:27:41.271, INFO ] Client reported status 0.
12:27:41.271, INFO ] Getting status from client w3wp.exe (3424).
12:27:41.271, ERROR] Failed to connect to client w3wp.exe (3424).
12:27:41.271, ERROR] <- CRuntimeClient::OnRoleStatusCallback(0x000000A1B6E0E3C0) =0x800706ba
12:27:41.271, INFO ] Removing disconnected client: w3wp.exe (3424).
12:27:56.279, INFO ] Getting status from client WaIISHost.exe (2728).
12:27:56.279, INFO ] Client reported status 0.
12:28:11.284, INFO ] Getting status from client WaIISHost.exe (2728).
12:28:11.284, INFO ] Client reported status 0.
12:28:26.296, INFO ] Getting status from client WaIISHost.exe (2728).
12:28:26.296, INFO ] Client reported status 0.
12:28:35.683, INFO ] Registering client with PID 2964.
12:28:35.683, INFO ] Client w3wp.exe (2964) registered.
12:28:41.464, INFO ] Getting status from client WaIISHost.exe (2728).
12:28:41.464, INFO ] Client reported status 0.
12:28:41.464, INFO ] Getting status from client w3wp.exe (2964).
12:28:41.480, INFO ] Client reported status 0.
12:28:56.499, INFO ] Getting status from client 

Relevant contents of AppAgentRuntime.log (somewhat redacted)

12:27:30.313, INFO ] The role can handle the config change without recycle.     
12:27:30.355, INFO ] Firewall configuration was not found for X.X.X.X. Creating new configuration for X.X.X.X
12:27:30.355, INFO ] Firewall configuration was not found for Y.Y.Y.Y. Creating new configuration for Y.Y.Y.Y
12:27:30.355, INFO ] Creating additional rule for Internal Endpoint.
12:27:30.355, INFO ] Creating additional rule for Internal Endpoint.
12:27:30.355, INFO ] Creating additional rule for Internal Endpoint.
12:27:30.355, INFO ] Setting firewall rule : -REDACTED-
12:27:30.355, INFO ] Firewall rule -REDACTED-
-Repeated 10+ times with different rule guids-
12:27:30.560, INFO ] Cleanup base filters for group NT SERVICE:
12:27:30.560, WARN ] BaseFilterRemoveStealthModeFilters not implemented     
12:27:30.560, INFO ] Add stealth-mode filters if requested for group NT SERVICE:
12:27:30.560, INFO ] Deleting firewall rules...     
12:27:31.011, INFO ] Deleted 14 rules. hr: 0x0      
12:27:31.011, WARN ] BaseFilterRemoveStealthModeFilters not implemented     
12:27:31.011, INFO ] Deleting URLACL : Url = http://X.X.X.X:XXX/        
12:27:31.011, WARN ] Warning: Unable to delete URLACL : URL = http://X.X.X.X:XXX/. Error code - 0x2
12:27:31.011, INFO ] Deleting URLACL : Url = https://X.X.X.X:XXX/
12:27:31.011, INFO ] Successfully created URLACL : URL = https://X.X.X.X:XXX/, SDDL = D:(A;;GX;;;S-1-5-20).
12:27:31.011, INFO ] AgentpUpdateConfigWorker Returning
    00000000.
12:27:31.011, INFO ] <<<<_Context_Ends: {-REDACTED-}    Return value = 00000000. 
12:27:31.011, WARN ] <- AgentMonitoringObject::EventEnd(0x00007FFF616577E0) =0x80070015
12:27:31.011, INFO ] <<<<_Context_Ends: {-REDACTED-}    Return value = 00000000. 

This looks suspicious to me, why is it updating a bunch of firewall rules?

Contents of WaAppAgent.log:

12:27:23.86] [HEART] WindowsAzureGuestAgent Heartbeat.
12:27:23.86] [INFO]  Role current state: Started.
12:27:23.86] [INFO]  Recieved goal state information.
12:27:23.86] [INFO]  Execution status: UpdateSucceeded.
12:27:23.86] [INFO]  Role -REDACTED- is reporting state Ready.
12:27:24.32] [INFO]  Role -REDACTED- has current state Started, desired state Started, and goal state execution status UpdateSucceeded.
12:27:28.87] [HEART] WindowsAzureGuestAgent Heartbeat.
12:27:28.87] [INFO]  Role current state: Started.
12:27:28.87] [INFO]  Recieved goal state information.
12:27:28.87] [INFO]  Execution status: UpdateSucceeded.
12:27:28.87] [INFO]  Role -REDACTED- is reporting state Ready.
12:27:28.87] [INFO]  Goal state 43 received.
12:27:28.87] [INFO]  Received stop role deadline hint: 300000. ExpectedState: Started
12:27:28.87] [INFO]  Goal state being updated.
12:27:28.87] [INFO]  Deleting all user accounts.
12:27:28.87] [INFO]  Role -REDACTED- is being updated.
12:27:28.87] [INFO]  Role -REDACTED- has goal state Started.
12:27:28.87] [INFO]  Extension Plugins Found.
12:27:28.95] [INFO]  Goal state execution started for role -REDACTED-.
12:27:28.95] [INFO]  Driving role -REDACTED- to goal state Started from current state Started.
12:27:29.98] [INFO]  Found role root. roleId:  tagFileName:  tagPatternUsed: *.tag root: E:\
12:27:29.98] [INFO]  Acled the directory E:\base.
12:27:29.98] [INFO]  Acled the directory E:\base\x64.
12:27:29.98] [INFO]  Acled the directory E:\base\x86.
12:27:29.98] [INFO]  Acled the directory D:\Packages.
12:27:29.98] [INFO]  Acled the directory D:\Packages\GuestAgent.
12:27:29.98] [INFO]  Acled the directory D:\Packages\GuestAgent\GuestAgent.
12:27:29.98] [INFO]  Acled the directory D:\Packages\GuestAgent\GuestAgent\LegacyRuntime.
12:27:29.98] [INFO]  Acled the directory D:\Packages\GuestAgent\GuestAgent\LegacyRuntime\x64.
12:27:29.98] [INFO]  Acled the directory D:\Packages\GuestAgent\GuestAgent\LegacyRuntime\x86.
12:27:29.98] [INFO]  Acled the directory D:\Packages\GuestAgent\Telemetry.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64\Extensions.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64\Extensions\ApplicationInsightsExtension.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64\Extensions\ApplicationInsightsExtension\Resources.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64\schema.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64\schema\1.0.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Monitor\x64\schema\2.0.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\RuntimeSettings.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\schema.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Status.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\StatusMonitor.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP\1.2.1.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP\1.2.1\RuntimeSettings.
12:27:29.98] [INFO]  Acled the directory D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP\1.2.1\Status.
12:27:30.08] [INFO]  Found role root. roleId: -REDACTED-
12:27:30.08] [INFO]  Sending new config file: -REDACTED-.
12:27:30.08] [INFO]  Starting installation of plugins. Incarnation: 43 Plugin size: 2
12:27:30.08] [INFO]  Downloading version manifest for plugin Microsoft.Azure.Diagnostics.PaaSDiagnostics from -REDACTED-
12:27:30.13] [INFO]  Getting plugin locations for plugin 'Microsoft.Azure.Diagnostics.PaaSDiagnostics'. Current Version: '1.8.1.0', Requested Version: '1.8.1.0'
12:27:30.13] [INFO]  Auto-Upgrade mode. Highest public version for plugin 'Microsoft.Azure.Diagnostics.PaaSDiagnostics' with requested version: '1.8.1.0', is: '1.8.1.0'
12:27:30.13] [INFO]  Updating plugin 'Microsoft.Azure.Diagnostics.PaaSDiagnostics' to version '1.8.1.0'
12:27:30.14] [INFO]  No plugin settings received. Setting nothing for plugin: Microsoft.Azure.Diagnostics.PaaSDiagnostics version: 1.8.1.0
12:27:30.14] [INFO]  Downloading version manifest for plugin Microsoft.Windows.Azure.Extensions.RDP from -REDACTED-
12:27:30.15] [INFO]  Getting plugin locations for plugin 'Microsoft.Windows.Azure.Extensions.RDP'. Current Version: '1.2.1', Requested Version: '1.2.1'
12:27:30.15] [INFO]  Auto-Upgrade mode. Highest public version for plugin 'Microsoft.Windows.Azure.Extensions.RDP' with requested version: '1.2.1', is: '1.2.1'
12:27:30.15] [INFO]  Updating plugin 'Microsoft.Windows.Azure.Extensions.RDP' to version '1.2.1'
12:27:30.15] [INFO]  No plugin settings received. Setting nothing for plugin: Microsoft.Windows.Azure.Extensions.RDP version: 1.2.1
12:27:30.15] [INFO]  Processing plugin Microsoft.Windows.Azure.Extensions.RDP version 1.2.1, state: enabled, autoupgrade: True, isJson: False
12:27:30.15] [INFO]  Plug-in Microsoft.Windows.Azure.Extensions.RDP 1.2.1 found in cache.
12:27:30.15] [INFO]  Extracting plug-in zip file to folder. Zip file: D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP\1.2.1\Microsoft.Windows.Azure.Extensions.RDP_1.2.1.zip
12:27:30.16] [INFO]  Xml manifest file D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP\1.2.1\PluginManifest.xml found corresponding to the plugin Microsoft.Windows.Azure.Extensions.RDP
12:27:30.16] [INFO]  Install command of plugin Microsoft.Windows.Azure.Extensions.RDP: D:\Packages\Plugins\Microsoft.Windows.Azure.Extensions.RDP\1.2.1\RemoteAccessPluginLauncher.exe
12:27:30.16] [INFO]  Beginning installation of plugin Microsoft.Windows.Azure.Extensions.RDP 1.2.1.
12:27:30.16] [INFO]  Processing plugin Microsoft.Azure.Diagnostics.PaaSDiagnostics version 1.8.1.0, state: enabled, autoupgrade: True, isJson: False
12:27:30.16] [INFO]  Plug-in Microsoft.Azure.Diagnostics.PaaSDiagnostics 1.8.1.0 found in cache.
12:27:30.16] [INFO]  Extracting plug-in zip file to folder. Zip file: D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Microsoft.Azure.Diagnostics.PaaSDiagnostics_1.8.1.0.zip
12:27:30.21] [WARN]  Package extraction failed. D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\Microsoft.Azure.Diagnostics.PaaSDiagnostics_1.8.1.0.zip D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0 HR = '0x8007026A' from PackageExpand, Code: 1005
12:27:30.21] [INFO]  Xml manifest file D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\PluginManifest.xml found corresponding to the plugin Microsoft.Azure.Diagnostics.PaaSDiagnostics
12:27:30.21] [INFO]  Install command of plugin Microsoft.Azure.Diagnostics.PaaSDiagnostics: D:\Packages\Plugins\Microsoft.Azure.Diagnostics.PaaSDiagnostics\1.8.1.0\diagnosticspluginlauncher.exe
12:27:30.21] [INFO]  Beginning installation of plugin Microsoft.Azure.Diagnostics.PaaSDiagnostics 1.8.1.0.
12:27:30.26] [INFO]  Found role root. roleId: {-REDACTED-} tagFileName: -REDACTED-.cssx tagPatternUsed: -REDACTED-.cssx.tag root: E:\
12:27:30.26] [WARN]  Environment variable RoleRoot already exists with old value: E:\. Replacing it with new value: E:\
12:27:30.26] [INFO]  Waiting for command of plugin Microsoft.Windows.Azure.Extensions.RDP to finish...
12:27:30.40] [INFO]  Found role root. roleId: {-REDACTED-} tagFileName: -REDACTED-.cssx tagPatternUsed: -REDACTED-.cssx.tag root: E:\
12:27:30.40] [WARN]  Environment variable RoleRoot already exists with old value: E:\. Replacing it with new value: E:\
12:27:30.40] [INFO]  Waiting for command of plugin Microsoft.Azure.Diagnostics.PaaSDiagnostics to finish...
12:27:31.01] [INFO]  Role -REDACTED- was updated.
12:27:31.01] [INFO]  1 events queued for role -REDACTED-.
12:27:33.56] [INFO]  Successfully installed plugin Microsoft.Windows.Azure.Extensions.RDP 1.2.1.
12:27:33.56] [INFO]  Plugin enabled (name: Microsoft.Windows.Azure.Extensions.RDP, version: 1.2.1)., Code: 0
12:27:35.00] [HEART] WindowsAzureGuestAgent Heartbeat.
12:27:35.00] [INFO]  Role current state: Started.
12:27:35.00] [INFO]  Recieved goal state information.
12:27:35.00] [INFO]  Execution status: UpdateSucceeded.
12:27:35.00] [INFO]  Role -REDACTED- is reporting queued event [NotReady, Starting, Role was updated successfully. @05/26/2017 12:27:31.01].
12:27:35.00] [INFO]  Generating substatus from system events.
12:27:35.00] [INFO]  Substatus is Role was updated successfully. System is initializing. [2017-05-26T12:27:28Z]
12:27:35.00] [INFO]  Role -REDACTED- is reporting state NotReady with sub-status Starting and details Role was updated successfully. System is initializing. [2017-05-26T12:27:28Z].
12:27:36.02] [INFO]  Role -REDACTED- has current state Started, desired state Started, and goal state execution status UpdateSucceeded.
12:27:40.03] [HEART] WindowsAzureGuestAgent Heartbeat.
12:27:40.03] [INFO]  Role current state: Started.
12:27:40.03] [INFO]  Recieved goal state information.
12:27:40.03] [INFO]  Execution status: UpdateSucceeded.
12:27:40.03] [INFO]  Role -REDACTED- is reporting state Ready.
12:27:41.03] [INFO]  Role -REDACTED- has current state Started, desired state Started, and goal state execution status UpdateSucceeded.
12:27:45.05] [HEART] WindowsAzureGuestAgent Heartbeat.
12:27:45.05] [INFO]  Role current state: Started.
12:27:45.05] [INFO]  Recieved goal state information.
12:27:45.05] [INFO]  Execution status: UpdateSucceeded.
12:27:45.05] [INFO]  Role -REDACTED- is reporting state Ready.
12:27:46.07] [INFO]  Role -REDACTED- has current state Started, desired state Started, and goal state execution status UpdateSucceeded.

It does this even when I don't do anything with the changed settings:

RoleEnvironment.Changing += onRoleEnvironmentChanging;
RoleEnvironment.Changed += onRoleEnvironmentChanged;

public static void onRoleEnvironmentChanging(object sender, RoleEnvironmentChangingEventArgs e)
{
  e.Cancel = false;
}

private static void onRoleEnvironmentChanged(object sender, RoleEnvironmentChangedEventArgs e)
{
}

Edit2: fixed

Disabling application insights fixed the problem.

See this question for removing application insights: Remove Application Insight from application on Visual Studio 2013)

In addition, I disabled sending diagnostics data to Application Insights: See disable send diagnostics data to application insights on publish settings

Finally there was a Windows Azure Diagnostics extension enabled on the role that also uploaded diagnostics to Application Insights. This extension had to be deleted via the portal.

Any process running on the VM which hooks into the service runtime can trigger a recycle. Check WaHostBootstrapper logs to see which process is causing the recycle. You can start with https://blogs.msdn.microsoft.com/kwill/2013/08/09/windows-azure-paas-compute-diagnostics-data/, and specifically focus on the ones that talk about WaHostBootstrapper.