[PUP-10080] Exec resources fail if the working directory is inaccessible Created: 2019/10/03  Updated: 2019/10/09  Resolved: 2019/10/08

Status: Closed
Project: Puppet
Component/s: Types and Providers, UX
Affects Version/s: PUP 6.8.1
Fix Version/s: None

Type: Bug Priority: Minor
Reporter: John Bollinger Assignee: Josh Cooper
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Blocks
is blocked by FACT-2055 Facter fails if its working directory... Accepted
Duplicate
duplicates PUP-5915 exec resources fail unless cwd is rea... Resolved
Relates
relates to PUP-9997 Puppet must not call Dir.chdir() exce... Accepted
Template: PUP Bug Template
Agent OS: CentOS 7
Master OS: CentOS 7
Epic Link: Execution API
Team: Coremunity
Sprint: Platform Core KANBAN
Method Found: Needs Assessment
QA Risk Assessment: Needs Assessment

 Description   

Puppet Version: 6.8.1
Puppet Server Version: 6.5.0
OS Name/Version: CentOS 7

Exec resources fail unnecessarily when the working directory from which the 'agent' or 'apply' face is launched does not exist or is inaccessible to puppet. Additionally, in the event that the working directory exists but is inaccessible to the process, the diagnostic emitted incorrectly reports that the directory does not exist.

I typically observe this on machines where my home directory is NFS-mounted, such that it is inaccessible to the local root account. With that as my working directory, I sudo a privileged shell in which to run the Puppet agent, but catalog application fails on account of errors from multiple Exec resources. Changing directory to a root-accessible one allows catalog application to succeed. In at least some cases, the command being executed is insensitive to the accessibility of the working directory, so there's no particular reason that the Exec should fail.

Desired Behavior:

Exec resources should not automatically fail on account of a missing or inaccessible working directory, unless a specific working directory is requested via the cwd parameter.

Puppet, generally, should not rely on the working directory being accessible except where it actually needs to access it for some configuration-, face-, or catalog-specific reason.

Actual Behavior:

Exec resources with no cwd specified fail spuriously when Puppet's working directory cannot be accessed, even when execution of the command does not depend on accessing that directory. The specific failure mode seems to depend on details of the situation, but the one I normally run into can be reproduced with puppet apply, too, like so:


Example 1

1. log in to a machine on which my home directory is on an automounted NFS file system with root squashing in effect
2. sudo bash to obtain a root shell
3. Execute

puppet apply --execute "exec { '/bin/echo': }"

Output:

Notice: Compiled catalog for xxx.yyy.zzz in environment production in 0.04 seconds
Error: Working directory /mnt/auto/home/a_group/jbolling does not exist!
Error: /Stage[main]/Main/Exec[/bin/echo]/returns: change from 'notrun' to ['0'] failed: Working directory /mnt/auto/home/miller2grp/jbolling does not exist!
Notice: Applied catalog in 0.12 seconds


Errors of the same form are also reported by the agent under these circumstances if the catalog being applied contains `Exec` resources without cwd parameters. On the other hand, these particular failures do not occur if the Exec in question has a cwd parameter designating an existing, accessible directory, notwithstanding that the Puppet process's own working directory is inaccessible to it.

Oddly enough, a different failure occurs if Puppet's working directory actually doesn't exist. That situation can be reproduced like so:


Example 2

1. Create a fresh directory for the experiment: mkdir doomed.
2. Make that directory the working directory: cd doomed.
3. In a separate shell, remove the directory: rm doomed.
4. In the first shell, run any Puppet command at all, for example

puppet agent --test

or

puppet apply --execute "exec { '/bin/echo': cwd => '/tmp' }"

.

Output

shell-init: error retrieving current directory: getcwd: cannot access parent directories: No such file or directory
terminate called after throwing an instance of 'boost::filesystem::filesystem_error'
what(): boost::filesystem::current_path: No such file or directory
Aborted


As described in conjunction with Example 1, however, Puppet does not actually need to access the current working directory to compile or apply a catalog, at least not as a general rule, so this failure is spurious.

