Mixlib::ShellOut - timeout #86

vlnrajesh · 2015-01-07T04:12:24Z

I am trying to use Mixlib::ShellOut to execute commands under ruby_block inside a chef recipe. In Some situations, we cannot complete the task in 600 seconds, and I would like extend further. I have added command in below way,

vsphere_output = Mixlib::ShellOut.new(_command, :timeout => 15000)

and I suspect it is not respecting timeout value. Please advise.

Xoph · 2015-02-05T22:11:56Z

I am having the same issue.

Some background:

I am using a 3rd party mixlibrary to create a new resource: https://github.com/ebsco/mixlibrary-core

We needed additional functionality that was not provided by powershell_script, such as returning stdout and stderr, and this mixlibrary also allowed us access to the exit code from PowerShell scripts. Here's the finding that started our working of using the mixlibrary: chef/chef#2348.

Here's the issue:

I have created a new LWRP for what we needed to accomplish using the 3rd part mixlibrary. You can see my provider and resource files below.

When I use this new LWRP with a timeout, I don't see the timeout being used. The timeout is important because we have a PowerShell script that installs SQL, and the SQL installation is running past the timeout.

Observations:

Sometimes SQL takes > 30 min to install. When it does, Chef throws a timeout error and the Chef run ends. But the process still runs in the background, until SQL finishes installing. Additionally, our PowerShell script also finishes running. So the 600 seconds timeout is not being used as well.

Environment:

Windows Server 2008 R2 and Windows Server 2012 R2
Chef-Client 11.16.4 and Chef-Client 12.0.3
Note: I haven't run the SQL installation that has a timeout on Chef-Client 12.0.3, but I tried to run another one of our PowerShell scripts that takes about a minute with a 10 second timeout and that didn't timeout. We are typically using 11.16.4, but could upgrade if there is a great reason to.
I don't know which version of the mixlib-shellout we are using, I'm new to Chef/Ruby and don't know how to get the information, but if you tell me how I'd be glad to get that info to you.

Thank you,
Christoph
GE Healthcare

Example of using our new resource

rst_common_powershellscriptex <name> do
    action :run
    cwd "<path>"
    code <<-EOH
        <PowerShell code>
    EOH
    returns [0,3]
    timeout 3600
end

providers\PowershellScriptEx.rb:

# Public: States that Chef WhyRun mode is supported by the LWRP
def whyrun_supported?
  true
end

# Public: Resource run action.  Executes the powershell and evaluates the result.
action :run do

    converge_by("Run #{ @new_resource }") do
        lazy_load_gems

        Chef::Log.info "Running this code: '#{ @current_resource.code }'"
        Chef::Log.info "  Working Directory: '#{ @current_resource.cwd }'"
        Dir.chdir(@current_resource.cwd)
        result = Mixlibrary::Core::Shell.windows_script_out(:powershell, @current_resource.code, {:timeout => @current_resource.timeout})
        @current_resource.exitcode = result.exitstatus

        if (0 == result.exitstatus)
            Chef::Log.warn format_script_output("#{ @new_resource } succeeded.", result.stdout) 
        elsif (@current_resource.returns.include? result.exitstatus) 
            Chef::Log.warn format_script_output("#{ @new_resource } generated a warning.", result.stdout) 
        else
            Chef::Log.error format_script_output("#{ @new_resource } failed with exit code #{ result.exitstatus }.", result.stdout) 
            raise "#{ @new_resource } failed with exit code #{ result.exitstatus }."
        end
    end
end

#Public: implements the load_current_resource method for this LWRP
def load_current_resource
    @current_resource = Chef::Resource::RstCommonPowershellscriptex.new(new_resource.name)
    @current_resource.name(new_resource.name)
    encapsulatedcode = <<-EOH
        #{new_resource.code}
    EOH
    @current_resource.code(encapsulatedcode)
    if new_resource.cwd.empty?
        @current_resource.cwd(Dir.pwd)
    else
        @current_resource.cwd(new_resource.cwd)
    end
    @current_resource.returns(new_resource.returns)
    @current_resource.exitcode = -99999
end

