chef-boneyard / windows

Development repository for Chef Cookbook windows
https://supermarket.chef.io/cookbooks/windows
Apache License 2.0
252 stars 270 forks source link

Cookbook v2.1.1 constantly re-installs windows feature #475

Closed Tech356 closed 6 years ago

Tech356 commented 7 years ago

Cookbook version

2.1.1

Chef-client version

12.19.36

Platform Details

Windows 7 x64

The same code worked in v2.0.2. The bug seems to have been introduced in https://github.com/chef-cookbooks/windows/pull/402 but I cannot find the specific bug. It seems that the dism_features is not loading initially (but still creating an empty Mash) which causes the first windows_feature resource to re-install. Then on the ohai reload it is loading all the features. I have not been able to find what is causing this behavior.

Scenario:

Here is the recipe

windows_feature 'Remote Server Administration Tools' do
  action :install
  feature_name 'RemoteServerAdministrationTools'
  notifies :request_reboot, 'reboot[reboot_for_feature]', :immediately
end

Here is the log

...
[2017-06-01T00:09:15-04:00] INFO: Processing ohai_plugin[dism_features] action create (windows::default line 40)
[2017-06-01T00:09:15-04:00] INFO: Processing directory[C:/chef/ohai/plugins] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 80)
[2017-06-01T00:09:15-04:00] INFO: Processing cookbook_file[C:/chef/ohai/plugins/dism_features.rb] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 87)
[2017-06-01T00:09:15-04:00] INFO: Processing ohai[dism_features] action nothing (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 110)
...
[2017-06-01T00:09:18-04:00] INFO: Processing ohai_plugin[dism_features] action create (windows::default line 40)
[2017-06-01T00:09:18-04:00] INFO: Processing directory[C:/chef/ohai/plugins] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 80)
[2017-06-01T00:09:18-04:00] INFO: Processing cookbook_file[C:/chef/ohai/plugins/dism_features.rb] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 87)
[2017-06-01T00:09:18-04:00] INFO: Processing ohai[dism_features] action nothing (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 110)
...
[2017-06-01T00:10:36-04:00] INFO: Processing windows_feature[Remote Server Administration Tools] action install (mycookbook::myrecipe line 121)
[2017-06-01T00:11:05-04:00] INFO: windows_feature[Remote Server Administration Tools] installed feature
[2017-06-01T00:11:05-04:00] INFO: windows_feature[Remote Server Administration Tools] sending request_reboot action to reboot[reboot_for_feature] (immediate)
[2017-06-01T00:11:05-04:00] INFO: Processing reboot[reboot_for_feature] action request_reboot (mycookbook::myrecipe line 10)
[2017-06-01T00:11:05-04:00] WARN: Reboot requested:'reboot_for_feature'
[2017-06-01T00:11:05-04:00] INFO: Changing reboot status from {} to {:delay_mins=>1, :reason=>"reboot relating to joining the domain", :timestamp=>2017-06-01 00:11:05 -0400, :requested_by=>"reboot_for_feature"}
[2017-06-01T00:11:05-04:00] INFO: Processing ohai[Reloading Dism_Features Plugin - Action [:install] of feature RemoteServerAdministrationTools] action reload (C:/chef/cache/cookbooks/windows/providers/feature_dism.rb line 70)
[2017-06-01T00:11:23-04:00] INFO: ohai[Reloading Dism_Features Plugin - Action [:install] of feature RemoteServerAdministrationTools] reloaded
...

To troubleshoot this problem I added additional logging to the installed? function

def installed?
  @installed ||= begin
    install_ohai_plugin unless node['dism_features']

    # Compare against ohai plugin instead of costly dism run
    Chef::Log.info("dism installed? has key for #{@new_resource.feature_name}: #{node['dism_features'].key?(@new_resource.feature_name)}")
    if node['dism_features'].key?(@new_resource.feature_name)
      Chef::Log.info("dism installed? value of key #{@new_resource.feature_name}: #{node['dism_features'][@new_resource.feature_name]}")
      Chef::Log.info("dism installed? value of key #{@new_resource.feature_name} is enabled #{node['dism_features'][@new_resource.feature_name] =~ /Enable/}")
    else
      Chef::Log.info("dism installed? has no key for #{@new_resource.feature_name}")
      Chef::Log.info("dism installed? keys = #{node['dism_features'].keys}")
    end
    node['dism_features'].key?(@new_resource.feature_name) && node['dism_features'][@new_resource.feature_name] =~ /Enable/
  end
