Salt: [2017.7] file.managed with cmd_check "No such file or directory"

[gabekahen]

Description of Issue/Question

Setup

I was able to replicate the issue with a jinja template file (salt://test_file.jinja) containing a single pair of curly brackets {}.

Salt state test_file.sls:

/tmp/test_file:
  file.managed:
    - source: salt://test_file.jinja
    - template: jinja
    - check_cmd: /bin/true

test_file.jinja:

{}

Steps to Reproduce Issue

$ salt 'sensu*1*1*' state.apply test_file
sensu-test-1-1.novalocal:
----------
          ID: /tmp/test_file
    Function: file.managed
      Result: False
     Comment: Unable to manage file: [Errno 2] No such file or directory: /tmp/__salt.tmp.1Fgxur
     Started: 21:33:00.380968
    Duration: 31.029 ms
     Changes:

Summary for sensu-test-1-1.novalocal
------------
Succeeded: 0
Failed:    1
------------
Total states run:     1
Total run time:  31.029 ms
ERROR: Minions returned with non-zero exit code

Minion debug output after running above state:

[INFO    ] User sudo_gabe.kahen Executing command state.apply with jid 20170719213259957188
[DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20170719213259957188', 'tgt': 'sensu*1*1*', 'ret': '', 'user': 'sudo_gabe.kahen', 'arg': ['test_file'], 'fun': 'state.apply'}
[INFO    ] Starting a new job with PID 31842
[DEBUG   ] LazyLoaded state.apply
[DEBUG   ] LazyLoaded direct_call.execute
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506')
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506')
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] In saltenv 'base', looking at rel_path 'test_file.sls' to resolve 'salt://test_file.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test_file.sls' to resolve 'salt://test_file.sls'
[DEBUG   ] Fetching file from saltenv 'base', ** attempting ** 'salt://test_file.sls'
[DEBUG   ] No dest file found
[INFO    ] Fetching file from saltenv 'base', ** done ** 'test_file.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/test_file.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test_file.sls' using 'jinja' renderer: 0.00406885147095
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/test_file.sls:
# Setup the Sensu client configuration
/tmp/test_file:
  file.managed:
    - source: salt://test_file.jinja
    - template: jinja
    - check_cmd: /bin/true

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('/tmp/test_file', OrderedDict([('file.managed', [OrderedDict([('source', 'salt://test_file.jinja')]), OrderedDict([('template', 'jinja')]), OrderedDict([('check_cmd', '/bin/true')])])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test_file.sls' using 'yaml' renderer: 0.00230503082275
[DEBUG   ] LazyLoaded file.managed
[INFO    ] Running state [/tmp/test_file] at time 21:33:00.380968
[INFO    ] Executing state file.managed for [/tmp/test_file]
[DEBUG   ] LazyLoaded file.source_list
[DEBUG   ] LazyLoaded cp.hash_file
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506')
[DEBUG   ] In saltenv 'base', looking at rel_path 'test_file.jinja' to resolve 'salt://test_file.jinja'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test_file.jinja' to resolve 'salt://test_file.jinja'
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[DEBUG   ] running our check_cmd
[DEBUG   ] LazyLoaded cmd.run_all
[INFO    ] Executing command '/bin/true /tmp/__salt.tmp.tH9yPL' in directory '/root'
[DEBUG   ] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/salt/states/file.py", line 2497, in managed
    **kwargs)
  File "/usr/lib/python2.7/dist-packages/salt/modules/file.py", line 5241, in manage_file
    __opts__['cachedir'])
  File "/usr/lib/python2.7/dist-packages/salt/utils/files.py", line 88, in copyfile
    '[Errno 2] No such file or directory: {0}'.format(source)
IOError: [Errno 2] No such file or directory: /tmp/__salt.tmp.1Fgxur

[ERROR   ] Unable to manage file: [Errno 2] No such file or directory: /tmp/__salt.tmp.1Fgxur
[INFO    ] Completed state [/tmp/test_file] at time 21:33:00.411997 duration_in_ms=31.029
[DEBUG   ] File /var/cache/salt/minion/accumulator/139867861561616 does not exist, no need to cleanup.
[DEBUG   ] Minion return retry timer set to 10 seconds (randomized)
[INFO    ] Returning information for job: 20170719213259957188
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'sensu-test-1-1.novalocal', 'tcp://10.100.15.90:4506')
[DEBUG   ] minion return: {'fun_args': ['test_file'], 'jid': '20170719213259957188', 'return': {'file_|-/tmp/test_file_|-/tmp/test_file_|-managed': {'comment': 'Unable to manage file: [Errno 2] No such file or directory: /tmp/__salt.tmp.1Fgxur', 'name': '/tmp/test_file', 'start_time': '21:33:00.380968', 'result': False, 'duration': 31.029, '__run_num__': 0, '__sls__': u'test_file', 'changes': {}, '__id__': '/tmp/test_file'}}, 'retcode': 2, 'success': True, 'fun': 'state.apply'}

Versions Report

Running salt 2017.7.0 (Nitrogen) on the Master & Minion
NOTE: Issue does not appear on minions running salt-minion 2016.11.6 (Carbon)

[kti-richard]

Having the same issue - but with the usage in the sudo-formula, where it uses visudo for the check_cmd. It's like loosing the tmp file reference from the actual check call.

[seedickcode]

Comes from this issue and subsequent patch #33708
The new check and handling,

          if sfn and os.path.isfile(sfn):
                os.remove(sfn)
                sfn = tmp_filename

..is not getting hit, so sfn = tmp_filename never gets assigned, so it looks like the subsequent file.manage_file module call is trying to manage something that doesn't exist, hence the file not found.

No time yet to debug further to suggest a fix other than reverting that section that fails to just assign sfn = tmp_filename as before, but it seems that that is leaving dangling tmp files in some cases (as per #33708)

[felippeb]

This does not appear to happen on a node which has been upgraded from 2016.11. Does happen on a clean install of 2017.7.0.

It all doesn't appear to occur on every single check_cmd file.managed state that I have. It appears to only be on one which has a jinja template as a source, and this template contains only jinja:

state:

test-config:
  file.managed:
    - name: {{ test.conf_dir }}/00config.json
    - source: salt://test/files/etc/test/conf.d/00config.json
    - user: root
    - group: test
    - mode: "0640"
    - template: jinja
    - check_cmd: /usr/local/bin/test configtest -config-file
    - require:
      - group: test

template:

{% from "test/map.jinja" import test with context -%}
{{ test.config | json }}

map:

{% import_yaml "test/defaults.yml" as defaults %}

{% set test = salt['pillar.get']('test', default=defaults.test, merge=True) %}

{% do test.config.update({'retry_join': test.config.retry_join or []}) %}

i was able to work around by using file.serialize:
state:

test-config:
  file.serialize:
    - name: {{ test.conf_dir }}/00config.json
    - user: root
    - group: test
    - mode: "0640"
    - dataset:
{% for k,v in test.config.iteritems() %}
        {{k}}: {{v}}
{% endfor %}
    - check_cmd: /usr/local/bin/test configtest -config-file
    - formatter: json
    - require:
      - group: test

[seedickcode]

This fails for me on minions that have been upgraded from 2016.11 and fresh installs. It fails as soon as the file being managed needs an actual change, so usually a machine getting just a salt upgrade will probably not have this issue.

@felippeb I think file.serialize doesn't support check_cmd making it the same as just removing check_cmd from file.managed.

[felippeb]

@seedickcode good catch. thanks 👍

this does appear to work, and also invokes check_cmd (according to debug output)

test-config:
  file.managed:
    - name: {{ test.conf_dir }}/00config.json
    - user: root
    - group: test
    - mode: "0640"
    - contents: |
        {{ test.config | json }}
    - check_cmd: /usr/local/bin/test configtest -config-file
    - require:
      - group: test

[INFO ] Running state [/etc/test/conf.d/00config.json] at time 04:20:21.389081 [INFO ] Executing state file.managed for [/etc/test/conf.d/00config.json] [DEBUG ] running our check_cmd [INFO ] Executing command '/usr/local/bin/test configtest -config-file /tmp/__salt.tmp.Iifxh6' in directory '/home/ubuntu' [INFO ] File changed: New file [INFO ] Completed state [/etc/test/conf.d/00config.json] at time 04:20:21.411164 duration_in_ms=22.082

[gtmanfred]

This is fixed in #42411

Closing this issue.