Of course, these issues can be worked around by ensuring that the working directory is an existing, accessible one before running Puppet, and I imagine that both failure scenarios presented are unlikely for most people. However, I personally hit the Example 1 case often enough to inspire me to file this report. I note also that it's distinctly more annoying when it occurs as a result of puppet agent --test ing a catalog that takes a minute to retrieve and a few minutes to apply, and there is some risk that such a failure leaves the system in an unexpected state requiring manual intervention.



 Comments   
Comment by Josh Cooper [ 2019/10/03 ]

Thanks John Bollinger. Could you run the first example with --trace? It may be related to PUP-9997

The second case is failing due to facter. Could you file a FACT ticket for that?

[root@rbbd3d3x1dbupp3 test]# facter --debug
shell-init: error retrieving current directory: getcwd: cannot access parent directories: No such file or directory
2019-10-03 17:16:34.811353 INFO  puppetlabs.facter - executed with command line: --debug.
2019-10-03 17:16:34.812893 INFO  leatherman.ruby:139 - ruby loaded from "/opt/puppetlabs/puppet/lib/libruby.so.2.5.3".
2019-10-03 17:16:34.813368 DEBUG leatherman.dynamic_library:77 - symbol rb_data_object_alloc not found in library /opt/puppetlabs/puppet/lib/libruby.so.2.5.3, trying alias rb_data_object_wrap.
2019-10-03 17:16:34.893465 INFO  leatherman.ruby:195 - using ruby version 2.5.3
2019-10-03 17:16:34.893562 INFO  puppetlabs.facter - resolving all facts.
2019-10-03 17:16:34.893661 DEBUG puppetlabs.facter - fact "facterversion" has resolved to "3.14.3".
2019-10-03 17:16:34.893774 DEBUG puppetlabs.facter - fact "aio_agent_version" has resolved to "6.8.1".
2019-10-03 17:16:34.894163 DEBUG leatherman.file_util:65 - Error reading file: No such file or directory
2019-10-03 17:16:34.895305 FATAL puppetlabs.facter - unhandled exception: boost::filesystem::current_path: No such file or directory

Comment by John Bollinger [ 2019/10/03 ]

FACT-2055 created for the Facter side.

Comment by John Bollinger [ 2019/10/03 ]

Trace of example 1:

# puppet apply --trace --execute "exec { '/bin/echo': }"
 Notice: Compiled catalog for moby.stjude.org in environment production in 0.04 seconds
 Error: Working directory /mnt/auto/home/miller2grp/jbolling does not exist!
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/execution.rb:196:in `execute'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/provider/exec.rb:60:in `block in run'
 /opt/puppetlabs/puppet/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
 /opt/puppetlabs/puppet/lib/ruby/2.5.0/timeout.rb:103:in `timeout'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/provider/exec.rb:53:in `run'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/provider/exec/posix.rb:45:in `run'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/type/exec.rb:133:in `block in sync'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/type/exec.rb:130:in `times'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/type/exec.rb:130:in `sync'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:241:in `sync'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:136:in `sync_if_needed'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:90:in `block in perform_changes'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:89:in `each'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:89:in `perform_changes'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:21:in `evaluate'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:263:in `apply'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:283:in `eval_resource'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:187:in `call'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:187:in `block (2 levels) in evaluate'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:521:in `block in thinmark'
 /opt/puppetlabs/puppet/lib/ruby/2.5.0/benchmark.rb:308:in `realtime'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:520:in `thinmark'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:187:in `block in evaluate'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:122:in `traverse'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:174:in `evaluate'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:240:in `block (2 levels) in apply'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:521:in `block in thinmark'
 /opt/puppetlabs/puppet/lib/ruby/2.5.0/benchmark.rb:308:in `realtime' 
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:520:in `thinmark' 
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:239:in `block in apply'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/log.rb:161:in `with_destination'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/report.rb:146:in `as_logging_destination'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:238:in `apply'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:194:in `block (2 levels) in apply_catalog'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:521:in `block in thinmark'
 /opt/puppetlabs/puppet/lib/ruby/2.5.0/benchmark.rb:308:in `realtime'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:520:in `thinmark'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:193:in `block in apply_catalog'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:233:in `block in benchmark'
 /opt/puppetlabs/puppet/lib/ruby/2.5.0/benchmark.rb:308:in `realtime'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:232:in `benchmark'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:192:in `apply_catalog'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:381:in `run_internal'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:242: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:266:in `override'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:219:in `run'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:343:in `apply_catalog'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:260:in `block (2 levels) in main'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:65:in `override'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:266:in `override'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:243: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:266:in `override'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:207:in `main'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/apply.rb:177:in `run_command'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:382:in `block in run'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:687:in `exit_on_fail'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:382:in `run'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:143:in `run'
 /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:77:in `execute'
 /opt/puppetlabs/puppet/bin/puppet:5:in `<main>'
 Error: /Stage[main]/Main/Exec[/bin/echo]/returns: change from 'notrun' to ['0'] failed: Working directory /mnt/auto/home/miller2grp/jbolling does not exist!
 Notice: Applied catalog in 0.14 seconds