end

After adding the additional logging, the log looks like this

...
[2017-06-01T17:06:10-04:00] INFO: Processing ohai_plugin[dism_features] action create (windows::default line 40)
[2017-06-01T17:06:10-04:00] INFO: Processing directory[C:/chef/ohai/plugins] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 80)
[2017-06-01T17:06:10-04:00] INFO: Processing cookbook_file[C:/chef/ohai/plugins/dism_features.rb] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 87)
[2017-06-01T17:06:10-04:00] INFO: Processing ohai[dism_features] action nothing (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 110)
...
[2017-06-01T17:06:12-04:00] INFO: Processing ohai_plugin[dism_features] action create (windows::default line 40)
[2017-06-01T17:06:12-04:00] INFO: Processing directory[C:/chef/ohai/plugins] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 80)
[2017-06-01T17:06:12-04:00] INFO: Processing cookbook_file[C:/chef/ohai/plugins/dism_features.rb] action create (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 87)
[2017-06-01T17:06:12-04:00] INFO: Processing ohai[dism_features] action nothing (C:/chef/cache/cookbooks/ohai/resources/plugin.rb line 110)
...
[2017-06-01T17:06:50-04:00] INFO: Processing windows_feature[Remote Server Administration Tools] action install (mycookbook::myrecipe line 121)
[2017-06-01T17:06:50-04:00] INFO: dism installed? has key for RemoteServerAdministrationTools: false
[2017-06-01T17:06:50-04:00] INFO: dism installed? has no key for RemoteServerAdministrationTools
[2017-06-01T17:06:50-04:00] INFO: dism installed? keys = []
[2017-06-01T17:06:57-04:00] INFO: windows_feature[Remote Server Administration Tools] installed feature
[2017-06-01T17:06:57-04:00] INFO: windows_feature[Remote Server Administration Tools] sending request_reboot action to reboot[reboot_for_feature] (immediate)
[2017-06-01T17:06:57-04:00] INFO: Processing reboot[reboot_for_feature] action request_reboot (mycookbook::myrecipe line 10)
[2017-06-01T17:06:57-04:00] WARN: Reboot requested:'reboot_for_feature'
[2017-06-01T17:06:57-04:00] INFO: Changing reboot status from {} to {:delay_mins=>1, :reason=>"reboot relating to joining the domain", :timestamp=>2017-06-01 17:06:57 -0400, :requested_by=>"reboot_for_feature"}
[2017-06-01T17:06:57-04:00] INFO: Processing ohai[Reloading Dism_Features Plugin - Action [:install] of feature RemoteServerAdministrationTools] action reload (C:/chef/cache/cookbooks/windows/providers/feature_dism.rb line 78)
[2017-06-01T17:06:59-04:00] INFO: ohai[Reloading Dism_Features Plugin - Action [:install] of feature RemoteServerAdministrationTools] reloaded
...

For each subsequent windows_feature, the resource correctly identifies the feature as already installed.