# Private: Loads the MixLibrary-Core component into memory. 
#          This is being done from a method to ensure that the gem is installed
#          before it is loaded into memory
def lazy_load_gems
    require 'mixlibrary/core/apps/shell'
end

# Private: Creates a message block that can easilly be seen in 
#          the Chef output stream and also makes it so we can
#          parse out the script results using a regular experession
def format_script_output(messageLine1, messageLine2)
    retval = <<-EOH

***********************************************************
************ Script Output Begin ***************
***********************************************************
#{ messageLine1 }
#{ messageLine2 }
***********************************************************
************* Script Output End ****************
***********************************************************
EOH
end

resources\PowershellScriptEx.rb:

actions :run
default_action :run 

attribute :name, :name_attribute => true
attribute :code, :kind_of => String, :default => ""
attribute :returns, :kind_of => Array, :default => []
attribute :cwd, :kind_of => String, :default => ""
attribute :timeout, :kind_of => Integer, :default => 900

attr_accessor :exitcode

jaym · 2015-02-05T22:30:15Z

I think the stack trace you get after a timeout would be really helpful

Xoph · 2015-02-05T22:43:08Z

I no longer have the Chef output, let me run it again and get you the stack trace.

Xoph · 2015-02-06T15:44:56Z

Relevant output:

    - Run rst-common_PowershellScriptEx[DakotaWebSiteCreation]
Recipe: rst-powershell-automation::UView_MSSQLServer_InstallAutomation
  * rst-common_PowershellScriptEx[UView_MSSQLServer_InstallAutomation] action run

    ================================================================================
    Error executing action `run` on resource 'rst-common_PowershellScriptEx[UView_MSSQLServer_InstallAutomation]'
    ================================================================================

    Mixlib::ShellOut::CommandTimeout
    --------------------------------
    command timed out:
    ---- Begin output of powershell.exe -NoLogo -NonInteractive -NoProfile -ExecutionPolicy RemoteSigned -InputFormat No
ne -File C:/Users/212327~1/AppData/Local/Temp/tempPSchef20150205-2960-89nkyx.ps1 ----
    STDOUT: INSTALLING MS SQL SERVER FOR UNIVERSAL VIEWER
    MS SQL Server installation is continuing without an explicit license key, assuming that it is embedded in the SQL in
stall package.
    Installing MS SQL Server using this information:
        MS SQL Server Install Package: C:\Data\Installs\SQL\Setup.exe
        MS SQL Server License Key: <<EMBEDDED LICENSE>>
        MS SQL Server Answer File Path: C:\Support\RadiologyServiceTools\Infrastructure\SQL_Server_2012_Installation.ini

    STDERR:
    ---- End output of powershell.exe -NoLogo -NonInteractive -NoProfile -ExecutionPolicy RemoteSigned -InputFormat None
 -File C:/Users/212327~1/AppData/Local/Temp/tempPSchef20150205-2960-89nkyx.ps1 ----

    Resource Declaration:
    ---------------------
    # In C:/Users/212327698/.chef/local-mode-cache/cache/cookbooks/rst-powershell-automation/recipes/UView_MSSQLServer_I
nstallAutomation.rb

     23: rst_common_powershellscriptex scriptName do
     24:        action :run
     25:        cwd "#{commonParameters['rst_package_path']}#{commonParameters['rst_package_path_uview']}"
     26:        code ".\\#{scriptName}.ps1 -silent#{scriptParameterString}"
     27: end

    Compiled Resource:
    ------------------
    # Declared in C:/Users/212327698/.chef/local-mode-cache/cache/cookbooks/rst-powershell-automation/recipes/UView_MSSQ
