Uploaded image for project: 'Puppet'
  1. Puppet
  2. PUP-6254

Windows Service start reports failures instead of success under some states

    XMLWordPrintable

Details

    Description

      During FM-5175, the WSUS_Client module failed acceptance tests intermittently due to a service start failure;

      16:23:14 Failures:
      		 
      16:23:14 
      16:23:14   1) wsus_client auto_update_option => notifyonly 
      16:23:14      Failure/Error: apply_manifest_on(default, pp, :catch_failures => true)
      		 
      16:23:14      Beaker::Host::CommandFailure:
      		 
      16:23:14        Host 't2jesxgwkw2uecz.delivery.puppetlabs.net' exited with 6 running:
      		 
      16:23:14         cmd.exe /c puppet apply --verbose --detailed-exitcodes C:/cygwin64/tmp/apply_manifest.pp.kuNup0
      		 
      16:23:14        Last 10 lines of output were:
      		 
      16:23:14        	Notice: /Stage[main]/Wsus_client/Registry_key[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU]/ensure: created
      		 
      16:23:14        	Notice: /Stage[main]/Wsus_client/Wsus_client::Setting[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]/Registry_value[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]/ensure: created
      		 
      16:23:14        	Info: /Stage[main]/Wsus_client/Wsus_client::Setting[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]/Registry_value[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]: Scheduling refresh of Service[wuauserv]
      		 
      16:23:14        	Notice: /Stage[main]/Wsus_client/Service[wuauserv]: Triggered 'refresh' from 1 events
      		 
      16:23:14        	Info: Class[Wsus_client]: Unscheduling all events on Class[Wsus_client]
      		 
      16:23:14        	Error: Cannot start wuauserv, error was: Execution of 'C:/Windows/system32/net.exe start wuauserv' returned 2: The service is starting or stopping.  Please try again later.
      		 
      16:23:14        	Wrapped exception:
      		 
      16:23:14        	Execution of 'C:/Windows/system32/net.exe start wuauserv' returned 2: The service is starting or stopping.  Please try again later.
      		 
      16:23:14        	Error: /Stage[main]/Wsus_client/Service[wuauserv]/ensure: change from stopped to running failed: Cannot start wuauserv, error was: Execution of 'C:/Windows/system32/net.exe start wuauserv' returned 2: The service is starting or stopping.  Please try again later.
      		 
      16:23:14        	Notice: Applied catalog in 4.96 seconds
      		 
      16:23:14        
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/host.rb:331:in `exec'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/host_helpers.rb:78:in `block in on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/shared/host_manager.rb:115:in `run_block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/patterns.rb:35:in `block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/host_helpers.rb:63:in `on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/puppet_helpers.rb:469:in `block in apply_manifest_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/shared/host_manager.rb:115:in `run_block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/patterns.rb:35:in `block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/puppet_helpers.rb:398:in `apply_manifest_on'
      		 
      16:23:14      # ./spec/acceptance/wsus_client_spec.rb:36:in `create_apply_manifest'
      		 
      16:23:14      # ./spec/acceptance/wsus_client_spec.rb:140:in `block (5 levels) in <top (required)>'
      		 
      16:23:14 
      16:23:14   2) wsus_client auto_update_option => 3 
      16:23:14      Failure/Error: apply_manifest_on(default, pp, :catch_failures => true)
      		 
      16:23:14      Beaker::Host::CommandFailure:
      		 
      16:23:14        Host 't2jesxgwkw2uecz.delivery.puppetlabs.net' exited with 6 running:
      		 
      16:23:14         cmd.exe /c puppet apply --verbose --detailed-exitcodes C:/cygwin64/tmp/apply_manifest.pp.p8MUsq
      		 
      16:23:14        Last 10 lines of output were:
      		 
      16:23:14        	Notice: /Stage[main]/Wsus_client/Registry_key[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU]/ensure: created
      		 
      16:23:14        	Notice: /Stage[main]/Wsus_client/Wsus_client::Setting[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]/Registry_value[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]/ensure: created
      		 
      16:23:14        	Info: /Stage[main]/Wsus_client/Wsus_client::Setting[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]/Registry_value[HKLM\Software\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions]: Scheduling refresh of Service[wuauserv]
      		 
      16:23:14        	Notice: /Stage[main]/Wsus_client/Service[wuauserv]: Triggered 'refresh' from 1 events
      		 
      16:23:14        	Info: Class[Wsus_client]: Unscheduling all events on Class[Wsus_client]
      		 
      16:23:14        	Error: Cannot start wuauserv, error was: Execution of 'C:/Windows/system32/net.exe start wuauserv' returned 2: The service is starting or stopping.  Please try again later.
      		 
      16:23:14        	Wrapped exception:
      		 
      16:23:14        	Execution of 'C:/Windows/system32/net.exe start wuauserv' returned 2: The service is starting or stopping.  Please try again later.
      		 
      16:23:14        	Error: /Stage[main]/Wsus_client/Service[wuauserv]/ensure: change from stopped to running failed: Cannot start wuauserv, error was: Execution of 'C:/Windows/system32/net.exe start wuauserv' returned 2: The service is starting or stopping.  Please try again later.
      		 
      16:23:14        	Notice: Applied catalog in 1.11 seconds
      		 
      16:23:14        
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/host.rb:331:in `exec'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/host_helpers.rb:78:in `block in on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/shared/host_manager.rb:115:in `run_block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/patterns.rb:35:in `block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/host_helpers.rb:63:in `on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/puppet_helpers.rb:469:in `block in apply_manifest_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/shared/host_manager.rb:115:in `run_block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/patterns.rb:35:in `block_on'
      		 
      16:23:14      # ./vendor/gems/gems/beaker-2.40.0/lib/beaker/dsl/helpers/puppet_helpers.rb:398:in `apply_manifest_on'
      		 
      16:23:14      # ./spec/acceptance/wsus_client_spec.rb:36:in `create_apply_manifest'
      		 
      16:23:14      # ./spec/acceptance/wsus_client_spec.rb:134:in `block (5 levels) in <top (required)>'
      		 
      16:23:14 
      16:23:14 Finished in 31 minutes 29 seconds (files took 16 minutes 36 seconds to load)
      		 
      16:23:14 163 examples, 2 failures

      This seems to come from the way puppet starts windows service. The status method converts the various windows service states into the puppet representation;
      https://github.com/puppetlabs/puppet/blob/master/lib/puppet/provider/service/windows.rb#L90-L95

      However during a start operation, the current status of the service is not queried before a start operation e.g. Issuing a Start to a service that is in the Start_pending state will error when using net.exe

      Also. Due to the way the SCM works, a puppet stop operation may still leave a service in a Stop_Pending state. So a subsequent, puppet start operation will fail as it will not wait for the Stop_pending to complete prior to issuing a start command.

      It appears that the start and stop operations require more state handling so as to not give false failures.

      Attachments

        Issue Links

          is blocked by

          Bug - A problem which impairs or prevents the functions of the product. PUP-5475 Windows Service provider should use something better than net.exe - perhaps direct FFI access

          • Major - Major loss of function.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MODULES-7696 Problem with wsus_client trying to restart the service but the service is already running

          • Low - Minor problems or easily worked around.
          • Open

          Bug - A problem which impairs or prevents the functions of the product. PUP-4993 systemd thinks 'activating' services are 'stopped'

          • Normal - Regular issue, some loss of functionality under specific circumstances.
          • Accepted

          Bug - A problem which impairs or prevents the functions of the product. PUP-5475 Windows Service provider should use something better than net.exe - perhaps direct FFI access

          • Major - Major loss of function.
          • Closed

          Improvement - An improvement or enhancement to an existing feature or task. PUP-8770 Puppet resource service status should be more than binary

          • Normal - Regular issue, some loss of functionality under specific circumstances.
          • Accepted

          Activity

            People

              Unassigned Unassigned
              glenn.sarti Glenn Sarti
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Zendesk Support