iis_pool is not idempotent when recycle_at_time is specified and is not changed

[jsco2t]

Cookbook version

4.1.7

Chef-client version

chef-client: 12.7.2
kitchen: 1.5.0

Platform Details

Windows Server 2012 R2

Issue:

After an app pool has been configured with iis_pool resource parameter recycle_at_time the next time the cookbook converges (with no changes to the app pool) the app pool is restarted.

Steps to Reproduce:

• Configure a site's app pool using the iis_pool resource from the IIS Cookbook. Make sure that a custom recycle_at_time is provided.

Example:

iis_pool 'foo' do
    runtime_version '4.0'
    pool_identity :SpecificUser
    pool_username 'some user'
    pool_password 'some password'
    idle_timeout '00:00:00'
    recycle_at_time '01:00:00'            # bug bug
    recycle_after_time '00:00:00'
    action [:add, :config]
end

• Converge the cookbook. (I was using test kitchen to do this)
• Converge the cookbook again.

Expected Result:

The second cookbook converge should be, effectively, a noop. It shouldn't adjust the app pool or cause the app pool to restart. The cook book (and more specifically the iis_pool resource) should be idempotent.

Actual Result:

Each time the cookbook converges the app pool is restarted. This can be observed in a few ways.

First the output from test kitchen reports the app pool is being configured:

• iis_pool[foo] action config[2016-06-14T17:36:26-05:00] INFO: Processing iis_pool[foo] action config
  [2016-06-14T17:36:26-05:00] INFO: iis_pool[foo] configured application pool
• If you check the event log on the target node machine the Web Server IIS event log will report that the app pool was restarted (because of a configuration change).

Further investigation notes

I spent several hours scratching my head over this and reading the IIS cookbook code. After careful inspection I believe the bug is probably happening here (my best guess):

iis/providers/pool.rb: lines 238-239:

node_array = XPath.match(doc.root, 'APPPOOL/add/recycling/periodicRestart/schedule/add')
should_clear_apppool_schedules = ((new_resource.recycle_at_time && is_new_recycle_at_time) || !node_array.empty?) || (new_resource.recycle_schedule_clear && !node_array.empty?)

I believe the problematic OR check is this statement: (new_resource.recycle_at_time && is_new_recycle_at_time) || !node_array.empty?. If I'm reading that correctly, in the context of the above, it will result in should_clear_apppool_schedules == true if we had a recycle_at_time but that recycle_at_time was not a new time. Meaning the app_pool was already configured with a restart time - so the node_array was not empty. But the restart time was also not new.

When I run the kitchen converge with debug output - it seems to agree that this is happening. Here is roughly what I see:

[2016-06-14T22:55:00-05:00] DEBUG: iis_pool[foo] current_resource match output: APPPOOL "foo" (MgdVersion:v4.0,MgdMode:Integrated,state:Started)
[2016-06-14T22:55:00-05:00] DEBUG: C:\Windows\System32\inetsrv\appcmd.exe list app pool "foo" /config:* /xml
[2016-06-14T22:55:00-05:00] DEBUG: C:\Windows\System32\inetsrv\appcmd.exe set config /section:applicationPools "/-[name='foo'].recycling.periodicRestart.schedule"
[2016-06-14T22:55:00-05:00] DEBUG: C:\Windows\System32\inetsrv\appcmd.exe set config /section:applicationPools "/+[name='foo'].recycling.periodicRestart.schedule.[value='01:00:00']"
[2016-06-14T22:55:00-05:00] INFO: iis_pool[foo] configured application pool

On Feb 17th it appears the above code was updated: b5b95db

-    should_clear_apppool_schedules = ((new_resource.recycle_at_time && is_new_recycle_at_time) || node_array.length > 1) || (new_resource.recycle_schedule_clear && node_array.length > 0)
+    should_clear_apppool_schedules = ((new_resource.recycle_at_time && is_new_recycle_at_time) || !node_array.empty?) || (new_resource.recycle_schedule_clear && !node_array.empty?)

Looking at the 4.1.7 release notes - I am guessing this was changed due to this bug: #247

The bug suggests there needs to be a way to reset the recycle_at_time to default. From reading the original code above - it seems that could have been accomplished by providing the recycle_schedule_clear attribute with a value of true. If any schedule items existed it should have cleared them (and put the app pool back into the default / no schedule state).

In any case the current fix appears to have a side effect that's impacting idempotency.

[EasyAsABC123]

I'll look into this in around 9 hours, sounds like the check is broken.

Justin Schuhmann

