Jira (PUP-5636) Puppet doesn't report missing binaries called through custom type and providers

[Geoff Williams (JIRA)]

Title: Message Title

Geoff Williams created an issue   Puppet / PUP-5636 Puppet doesn't report missing binaries called through custom type and providers Issue Type: Bug Affects Versions: PUP 4.3.1 Assignee: Kylo Ginsberg Attachments: testcase_unreported_missing_command.tar.gz Components: Client Created: 2015/12/22 10:34 PM Environment: Puppet Enterprise 2015.3.0 running under Docker Priority: Normal Reporter: Geoff Williams Overview When a custom type and provider attempts to run a program that is missing (or not discoverable in $PATH), Puppet doesn't report that the program is missing. Expected result If a program or script is missing, Puppet should inform the user, eg: command not found: openssl Actual result Users receive a message similar to the following: Error: Execution of 'openssl x509 -fingerprint -md5 -noout -in /etc/puppetlabs/puppet/ssl/certs/ca.pem' returned 1: This seems to indicate that the command has exited with a failure but this is not the case - the real error in this case is that openssl was not found in the PATH for some reason. Proof The above statement can be proved by: Moving the binary executable out of the way and observing the same error changing the type and provider to reference a non-existant binary Testcase Please see attached file for a testcase. This was originally reproducable using the pe_java_ks module under certain conditions. I'm not sure if this uses the puppet's execution API in a different way to other types and providers, however, the code ends up deep within puppet so it would be good if this could be addressed in-product. To use the testcase, extract the tarball and copy pe_java_ks into your modulepath. If using PE you will need to replace the directory at /opt/puppetlabs/puppet/modules/pe_java_ks/. Then attempt to run puppet in apply mode against test.pp. This will fail as the module has been altered to reference binaries that do not exist, and you will see the following error: [root@pe-puppet ~]# puppet apply --debug --evaltrace --trace test.pp Debug: Runtime environment: puppet_version=4.3.1, ruby_version=2.1.7, run_mode=user, default_encoding=UTF-8 Debug: Evicting cache entry for environment 'production' Debug: Caching environment 'production' (ttl = 0 sec) Debug: Evicting cache entry for environment 'production' Debug: Caching environment 'production' (ttl = 0 sec) Debug: Loading external facts from /opt/puppetlabs/puppet/cache/facts.d Info: Loading facts --- SNIP --- Debug: Executing: 'keytool_nothere -list -keystore /etc/puppetlabs/activemq/broker.ts -alias puppetca' Debug: Executing: 'keytool_nothere -list -keystore /etc/puppetlabs/activemq/broker.ts -alias puppetca' Debug: Executing: 'keytool_nothere -importcert -noprompt -alias puppetca -file /etc/puppetlabs/puppet/ssl/certs/ca.pem -keystore /etc/puppetlabs/activemq/broker.ts -trustcacerts' Error: Execution of 'keytool_nothere -importcert -noprompt -alias puppetca -file /etc/puppetlabs/puppet/ssl/certs/ca.pem -keystore /etc/puppetlabs/activemq/broker.ts -trustcacerts' returned 1: /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/execution.rb:232:in `execute' /opt/puppetlabs/puppet/modules/pe_java_ks/lib/puppet/provider/pe_java_ks/keytool.rb:227:in `call' /opt/puppetlabs/puppet/modules/pe_java_ks/lib/puppet/provider/pe_java_ks/keytool.rb:227:in `block in run_command' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:34:in `withenv' /opt/puppetlabs/puppet/modules/pe_java_ks/lib/puppet/provider/pe_java_ks/keytool.rb:226:in `call' /opt/puppetlabs/puppet/modules/pe_java_ks/lib/puppet/provider/pe_java_ks/keytool.rb:226:in `run_command' /opt/puppetlabs/puppet/modules/pe_java_ks/lib/puppet/provider/pe_java_ks/keytool.rb:145:in `create' /opt/puppetlabs/puppet/modules/pe_java_ks/lib/puppet/type/pe_java_ks.rb:24:in `block (3 levels) in <top (required)>' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/property.rb:427:in `set' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/property.rb:501:in `sync' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:214:in `sync' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:139:in `sync_if_needed' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:81:in `perform_changes' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:20:in `evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:207:in `apply' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:223:in `eval_resource' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:150:in `call' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:150:in `block (2 levels) in evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:292:in `block in thinmark' /opt/puppetlabs/puppet/lib/ruby/2.1.0/benchmark.rb:294:in `realtime' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:291:in `thinmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:150:in `block in evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:118:in `traverse' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:141:in `evaluate' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:202:in `block in apply' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/log.rb:153:in `with_destination' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/report.rb:107:in `as_logging_destination' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:201:in `apply' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:119:in `block in apply_catalog' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:129:in `block in benchmark' /opt/puppetlabs/puppet/lib/ruby/2.1.0/benchmark.rb:294:in `realtime' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:128:in `benchmark' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:118:in `apply_catalog' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:232:in `run_internal' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:134:in `block in run' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:133:in `run' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:347:in `apply_catalog' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:274:in `block in main' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:240:in `override' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:225:in `main' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:170:in `run_command' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:344:in `block in run' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:446:in `exit_on_fail' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:344:in `run' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:128:in `run' /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:72:in `execute' /opt/puppetlabs/puppet/bin/puppet:5:in `<main>' Error: /Stage[main]/Main/Pe_java_ks[puppetca:truststore]/ensure: change from absent to latest failed: Execution of 'keytool_nothere -importcert -noprompt -alias puppetca -file /etc/puppetlabs/puppet/ssl/certs/ca.pem -keystore /etc/puppetlabs/activemq/broker.ts -trustcacerts' returned 1: Info: /Stage[main]/Main/Pe_java_ks[puppetca:truststore]: Evaluated in 0.03 seconds Info: Class[Main]: Starting to evaluate the resource Debug: Class[Main]: Resource is being skipped, unscheduling all events Info: Class[Main]: Evaluated in 0.00 seconds Info: Stage[main]: Starting to evaluate the resource Debug: Stage[main]: Resource is being skipped, unscheduling all events Info: Stage[main]: Evaluated in 0.00 seconds Info: /Schedule[puppet]: Starting to evaluate the resource Info: /Schedule[puppet]: Evaluated in 0.00 seconds Info: /Schedule[hourly]: Starting to evaluate the resource Info: /Schedule[hourly]: Evaluated in 0.00 seconds Info: /Schedule[daily]: Starting to evaluate the resource Info: /Schedule[daily]: Evaluated in 0.00 seconds Info: /Schedule[weekly]: Starting to evaluate the resource Info: /Schedule[weekly]: Evaluated in 0.00 seconds Info: /Schedule[monthly]: Starting to evaluate the resource Info: /Schedule[monthly]: Evaluated in 0.00 seconds Info: /Schedule[never]: Starting to evaluate the resource Info: /Schedule[never]: Evaluated in 0.00 seconds Info: /Filebucket[puppet]: Starting to evaluate the resource Info: /Filebucket[puppet]: Evaluated in 0.00 seconds Debug: Finishing transaction 19510700 Debug: Storing state Debug: Stored state in 0.06 seconds Notice: Applied catalog in 0.19 seconds Debug: Applying settings catalog for sections reporting, metrics Debug: Finishing transaction 25137260 Debug: Received report to process from pe-puppet.localdomain Debug: Evicting cache entry for environment 'production' Debug: Caching environment 'production' (ttl = 0 sec) Debug: Processing report from pe-puppet.localdomain with processor Puppet::Reports::Store Notice that the above puppet run never says the command is not found. Why this is important It's incredibly difficult and time consuming to troubleshoot errors due to missing commands, packages or incorrect PATH statements at the moment because it looks like Puppet is running the command and receiving an error statement with no output. Desired outcome It would be great if the error handling in /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/execution.rb:232:in `execute' could be improved to report command not found errors to the user. Add Comment   This message was sent by Atlassian JIRA (v6.4.12#64027-sha1:e3691cc) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To post to this group, send email to puppet-bugs@googlegroups.com. Visit this group at https://groups.google.com/group/puppet-bugs. For more options, visit https://groups.google.com/d/optout.