Unable to replace python cookbook with poise-python

[jamiebuxxx]

We are trying to replace the depreciated python cookbook with the poise-python cookbook in our Chef 12 environment. When running chef-client(version 12.3.0) on a system that previously had the python cookbook on it, we receive the following error message:

Recipe: poise-python::default
  * python_runtime[2] action install

    ================================================================================
    Error executing action `install` on resource 'python_runtime[2]'
    ================================================================================

    Poise::Error
    ------------
    Unable to find cookbook for file "/var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/base.rb"

    Cookbook Trace:
    ---------------
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/utils.rb:64:in `find_cookbook_name'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/defined_in.rb:69:in `poise_defined_in_cookbook'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:233:in `default_inversion_attributes'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:252:in `resolve_inversion_attribute'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:268:in `block in inversion_options'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:267:in `tap'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:267:in `inversion_options'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:307:in `resolve_inversion_provider'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:350:in `provides?'

    Resource Declaration:
    ---------------------
    # In /var/chef/cache/cookbooks/poise-python/recipes/default.rb

     20: python_runtime '2' if node['poise-python']['install_python2']

    Compiled Resource:
    ------------------
    # Declared in /var/chef/cache/cookbooks/poise-python/recipes/default.rb:20:in `from_file'

    python_runtime("2") do
      action [:install]
      retries 0
      retry_delay 2
      default_guard_interpreter :default
      subresources [python_package[pymssql], python_package[pexpect]]
      declared_type :python_runtime
      cookbook_name "poise-python"
      recipe_name "default"
    end

However, we can see that cookbook files do exist:

$:~# ls -la /var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/
total 28
drwxr-xr-x 2 root root 4096 Oct  2 16:58 .
drwxr-xr-x 5 root root 4096 Oct  2 16:58 ..
-rw------- 1 root root 5819 Oct  2 16:58 base.rb
-rw------- 1 root root 2646 Oct  2 16:58 portable_pypy.rb
-rw------- 1 root root 3029 Oct  2 16:58 scl.rb
-rw------- 1 root root 2647 Oct  2 16:58 system.rb

There are no issues running the poise-python cookbook on brand new nodes or nodes that have never ran the python cookbook before.

[coderanger]

What version of the Poise cookbook are you using? If it is the latest, we can walk through turn on the omgtoomuchoutput debug level for that particular bit of code which should hopefully make it easy to track down.

[jamiebuxxx]

We are using version 1.0.0 that is listed on the Chef supermarket in our Berkshelf file. Just let me know if there is a later version available and how to turn on the verbose debug level.

[coderanger]

1.0.0 of Poise or of Poise-Python? This should depend on at least Poise 2.0.

[jamiebuxxx]

1.0.0 of poise-python. From our Berksfile it appears that the poise version is 2.4.0.

poise (2.4.0) poise-languages (1.1.0) poise-python (1.0.0)

[coderanger]

Okay, that makes more sense :) So to get the full trace you'll want to first set Chef to log_level debug, and then either set $POISE_DEBUG in the environment or as a node attribute. The easiest way to do this would be env POISE_DEBUG=1 chef-client -l debug. That should display the full list of files it sees as part of each cookbook while scanning.

[jamiebuxxx]

Using the env POISE_DEBUG=1 chef-client -l debug command gives me the following, which looks simular to the original error message.

Recipe: poise-python::default
  * python_runtime[2] action install

    ================================================================================
    Error executing action `install` on resource 'python_runtime[2]'
    ================================================================================

    Poise::Error
    ------------
    Unable to find cookbook for file "/var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/base.rb"

    Cookbook Trace:
    ---------------
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/utils.rb:64:in `find_cookbook_name'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/defined_in.rb:69:in `poise_defined_in_cookbook'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:237:in `default_inversion_attributes'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:256:in `resolve_inversion_attribute'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:272:in `block in inversion_options'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:271:in `tap'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:271:in `inversion_options'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:311:in `resolve_inversion_provider'
    /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:354:in `provides?'

    Resource Declaration:
    ---------------------
    # In /var/chef/cache/cookbooks/poise-python/recipes/default.rb

     20: python_runtime '2' if node['poise-python']['install_python2']

    Compiled Resource:
    ------------------
    # Declared in /var/chef/cache/cookbooks/poise-python/recipes/default.rb:20:in `from_file'

    python_runtime("2") do
      action [:install]
      retries 0
      retry_delay 2
      default_guard_interpreter :default
      subresources [python_package[pymssql], python_package[pexpect]]
      declared_type :python_runtime
      cookbook_name "poise-python"
      recipe_name "default"
    end