...
[2017-06-01T17:06:59-04:00] INFO: Processing windows_feature[Role Administration Tools] action install (mycookbook::myrecipe line 121)
[2017-06-01T17:06:59-04:00] INFO: dism installed? has key for RemoteServerAdministrationTools-Roles: true
[2017-06-01T17:06:59-04:00] INFO: dism installed? value of key RemoteServerAdministrationTools-Roles: Enabled
[2017-06-01T17:06:59-04:00] INFO: dism installed? value of key RemoteServerAdministrationTools-Roles is enabled 0
...
[2017-06-01T17:06:59-04:00] INFO: Processing windows_feature[Storage Replica Administrative Tools] action remove (mycookbook::myrecipe line 121)
[2017-06-01T17:06:59-04:00] INFO: dism installed? has key for RemoteServerAdministrationTools-Roles-FileServices-SR: false
[2017-06-01T17:06:59-04:00] INFO: dism installed? has no key for RemoteServerAdministrationTools-Roles-FileServices-SR
[2017-06-01T17:06:59-04:00] INFO: dism installed? keys = ["OEMHelpCustomization", "CorporationHelpCustomization", "SimpleTCP", "SNMP", "WMISnmpProvider", "TelnetServer", "TelnetClient", "WindowsGadgetPlatform", "InboxGames", "More Games", "Solitaire", "SpiderSolitaire", "Hearts", "FreeCell", "Minesweeper", "PurblePlace", "Chess", "Shanghai", "Internet Games", "Internet Checkers", "Internet Backgammon", "Internet Spades", "IIS-WebServerRole", "IIS-WebServer", "IIS-CommonHttpFeatures", "IIS-HttpErrors", "IIS-HttpRedirect", "IIS-ApplicationDevelopment", "IIS-Security", "IIS-URLAuthorization", "IIS-RequestFiltering", "IIS-NetFxExtensibility", "IIS-HealthAndDiagnostics", "IIS-HttpLogging", "IIS-LoggingLibraries", "IIS-RequestMonitor", "IIS-HttpTracing", "IIS-IPSecurity", "IIS-Performance", "IIS-HttpCompressionDynamic", "IIS-WebServerManagementTools", "IIS-ManagementScriptingTools", "IIS-IIS6ManagementCompatibility", "IIS-Metabase", "WAS-WindowsActivationService", "WAS-ProcessModel", "WAS-NetFxEnvironment", "WAS-ConfigurationAPI", "IIS-HostableWebCore", "IIS-ISAPIExtensions", "IIS-ISAPIFilter", "IIS-StaticContent", "IIS-DefaultDocument", "IIS-DirectoryBrowsing", "IIS-WebDAV", "IIS-ASPNET", "IIS-ASP", "IIS-CGI", "IIS-ServerSideIncludes", "IIS-CustomLogging", "IIS-BasicAuthentication", "IIS-HttpCompressionStatic", "IIS-ManagementConsole", "IIS-ManagementService", "IIS-WMICompatibility", "IIS-LegacyScripts", "IIS-LegacySnapIn", "IIS-FTPServer", "IIS-FTPSvc", "IIS-FTPExtensibility", "IIS-WindowsAuthentication", "IIS-DigestAuthentication", "IIS-ClientCertificateMappingAuthentication", "IIS-IISCertificateMappingAuthentication", "IIS-ODBCLogging", "MediaPlayback", "WindowsMediaPlayer", "MediaCenter", "OpticalMediaDisc", "NetFx3", "WCF-HTTP-Activation", "WCF-NonHTTP-Activation", "RasRip", "MSMQ-Container", "MSMQ-Server", "MSMQ-Triggers", "MSMQ-ADIntegration", "MSMQ-HTTP", "MSMQ-Multicast", "MSMQ-DCOMProxy", "TabletPCOC", "ServicesForNFS-ClientOnly", "ClientForNFS-Infrastructure", "NFS-Administration", "SUA", "Printing-Foundation-Features", "Printing-Foundation-LPRPortMonitor", "Printing-Foundation-LPDPrintService", "Printing-Foundation-InternetPrinting-Client", "FaxServicesClientPackage", "ScanManagementConsole", "TFTP", "MSRDC-Infrastructure", "Printing-XPSServices-Features", "Indexing-Service-Package", "Internet-Explorer-Optional-amd64", "Xps-Foundation-Xps-Viewer", "TIFFIFilter", "SearchEngine-Client-Package", "RemoteServerAdministrationTools", "RemoteServerAdministrationTools-ServerManager", "RemoteServerAdministrationTools-Roles", "RemoteServerAdministrationTools-Roles-CertificateServices", "RemoteServerAdministrationTools-Roles-CertificateServices-CA", "RemoteServerAdministrationTools-Roles-CertificateServices-OnlineResponder", "RemoteServerAdministrationTools-Roles-AD", "RemoteServerAdministrationTools-Roles-AD-DS", "RemoteServerAdministrationTools-Roles-AD-DS-SnapIns", "RemoteServerAdministrationTools-Roles-AD-DS-AdministrativeCenter", "RemoteServerAdministrationTools-Roles-AD-DS-NIS", "RemoteServerAdministrationTools-Roles-AD-LDS", "RemoteServerAdministrationTools-Roles-AD-Powershell", "RemoteServerAdministrationTools-Roles-DHCP", "RemoteServerAdministrationTools-Roles-DNS", "RemoteServerAdministrationTools-Roles-FileServices", "RemoteServerAdministrationTools-Roles-FileServices-Dfs", "RemoteServerAdministrationTools-Roles-FileServices-Fsrm", "RemoteServerAdministrationTools-Roles-FileServices-StorageMgmt", "RemoteServerAdministrationTools-Roles-HyperV", "RemoteServerAdministrationTools-Roles-RDS", "RemoteServerAdministrationTools-Features", "RemoteServerAdministrationTools-Features-BitLocker", "RemoteServerAdministrationTools-Features-Clustering", "RemoteServerAdministrationTools-Features-GP", "RemoteServerAdministrationTools-Features-LoadBalancing", "RemoteServerAdministrationTools-Features-SmtpServer", "RemoteServerAdministrationTools-Features-StorageExplorer", "RemoteServerAdministrationTools-Features-StorageManager", "RemoteServerAdministrationTools-Features-Wsrm"]
...