Comment by Josh Cooper [ 2019/10/03 ]

The base exec provider is defaulting the cwd, which seems wrong if it's not being managed. If I comment out that line, then I run into the facter issue.

Comment by John Bollinger [ 2019/10/03 ]

Huh.  Do you reproduce example 1 with unmodified Puppet, Josh Cooper?  Because when I hit the facter issue, it seems like puppet doesn't go anywhere at all – even puppet help fails – yet under Example 1 circumstances (the working directory exists but is inaccessible) an Exec with cwd set applies successfully for me. That would be

Example 3

  1.  Set up as in Example 1
  2. Execute the command

    puppet apply --execute "exec { '/bin/echo': cwd => '/tmp' }" 

The catalog is compiled and applied successfully in that case.

Comment by Josh Cooper [ 2019/10/03 ]

I don't have an easy way to reproduce example 1

Comment by John Bollinger [ 2019/10/04 ]

I agree that this issue is related to PUP-9997, but I think the key observation is Josh's from a few comments back: that it is inappropriate for the Exec provider to default the cwd parameter.  Instead, if no value is specified for that parameter then the provider ought not to attempt to change directory at all, neither in the parent nor in the child.

Such a change should be pretty safe from unwanted side effects, for in the vast majority of cases, changing the working directory to the same directory it already is, as Puppet does now, will have the same observable effects as the proposed behavior of not changing it at all.

Comment by John Bollinger [ 2019/10/04 ]

I confirm that modifying the base Exec provider to avoid defaulting the cwd parameter resolves the Example 1 case for me.  All unit tests continue to pass with that change.  I would be prepared to submit a PR, but

  • I'm not sure how to write tests that demonstrate the issue in the unpatched code, and
  • I'm uncertain whether this ought to instead be rolled in as part of a larger patch addressing PUP-9997.

Advice?

Comment by James Ralston [ 2019/10/08 ]

John Bollinger, I'll defer to Puppet folks who want to chime in, but as the reporter of PUP-9997, I would just submit a PR with the code fixes and no tests.

From looking at the code for the Exec provider, I think the only thing that is required is removing the cwd ||= Dir.pwd line, as Puppet::Util::Execution.execute() only calls Dir.chdir if the cwd parameter was set. Did you come to a different conclusion?

Comment by John Bollinger [ 2019/10/08 ]

James Ralston, I came to the same conclusion about the code change to be made, +/- explanatory code comments.  That seems to be what Josh Cooper was looking at, too.  I guess I can go ahead and submit the PR, and Puppet can kick it back to me if they don't want it.

Comment by James Ralston [ 2019/10/08 ]

John Bollinger, I propose that there are two separate issues here:

  1. Puppet misbehaves / fails if the cwd is inaccessible.
  2. Puppet misbehaves / fails if the cwd does not exist.

I reopend my ticket PUP-9997, which is solely about issue #1. Would you be willing to confine issue #1 to PUP-9997, and keep issue #2 confined to this ticket?

Comment by Josh Cooper [ 2019/10/08 ]

I agree. Let's close this as a dup of PUP-9997, update PR https://github.com/puppetlabs/puppet/pull/7775 to reference PUP-5915, and track the general issue of Dir.chdir in PUP-9997.

Comment by John Bollinger [ 2019/10/09 ]

For the record, I'm fine with this resolution.  I agree that my example 1 is among the cases covered by PUP-9997, but not necessarily the only such case.  My example #2 has already been reassigned to FACT-2055.

Generated at Mon Dec 16 02:09:32 PST 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.