LServer_InstallAutomation.rb:23:in `from_file'

    rst_common_powershellscriptex("UView_MSSQLServer_InstallAutomation") do
      action [:run]
      retries 0
      retry_delay 2
      guard_interpreter :default
      cookbook_name "rst-powershell-automation"
      recipe_name "UView_MSSQLServer_InstallAutomation"
      cwd "C:\\Support\\RadiologyServiceTools\\UView"
      code ".\\UView_MSSQLServer_InstallAutomation.ps1 -silent -mssqlInstallPackageFolder \"C:\\Data\\Installs\\SQL\""
    end


Running handlers:
[2015-02-05T19:34:22-06:00] ERROR: Running exception handlers
Running handlers complete
[2015-02-05T19:34:22-06:00] ERROR: Exception handlers complete
[2015-02-05T19:34:22-06:00] FATAL: Stacktrace dumped to C:/Users/212327698/.chef/local-mode-cache/cache/chef-stacktrace.
out
Chef Client failed. 8 resources updated in 5061.965958 seconds
[2015-02-05T19:34:22-06:00] FATAL: Mixlib::ShellOut::CommandTimeout: rst-common_PowershellScriptEx[UView_MSSQLServer_Ins
tallAutomation] (rst-powershell-automation::UView_MSSQLServer_InstallAutomation line 23) had an error: Mixlib::ShellOut:
:CommandTimeout: command timed out:
---- Begin output of powershell.exe -NoLogo -NonInteractive -NoProfile -ExecutionPolicy RemoteSigned -InputFormat None -
File C:/Users/212327~1/AppData/Local/Temp/tempPSchef20150205-2960-89nkyx.ps1 ----
STDOUT: INSTALLING MS SQL SERVER FOR UNIVERSAL VIEWER
MS SQL Server installation is continuing without an explicit license key, assuming that it is embedded in the SQL instal
l package.
Installing MS SQL Server using this information:
        MS SQL Server Install Package: C:\Data\Installs\SQL\Setup.exe
        MS SQL Server License Key: <<EMBEDDED LICENSE>>
        MS SQL Server Answer File Path: C:\Support\RadiologyServiceTools\Infrastructure\SQL_Server_2012_Installation.ini

STDERR:
---- End output of powershell.exe -NoLogo -NonInteractive -NoProfile -ExecutionPolicy RemoteSigned -InputFormat None -Fi
le C:/Users/212327~1/AppData/Local/Temp/tempPSchef20150205-2960-89nkyx.ps1 ----

Xoph · 2015-02-06T15:45:51Z

I also posted to the mixlibrary github we are using: ebsco/mixlibrary-core#7

jaym · 2015-02-06T15:54:19Z

Stack trace is in C:/Users/212327698/.chef/local-mode-cache/cache/chef-stacktrace.out

Xoph · 2015-02-06T15:56:57Z

Here's the actually stack trace (sorry still learning to read chef output):

Generated at 2015-02-05 19:34:22 -0600
Mixlib::ShellOut::CommandTimeout: rst-common_PowershellScriptEx[UView_MSSQLServer_InstallAutomation] (rst-powershell-automation::UView_MSSQLServer_InstallAutomation line 23) had an error: Mixlib::ShellOut::CommandTimeout: command timed out:
---- Begin output of powershell.exe -NoLogo -NonInteractive -NoProfile -ExecutionPolicy RemoteSigned -InputFormat None -File C:/Users/212327~1/AppData/Local/Temp/tempPSchef20150205-2960-89nkyx.ps1 ----
STDOUT: INSTALLING MS SQL SERVER FOR UNIVERSAL VIEWER
MS SQL Server installation is continuing without an explicit license key, assuming that it is embedded in the SQL install package.
Installing MS SQL Server using this information:

    MS SQL Server Install Package: C:\Data\Installs\SQL\Setup.exe

    MS SQL Server License Key: <<EMBEDDED LICENSE>>

    MS SQL Server Answer File Path: C:\Support\RadiologyServiceTools\Infrastructure\SQL_Server_2012_Installation.ini
STDERR: 
---- End output of powershell.exe -NoLogo -NonInteractive -NoProfile -ExecutionPolicy RemoteSigned -InputFormat None -File C:/Users/212327~1/AppData/Local/Temp/tempPSchef20150205-2960-89nkyx.ps1 ----

C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlib-shellout-1.6.0-x86-mingw32/lib/mixlib/shellout/windows.rb:114:in `run_command'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlib-shellout-1.6.0-x86-mingw32/lib/mixlib/shellout.rb:242:in `run_command'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/mixin/shell_out.rb:37:in `shell_out'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/shell_call.rb:14:in `shell'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/scripts/shelloutwrapper.rb:93:in `shellout'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/scripts/shelloutwrapper.rb:49:in `run_command'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/scripts/base.rb:24:in `run_command'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/scripts/windows_script.rb:41:in `run_command'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/scripts/powershell.rb:38:in `orchestrate'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/app.rb:47:in `run_windows_script'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/mixlibrary-core-0.0.9/lib/mixlibrary/core/shell/app.rb:21:in `windows_script_out'
C:/Users/212327698/.chef/local-mode-cache/cache/cookbooks/rst-common/providers/PowershellScriptEx.rb:38:in `block (2 levels) in class_from_file'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/mixin/why_run.rb:52:in `call'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/mixin/why_run.rb:52:in `add_action'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/provider.rb:156:in `converge_by'
C:/Users/212327698/.chef/local-mode-cache/cache/cookbooks/rst-common/providers/PowershellScriptEx.rb:32:in `block in class_from_file'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/provider/lwrp_base.rb:138:in `instance_eval'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/provider/lwrp_base.rb:138:in `block in action'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/provider.rb:121:in `run_action'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource.rb:648:in `run_action'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/runner.rb:49:in `run_action'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/runner.rb:81:in `block (2 levels) in converge'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/runner.rb:81:in `each'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/runner.rb:81:in `block in converge'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection.rb:98:in `block in execute_each_resource'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection/stepable_iterator.rb:116:in `call'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection/stepable_iterator.rb:116:in `call_iterator_block'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection/stepable_iterator.rb:85:in `step'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection/stepable_iterator.rb:104:in `iterate'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection/stepable_iterator.rb:55:in `each_with_index'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/resource_collection.rb:96:in `execute_each_resource'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/runner.rb:80:in `converge'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/client.rb:345:in `converge'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/client.rb:431:in `do_run'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/client.rb:227:in `run'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/application.rb:236:in `run_chef_client'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/application/client.rb:338:in `block in run_application'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/application/client.rb:327:in `loop'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/application/client.rb:327:in `run_application'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/lib/chef/application.rb:55:in `run'
C:/opscode/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.16.4-x86-mingw32/bin/chef-client:26:in `<top (required)>'
C:/opscode/chef/bin/chef-client:23:in `load'
C:/opscode/chef/bin/chef-client:23:in `<main>'

jaym · 2015-02-06T16:38:09Z

Observations:

Sometimes SQL takes > 30 min to install. When it does, Chef throws a timeout error and the Chef run ends. But the process still runs in the background, until SQL finishes installing. Additionally, our PowerShell script also finishes running. So the 600 seconds timeout is not being used as well.

Your first observation will be fixed in the next release of Chef 12. See #79

It's not clear why the timeout is falling back to the default. Perhaps a bug in the library you are using?

Xoph · 2015-02-06T17:07:44Z

I found out the issue from my post on their library git. Wasn't specifying the LWRP correctly.

Looking forward to that next release of Chef 12.

Thank you.

btm · 2015-05-13T20:42:59Z

@Xoph it sounds like you're all set, so I'm going to close this issue. Let us know if you're still having problems.

btm closed this as completed May 13, 2015

chef locked and limited conversation to collaborators Nov 16, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Mixlib::ShellOut - timeout #86

Mixlib::ShellOut - timeout #86

vlnrajesh commented Jan 7, 2015

Xoph commented Feb 5, 2015

jaym commented Feb 5, 2015

Xoph commented Feb 5, 2015

Xoph commented Feb 6, 2015

Xoph commented Feb 6, 2015

jaym commented Feb 6, 2015

Xoph commented Feb 6, 2015

jaym commented Feb 6, 2015

Xoph commented Feb 6, 2015

btm commented May 13, 2015

Mixlib::ShellOut - timeout #86

Mixlib::ShellOut - timeout #86

Comments

vlnrajesh commented Jan 7, 2015

Xoph commented Feb 5, 2015

jaym commented Feb 5, 2015

Xoph commented Feb 5, 2015

Xoph commented Feb 6, 2015

Xoph commented Feb 6, 2015

jaym commented Feb 6, 2015

Xoph commented Feb 6, 2015

jaym commented Feb 6, 2015

Xoph commented Feb 6, 2015

btm commented May 13, 2015