When I run the ohai command manually it returns no results

C:\Users\user>ohai -d "c:/Chef/ohai/plugins" dism_features
{

}

The plugin path is included in the client.rb config

...
ohai.plugin_path << 'c:/chef/ohai/plugins'
...
Tech356 commented 7 years ago

Running Ohai with log level set to debug shows that the dism command is timing out.

C:\Users\user>ohai -l debug -d c:/chef/ohai/plugins dism_features
...
DEBUG: Loading plugin at c:/Chef/ohai/plugins/dism_features.rb
DEBUG: Plugin DismFeatures: ran 'C:\Windows\sysnative\dism.exe /Get-Features /Online /Format:Table' and timed out after 30 seconds
DEBUG: Plugin DismFeatures threw #<Ohai::Exceptions::Exec: command timed out:
---- Begin output of C:\Windows\sysnative\dism.exe /Get-Features /Online /Format:Table ----
STDOUT: Deployment Image Servicing and Management tool
Version: 6.1.7600.16385

Image Version: 6.1.7600.16385
STDERR:
---- End output of C:\Windows\sysnative\dism.exe /Get-Features /Online /Format:Table ----

ProcessId: 5056
app_name: C:\Windows\sysnative\dism.exe
command_line: C:\Windows\sysnative\dism.exe /Get-Features /Online /Format:Tabletimeout: 30>
...

Subsequent runs of dism return within the timeout.

C:\Users\user>ohai -l debug -d c:/chef/ohai/plugins dism_features
...
DEBUG: Loading plugin at c:/Chef/ohai/plugins/dism_features.rb
DEBUG: Plugin DismFeatures: ran 'C:\Windows\sysnative\dism.exe /Get-Features /Online /Format:Table' and returned 0
{
  "OEMHelpCustomization": "Disabled",
  "CorporationHelpCustomization": "Disabled",
  "SimpleTCP": "Disabled",
  ...
}

After every reboot, dism would timeout the first time. Timing the runs using a stopwatch gave 57.69 seconds for the first invocation and 16.91 seconds for the second invocation.

PR #402 removed the WMI query that was used on Win7+ machines. Adding it back into the plugin would presumably fix this issue.

# Win32_OptionalFeature wmi class is only available in Win7+ (NT >= 6.1), but is way faster than dism.exe
if win_version.major_version > 6 || (win_version.major_version == 6 && win_version.minor_version >= 1)
  !execute_wmi_query("SELECT * FROM Win32_OptionalFeature WHERE Name='#{@new_resource.feature_name}' AND InstallState=1").nil?
else
  cmd = shell_out("#{dism} /online /Get-Features", returns: [0, 42, 127])
  cmd.stderr.empty? && (cmd.stdout =~ /^Feature Name : #{@new_resource.feature_name}.?$\n^State : Enabled.?$/i)
end
jugatsu commented 7 years ago

Can you reproduce this issue on windows cookbook version 3?

Tech356 commented 7 years ago

I have not deployed version 3 yet. The code doesn't look to change between versions so I would expect similar results.

tas50 commented 6 years ago

There was just a PR merged that should fix the idempotency of the feature

Tech356 commented 6 years ago

For reference, the PR that was merged is #495 and was released in 3.2.0.