I know the debug level is set because the chef-client is giving me a lot of extra output. And the environment variable is set as well.

$:~# export POISE_DEBUG=1
$:~# echo $POISE_DEBUG
1

[coderanger]

Are you overriding the log level elsewhere? That should be showing way more log output just from -l debug.

[jamiebuxxx]

Ah, yes. We recently added a Chef handler for reporting failed chef runs. I just checked my email and received the following contents:

Poise::Error: python_runtime[2] (poise-python::default line 20) had an error: Poise::Error: Unable to find cookbook for file "/var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/base.rb"

/var/chef/cache/cookbooks/poise/files/halite_gem/poise/utils.rb:64:in `find_cookbook_name'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/defined_in.rb:69:in `poise_defined_in_cookbook'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:237:in `default_inversion_attributes'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:256:in `resolve_inversion_attribute'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:272:in `block in inversion_options'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:271:in `tap'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:271:in `inversion_options'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:311:in `resolve_inversion_provider'
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:354:in `provides?'
/opt/chef/embedded/apps/chef/lib/chef/provider_resolver.rb:52:in `block in enabled_handlers'
/opt/chef/embedded/apps/chef/lib/chef/provider_resolver.rb:49:in `select'
/opt/chef/embedded/apps/chef/lib/chef/provider_resolver.rb:49:in `enabled_handlers'
/opt/chef/embedded/apps/chef/lib/chef/provider_resolver.rb:75:in `maybe_dynamic_provider_resolution'
/opt/chef/embedded/apps/chef/lib/chef/provider_resolver.rb:42:in `resolve'
/opt/chef/embedded/apps/chef/lib/chef/resource.rb:1020:in `provider_for_action'
/opt/chef/embedded/apps/chef/lib/chef/resource.rb:562:in `run_action'
/opt/chef/embedded/apps/chef/lib/chef/runner.rb:49:in `run_action'
/opt/chef/embedded/apps/chef/lib/chef/runner.rb:81:in `block (2 levels) in converge'
/opt/chef/embedded/apps/chef/lib/chef/runner.rb:81:in `each'
/opt/chef/embedded/apps/chef/lib/chef/runner.rb:81:in `block in converge'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/resource_list.rb:83:in `block in execute_each_resource'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/stepable_iterator.rb:116:in `call'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/stepable_iterator.rb:116:in `call_iterator_block'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/stepable_iterator.rb:85:in `step'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/stepable_iterator.rb:104:in `iterate'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/stepable_iterator.rb:55:in `each_with_index'
/opt/chef/embedded/apps/chef/lib/chef/resource_collection/resource_list.rb:81:in `execute_each_resource'
/opt/chef/embedded/apps/chef/lib/chef/runner.rb:80:in `converge'
/opt/chef/embedded/apps/chef/lib/chef/client.rb:339:in `block in converge'
/opt/chef/embedded/apps/chef/lib/chef/client.rb:334:in `catch'
/opt/chef/embedded/apps/chef/lib/chef/client.rb:334:in `converge'
/opt/chef/embedded/apps/chef/lib/chef/client.rb:353:in `converge_and_save'
/opt/chef/embedded/apps/chef/lib/chef/client.rb:457:in `run'
/opt/chef/embedded/apps/chef/lib/chef/application.rb:271:in `block in fork_chef_client'
/opt/chef/embedded/apps/chef/lib/chef/application.rb:259:in `fork'
/opt/chef/embedded/apps/chef/lib/chef/application.rb:259:in `fork_chef_client'
/opt/chef/embedded/apps/chef/lib/chef/application.rb:225:in `block in run_chef_client'
/opt/chef/embedded/apps/chef/lib/chef/local_mode.rb:39:in `with_server_connectivity'
/opt/chef/embedded/apps/chef/lib/chef/application.rb:213:in `run_chef_client'
/opt/chef/embedded/apps/chef/lib/chef/application/client.rb:402:in `block in interval_run_chef_client'
/opt/chef/embedded/apps/chef/lib/chef/application/client.rb:392:in `loop'
/opt/chef/embedded/apps/chef/lib/chef/application/client.rb:392:in `interval_run_chef_client'
/opt/chef/embedded/apps/chef/lib/chef/application/client.rb:382:in `run_application'
/opt/chef/embedded/apps/chef/lib/chef/application.rb:60:in `run'
/opt/chef/embedded/apps/chef/bin/chef-client:26:in `<top (required)>'
/usr/bin/chef-client:51:in `load'
/usr/bin/chef-client:51:in `<main>'

Apologies about that. :)

[coderanger]

Yes, look above that, the lines we are looking for are like the one I linked (Chef::Log.debug("[Poise] Checking #{seg} in #{name}: #{file.inspect}")).

[jamiebuxxx]

Hmm, I'm not finding anything like that line in the chef-client logs:

[2015-10-02T18:40:57+00:00] INFO: Processing python_runtime[2] action install (poise-python::default line 20)
[2015-10-02T18:40:57+00:00] DEBUG: [PoisePython::PythonProviders::Base] Checking cookbook name for /var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/base.rb
[2015-10-02T18:40:57+00:00] DEBUG: [Poise] Checking cookbook for "/var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/base.rb"
[2015-10-02T18:40:57+00:00] INFO: Running queued delayed notifications before re-raising exception
[2015-10-02T18:40:57+00:00] DEBUG: Re-raising exception: Poise::Error - python_runtime[2] (poise-python::default line 20) had an error: Poise::Error: Unable to find cookbook for file "/var/chef/cache/cookbooks/poise-python/files/halite_gem/poise_python/python_providers/base.rb"
/var/chef/cache/cookbooks/poise/files/halite_gem/poise/utils.rb:64:in `find_cookbook_name'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/defined_in.rb:69:in `poise_defined_in_cookbook'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:237:in `default_inversion_attributes'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:256:in `resolve_inversion_attribute'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:272:in `block in inversion_options'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:271:in `tap'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:271:in `inversion_options'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:311:in `resolve_inversion_provider'
  /var/chef/cache/cookbooks/poise/files/halite_gem/poise/helpers/inversion.rb:354:in `provides?'
...

The environment variable is set, but somehow that line is being skipped and going directly to line 64

[coderanger]

Are you running via sudo chef-client? If so that would be resetting your env vars for you. Either way, you can also use the second method to enable debugging which is set POISE_DEBUG as a node attribute, usually via knife node edit.

[jamiebuxxx]

Yea, we are running chef-client. I'm trying set the node attribute, but its not changing anything.

poise-python

    provider: auto
    options: 
    install_python2: true
    install_python3: false
    install_pypy: false

POISE_DEBUG: 1

I'm not sure what exactly I'm missing here.

[jamiebuxxx]

Ok, we were able to get poise-python cookbook to work! I had nothing to do with the previous python cookbook, but with the parted cookbook being ran before the poise-python cookbook.

Its super weird and should not have any connection. But after changing the chef run list order, everything is working fine. However, we are still curious about what's happening here. Our team is going to have a deeper conversation about this on Monday. I'm also not sure why we were unable to get the debug info from the poise cookbook. Must be doing too much on a Friday I guess! :)

Thanks for getting back to us so quickly and keep up the awesome work!

[coderanger]

Huh, I'll see if I can repro that locally since it definitely shouldn't have that kind of effect.

[jamiebuxxx]

Agreed! We are wrapping the parted cookbook to partition /dev/sdb1 and mount it to /data. Here's a copy of the recipe are using for that.

https://gist.github.com/jamiebuxxx/8e18d29d3964d5f5803b

[coderanger]

Hmm, I can't see to repro this. If it happens again we can try more though!

[matl33t]

I also encountered this issue - after much digging I found this was caused by the run_context getting wiped out immediately after a guard. Some searching yielded https://github.com/chef/chef/issues/3485 which @coderanger addressed, and upgrading my client from 12.3.0 -> 12.5.1 fixed it - patched at 12.4.0

[coderanger]

Aha, well researched! I had totally forgotten about that bug, but it would definitely do it. Thanks!

[jamiebuxxx]

Cool deal! I'll pass this info over to the rest of my team. Thanks for the insight @matl33t!