On Jun 15, 2016, at 12:10 AM, jsco2t notifications@github.com wrote:

Cookbook version

4.1.7

Chef-client version

chef-client: 12.7.2
kitchen: 1.5.0

Platform Details

Windows Server 2012 R2

Issue:

After an app pool has been configured with iis_pool resource parameter recycle_at_time the next time the cookbook converges (with no changes to the app pool) the app pool is restarted.

Steps to Reproduce:

Configure a site's app pool using the iis_pool resource from the IIS Cookbook. Make sure that a custom recycle_at_time is provided.
Example:

iis_pool 'foo' do
runtime_version '4.0'
pool_identity :SpecificUser
pool_username 'some user'
pool_password 'some password'
idle_timeout '00:00:00'
recycle_at_time '01:00:00' # bug bug
recycle_after_time '00:00:00'
action [:add, :config]
end
Converge the cookbook. (I was using test kitchen to do this)

Converge the cookbook again.

Expected Result:

The second cookbook converge should be, effectively, a noop. It shouldn't adjust the app pool or cause the app pool to restart. The cook book (and more specifically the iis_pool resource) should be idempotent.

Actual Result:

Each time the cookbook converges the app pool is restarted. This can be observed in a few ways.

First the output from test kitchen reports the app pool is being configured:

iis_pool[foo] action config[2016-06-14T17:36:26-05:00] INFO: Processing iis_pool[foo] action config
[2016-06-14T17:36:26-05:00] INFO: iis_pool[foo] configured application pool

If you check the event log on the target node machine the Web Server IIS event log will report that the app pool was restarted (because of a configuration change).

Further investigation notes

I spent several hours scratching my head over this and reading the IIS cookbook code. After careful inspection I believe the bug is probably happening here (my best guess):

iis/providers/pool.rb: lines 238-239:

node_array = XPath.match(doc.root, 'APPPOOL/add/recycling/periodicRestart/schedule/add')
should_clear_apppool_schedules = ((new_resource.recycle_at_time && is_new_recycle_at_time) || !node_array.empty?) || (new_resource.recycle_schedule_clear && !node_array.empty?)
I believe the problematic OR check is this statement: (new_resource.recycle_at_time && is_new_recycle_at_time) || !node_array.empty?. If I'm reading that correctly, in the context of the above, it will result in should_clear_apppool_schedules == true if we had a recycle_at_time but that recycle_at_time was not a new time. Meaning the app_pool was already configured with a restart time - so the node_array was not empty. But the restart time was also not new.

When I run the kitchen converge with debug output - it seems to agree that this is happening. Here is roughly what I see:

[2016-06-14T22:55:00-05:00] DEBUG: iis_pool[foo] current_resource match output: APPPOOL "foo" (MgdVersion:v4.0,MgdMode:Integrated,state:Started)
[2016-06-14T22:55:00-05:00] DEBUG: C:\Windows\System32\inetsrv\appcmd.exe list app pool "foo" /config:* /xml
[2016-06-14T22:55:00-05:00] DEBUG: C:\Windows\System32\inetsrv\appcmd.exe set config /section:applicationPools "/-[name='foo'].recycling.periodicRestart.schedule"
[2016-06-14T22:55:00-05:00] DEBUG: C:\Windows\System32\inetsrv\appcmd.exe set config /section:applicationPools "/+[name='foo'].recycling.periodicRestart.schedule.[value='01:00:00']"
[2016-06-14T22:55:00-05:00] INFO: iis_pool[foo] configured application pool
On Feb 17th it appears the above code was updated: b5b95db

• should_clear_apppool_schedules = ((new_resource.recycle_at_time && is_new_recycle_at_time) || node_array.length > 1) || (new_resource.recycle_schedule_clear && node_array.length > 0)
• should_clear_apppool_schedules = ((new_resource.recycle_at_time && is_new_recycle_at_time) || !node_array.empty?) || (new_resource.recycle_schedule_clear && !node_array.empty?)
  Looking at the 4.1.7 release notes - I am guessing this was changed due to this bug: Can't set recycle_at_time to default #247

The bug suggests there needs to be a way to reset the recycle_at_time to default. From reading the original code above - it seems that could have been accomplished by providing the recycle_schedule_clear attribute with a value of true. If any schedule items existed it should have cleared them (and put the app pool back into the default / no schedule state).

In any case the current fix appears to have a side effect that's impacting idempotency.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.

[EasyAsABC123]

Status: Spinning up test environment

[EasyAsABC123]

@jsco2t please test #283 as it appears to solve this issue