Concurrent orchestrate runners get mixed up pillar data

[tnypex]

Hi,

salt['pillar.get'] returns mixed up values when concurrent orchestrate runners are started by the reactor.
This is the same issue as in #23373 event though that was supposed to be fixed by the RequestContext implementation (PR #27843)

SLS and logs below:

the reactor sls is:

{% set fun = data.get('fun', {}) %}
{% set arg = data.get('arg', {}) %}
{% set minions = data.get('minions', {}) %}


{% if fun == "test.ping" %}
{% for minion in minions %}
orchestrate_handle_test_{{minion}}:
  runner.state.orchestrate:
    - mods: orchestration.test.test
    - pillar: {target_server: {{minion}}}

{% endfor %}
{% endif %}

and the orchestrate sls:

notify_test_{{target_server}}:
  salt.function:
    - name: cmd.run
    - tgt: minion1
    - arg:
      - '/tmp/test.ksh  {{ target_server }}'
      - '/tmp/'
      - '/dev/null'
      - 'myid'

When, running test.ping against multiple minions salt '*' test.ping , the reactor sls is correctly rendered but the following orchestrate runners get mixed/inconsistent pillar data, full debug logs pasted below:

[DEBUG   ] LazyLoaded local_cache.prep_jid
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'_stamp': '2016-01-12T11:00:22.995250', 'minions': ['minion1', 'minion2', 'minion3', 'minion4']}
[DEBUG   ] Sending event - data = {'tgt_type': 'glob', 'jid': '20160112120022993175', 'tgt': '*', '_stamp': '2016-01-12T11:00:22.996043', 'user': 'root', 'arg': [], 'fun': 'test.ping', 'minions': ['minion1', 'minion2', 'minion3', 'minion4']}
[DEBUG   ] Gathering reactors for tag 20160112120022993175
[DEBUG   ] Gathering reactors for tag salt/job/20160112120022993175/new
[DEBUG   ] Compiling reactions for tag salt/job/20160112120022993175/new
[DEBUG   ] compile template: /srv/salt/base/reactor/jobs.sls
[INFO    ] User root Published command test.ping with jid 20160112120022993175
[DEBUG   ] Published command details {'tgt_type': 'glob', 'jid': '20160112120022993175', 'tgt': '*', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'test.ping'}
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[PROFILE ] Time (in seconds) to render '/srv/salt/base/reactor/jobs.sls' using 'jinja' renderer: 0.0269289016724
[DEBUG   ] Rendered data from file: /srv/salt/base/reactor/jobs.sls:







orchestrate_handle_test_minion1:
  runner.state.orchestrate:
    - mods: orchestration.test.test
    - pillar: {target_server: minion1}


orchestrate_handle_test_minion2:
  runner.state.orchestrate:
    - mods: orchestration.test.test
    - pillar: {target_server: minion2}


orchestrate_handle_test_minion3:
  runner.state.orchestrate:
    - mods: orchestration.test.test
    - pillar: {target_server: minion3}


orchestrate_handle_test_minion4:
  runner.state.orchestrate:
    - mods: orchestration.test.test
    - pillar: {target_server: minion4}







[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering: 
OrderedDict([('orchestrate_handle_test_minion1', OrderedDict([('runner.state.orchestrate', [OrderedDict([('mods', 'orchestration.test.test')]), OrderedDict([('pillar', OrderedDict([('target_server', 'minion1')]))])])])), ('orchestrate_handle_test_minion2', OrderedDict([('runner.state.orchestrate', [OrderedDict([('mods', 'orchestration.test.test')]), OrderedDict([('pillar', OrderedDict([('target_server', 'minion2')]))])])])), ('orchestrate_handle_test_minion3', OrderedDict([('runner.state.orchestrate', [OrderedDict([('mods', 'orchestration.test.test')]), OrderedDict([('pillar', OrderedDict([('target_server', 'minion3')]))])])])), ('orchestrate_handle_test_minion4', OrderedDict([('runner.state.orchestrate', [OrderedDict([('mods', 'orchestration.test.test')]), OrderedDict([('pillar', OrderedDict([('target_server', 'minion4')]))])])]))])
[PROFILE ] Time (in seconds) to render '/srv/salt/base/reactor/jobs.sls' using 'yaml' renderer: 0.0187299251556
[DEBUG   ] ThreadPool executing func: <bound method RunnerClient.low of <salt.runner.RunnerClient object at 0x23d8f10>> with args:('state.orchestrate', {'mods': 'orchestration.test.test', 'name': u'orchestrate_handle_test_minion1', 'pillar': OrderedDict([('target_server', 'minion1')]), 'state': 'runner', '__id__': 'orchestrate_handle_test_minion1', '__user__': 'Reactor', '__sls__': '/srv/salt/base/reactor/jobs.sls', 'order': 1, 'user': 'Reactor'}) kwargs{}
[DEBUG   ] ThreadPool executing func: <bound method RunnerClient.low of <salt.runner.RunnerClient object at 0x23d8f10>> with args:('state.orchestrate', {'mods': 'orchestration.test.test', 'name': u'orchestrate_handle_test_minion2', 'pillar': OrderedDict([('target_server', 'minion2')]), 'state': 'runner', '__id__': 'orchestrate_handle_test_minion2', '__user__': 'Reactor', '__sls__': '/srv/salt/base/reactor/jobs.sls', 'order': 1, 'user': 'Reactor'}) kwargs{}
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] ThreadPool executing func: <bound method RunnerClient.low of <salt.runner.RunnerClient object at 0x23d8f10>> with args:('state.orchestrate', {'mods': 'orchestration.test.test', 'name': u'orchestrate_handle_test_minion4', 'pillar': OrderedDict([('target_server', 'minion4')]), 'state': 'runner', '__id__': 'orchestrate_handle_test_minion4', '__user__': 'Reactor', '__sls__': '/srv/salt/base/reactor/jobs.sls', 'order': 1, 'user': 'Reactor'}) kwargs{}
[DEBUG   ] ThreadPool executing func: <bound method RunnerClient.low of <salt.runner.RunnerClient object at 0x23d8f10>> with args:('state.orchestrate', {'mods': 'orchestration.test.test', 'name': u'orchestrate_handle_test_minion3', 'pillar': OrderedDict([('target_server', 'minion3')]), 'state': 'runner', '__id__': 'orchestrate_handle_test_minion3', '__user__': 'Reactor', '__sls__': '/srv/salt/base/reactor/jobs.sls', 'order': 1, 'user': 'Reactor'}) kwargs{}
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'fun': 'runner.state.orchestrate', 'jid': '20160112120024318919', 'user': 'Reactor', '_stamp': '2016-01-12T11:00:24.326944'}
[DEBUG   ] LazyLoaded state.orchestrate
[DEBUG   ] Error loading runners.nacl: libnacl import error, perhaps missing python libnacl package
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'fun': 'runner.state.orchestrate', 'jid': '20160112120024365367', 'user': 'Reactor', '_stamp': '2016-01-12T11:00:24.385043'}
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'fun': 'runner.state.orchestrate', 'jid': '20160112120024412357', 'user': 'Reactor', '_stamp': '2016-01-12T11:00:24.428243'}
/usr/lib/python2.6/site-packages/salt/client/mixins.py:333: DeprecationWarning: kwargs must be passed inside the low under "kwargs"
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'fun': 'runner.state.orchestrate', 'jid': '20160112120024506091', 'user': 'Reactor', '_stamp': '2016-01-12T11:00:24.523897'}
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Guessing ID. The id can be explicitly set in /etc/salt/minion
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[INFO    ] Found minion id from generate_minion_id(): saltmaster
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded state.sls
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] LazyLoaded state.sls
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded state.sls
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] LazyLoaded roots.envs
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded roots.envs
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] Could not LazyLoad roots.init
[DEBUG   ] Updating roots fileserver cache
[DEBUG   ] LazyLoaded state.sls
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] Could not LazyLoad roots.init
[DEBUG   ] Updating roots fileserver cache
[DEBUG   ] LazyLoaded roots.envs
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] Could not LazyLoad roots.init
[DEBUG   ] Updating roots fileserver cache
[DEBUG   ] LazyLoaded roots.envs
[DEBUG   ] Could not LazyLoad roots.init
[DEBUG   ] Updating roots fileserver cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] In saltenv 'base', looking at rel_path 'orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/master/files/base/orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[DEBUG   ] LazyLoaded jinja.render
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://orchestration/test/test.sls'
[DEBUG   ] compile template: /var/cache/salt/master/files/base/orchestration/test/test.sls
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[DEBUG   ] In saltenv 'base', looking at rel_path 'orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/master/files/base/orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[DEBUG   ] LazyLoaded pillar.get
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'jinja' renderer: 0.0154371261597
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://orchestration/test/test.sls'
[DEBUG   ] Rendered data from file: /var/cache/salt/master/files/base/orchestration/test/test.sls:



notify_test_minion1:
  salt.function:
    - name: cmd.run
    - tgt: minion1
    - arg:
      - '/tmp/test.ksh minion1'
      - '/tmp/'
      - '/dev/null'
      - 'myid'



[DEBUG   ] compile template: /var/cache/salt/master/files/base/orchestration/test/test.sls
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering: 
OrderedDict([('notify_test_minion1', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.run')]), OrderedDict([('tgt', 'minion1')]), OrderedDict([('arg', ['/tmp/test.ksh minion1', '/tmp/', '/dev/null', 'myid'])])])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'jinja' renderer: 0.0174221992493
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'yaml' renderer: 0.0254518985748
[DEBUG   ] Rendered data from file: /var/cache/salt/master/files/base/orchestration/test/test.sls:



notify_test_minion1:
  salt.function:
    - name: cmd.run
    - tgt: minion1
    - arg:
      - '/tmp/test.ksh minion1'
      - '/tmp/'
      - '/dev/null'
      - 'myid'



[DEBUG   ] LazyLoaded config.option
[DEBUG   ] Results of YAML rendering: 
OrderedDict([('notify_test_minion1', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.run')]), OrderedDict([('tgt', 'minion1')]), OrderedDict([('arg', ['/tmp/test.ksh minion1', '/tmp/', '/dev/null', 'myid'])])])]))])
[DEBUG   ] LazyLoaded salt.function
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'yaml' renderer: 0.0123250484467
[INFO    ] Running state [cmd.run] at time 12:00:26.056375
[DEBUG   ] LazyLoaded salt.function
[INFO    ] Executing state salt.function for cmd.run
[INFO    ] Running state [cmd.run] at time 12:00:26.061644
[INFO    ] Executing state salt.function for cmd.run
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] LazyLoaded saltutil.cmd
[DEBUG   ] Reading configuration from /etc/salt/master
[DEBUG   ] Missing configuration file: /root/.saltrc
[DEBUG   ] Missing configuration file: /root/.saltrc
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'saltmaster_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'saltmaster_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG   ] LazyLoaded local_cache.prep_jid
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'_stamp': '2016-01-12T11:00:26.319562', 'minions': ['minion1']}
[DEBUG   ] Sending event - data = {'tgt_type': 'glob', 'jid': '20160112120026315063', 'tgt': 'minion1', '_stamp': '2016-01-12T11:00:26.323314', 'user': 'root', 'arg': ['/tmp/test.ksh minion1', '/tmp/', '/dev/null', 'myid'], 'fun': 'cmd.run', 'minions': ['minion1']}
[DEBUG   ] Gathering reactors for tag 20160112120026315063
[DEBUG   ] Gathering reactors for tag salt/job/20160112120026315063/new
[DEBUG   ] Compiling reactions for tag salt/job/20160112120026315063/new
[INFO    ] User root Published command cmd.run with jid 20160112120026315063
[DEBUG   ] Published command details {'tgt_type': 'glob', 'jid': '20160112120026315063', 'tgt': 'minion1', 'ret': '', 'user': 'root', 'arg': ['/tmp/test.ksh minion1', '/tmp/', '/dev/null', 'myid'], 'fun': 'cmd.run'}
[DEBUG   ] compile template: /srv/salt/base/reactor/jobs.sls
[DEBUG   ] LazyLoaded local_cache.prep_jid
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG   ] Sending event - data = {'_stamp': '2016-01-12T11:00:26.342095', 'minions': ['minion1']}
[DEBUG   ] LazyLoaded local_cache.get_load
[DEBUG   ] Sending event - data = {'tgt_type': 'glob', 'jid': '20160112120026336813', 'tgt': 'minion1', '_stamp': '2016-01-12T11:00:26.346361', 'user': 'root', 'arg': ['/tmp/test.ksh minion1', '/tmp/', '/dev/null', 'myid'], 'fun': 'cmd.run', 'minions': ['minion1']}
[DEBUG   ] get_iter_returns for jid 20160112120026315063 sent to set(['minion1']) will timeout at 12:00:31.345095
[INFO    ] User root Published command cmd.run with jid 20160112120026336813
[DEBUG   ] Published command details {'tgt_type': 'glob', 'jid': '20160112120026336813', 'tgt': 'minion1', 'ret': '', 'user': 'root', 'arg': ['/tmp/test.ksh minion1', '/tmp/', '/dev/null', 'myid'], 'fun': 'cmd.run'}
[PROFILE ] Time (in seconds) to render '/srv/salt/base/reactor/jobs.sls' using 'jinja' renderer: 0.0436570644379
[DEBUG   ] Rendered data from file: /srv/salt/base/reactor/jobs.sls:










[DEBUG   ] LazyLoaded local_cache.get_load
[DEBUG   ] Results of YAML rendering: 
{}
[PROFILE ] Time (in seconds) to render '/srv/salt/base/reactor/jobs.sls' using 'yaml' renderer: 0.00289511680603
[DEBUG   ] get_iter_returns for jid 20160112120026336813 sent to set(['minion1']) will timeout at 12:00:31.380916
[DEBUG   ] Gathering reactors for tag 20160112120026336813
[DEBUG   ] Gathering reactors for tag salt/job/20160112120026336813/new
[DEBUG   ] Compiling reactions for tag salt/job/20160112120026336813/new
[DEBUG   ] compile template: /srv/salt/base/reactor/jobs.sls
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[PROFILE ] Time (in seconds) to render '/srv/salt/base/reactor/jobs.sls' using 'jinja' renderer: 0.0241320133209
[DEBUG   ] Rendered data from file: /srv/salt/base/reactor/jobs.sls:










[DEBUG   ] Results of YAML rendering: 
{}
[PROFILE ] Time (in seconds) to render '/srv/salt/base/reactor/jobs.sls' using 'yaml' renderer: 0.00102591514587
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] In saltenv 'base', looking at rel_path 'orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/master/files/base/orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://orchestration/test/test.sls'
[DEBUG   ] compile template: /var/cache/salt/master/files/base/orchestration/test/test.sls
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded pillar.get
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'jinja' renderer: 0.00727510452271
[DEBUG   ] In saltenv 'base', looking at rel_path 'orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[DEBUG   ] Rendered data from file: /var/cache/salt/master/files/base/orchestration/test/test.sls:



notify_test_minion3:
  salt.function:
    - name: cmd.run
    - tgt: minion1
    - arg:
      - '/tmp/test.ksh minion3'
      - '/tmp/'
      - '/dev/null'
      - 'myid'



[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/master/files/base/orchestration/test/test.sls' to resolve 'salt://orchestration/test/test.sls'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://orchestration/test/test.sls'
[DEBUG   ] compile template: /var/cache/salt/master/files/base/orchestration/test/test.sls
[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering: 
OrderedDict([('notify_test_minion3', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.run')]), OrderedDict([('tgt', 'minion1')]), OrderedDict([('arg', ['/tmp/test.ksh minion3', '/tmp/', '/dev/null', 'myid'])])])]))])
[DEBUG   ] Jinja search path: '['/var/cache/salt/master/files/base']'
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'yaml' renderer: 0.0101249217987
[PROFILE ] Time (in seconds) to render '/var/cache/salt/master/files/base/orchestration/test/test.sls' using 'jinja' renderer: 0.00700879096985
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] Rendered data from file: /var/cache/salt/master/files/base/orchestration/test/test.sls:



notify_test_minion3:
  salt.function:
    - name: cmd.run
    - tgt: minion1
    - arg:
      - '/tmp/test.ksh minion3'
      - '/tmp/'
      - '/dev/null'
      - 'myid'

[jfindlay]

@tnypex, thanks for reporting.

[themalkolm]

I can confirm too that this is happening in 2015.8.7

[mchugh19]

I just created #38868 which seems related. Seeing this behavior in 2016.11.1

[DrMerlin]

Seeing this frequently too. Breaking our ability to effectively use orchestration.

[DrMerlin]

This is still really killing our orchestration. Is there any hope in sight?
We're hoping to roll to 2017.7.2 as soon as it's realeased, but it doesn't look like this is getting fixed.

Any work arounds?

[Ch3LL]

Okay the only thing i can replicate is sometimes the pillar data is empty on 2017.7 and it only occurs sometimes.

2017-09-14 15:55:46,347 [salt.template                            ][DEBUG   ][57] Rendered data from file: /var/cache/salt/master/files/base/orch/test.sls:

notify_test_minion3:
  salt.function:
    - name: cmd.run
    - tgt: minion3
    - arg:
      - touch /tmp/minion3

2017-09-14 15:55:46,356 [salt.utils.lazy                          ][DEBUG   ][57] LazyLoaded config.get
2017-09-14 15:55:46,357 [salt.loaded.int.render.yaml              ][DEBUG   ][57] Results of YAML rendering: 
--
2017-09-14 15:55:47,038 [salt.template                            ][DEBUG   ][57] Rendered data from file: /var/cache/salt/master/files/base/orch/test.sls:

notify_test_:
  salt.function:
    - name: cmd.run
    - tgt: 
    - arg:
      - touch /tmp/

2017-09-14 15:55:47,045 [salt.utils.lazy                          ][DEBUG   ][57] LazyLoaded config.get
2017-09-14 15:55:47,045 [salt.loaded.int.render.yaml              ][DEBUG   ][57] Results of YAML rendering: 
--
2017-09-14 15:55:47,236 [salt.template                            ][DEBUG   ][57] Rendered data from file: /var/cache/salt/master/files/base/orch/test.sls:

notify_test_minion2:
  salt.function:
    - name: cmd.run
    - tgt: minion2
    - arg:
      - touch /tmp/minion2

2017-09-14 15:55:47,240 [salt.utils.lazy                          ][DEBUG   ][57] LazyLoaded config.get
2017-09-14 15:55:47,240 [salt.state                               ][ERROR   ][57] No changes made for cmd.run

Here is a docker container for someone to quickly replicate:

1. docker run -it -v ~/git/salt:/testing/ ch3ll/issues:30353 ( where ~/git/salt is a local cloned git repo of salt )
2. salt-master -d; salt-minion -d; salt-minion -c /etc/salt2/ -d; salt-minion -c /etc/salt3/ -d
3. And run ~/test.sh and it will run test.ping and then grep the logs for the rendered file.

You will need to run that ~/test.sh a couple of times. (5-10 times) and you will see empty pillar data sometimes.

I found this PR in the queue: #39948 which should fix the issue. I tested with this fix and did not see pillar data missing. Can anyone here verify this fix resolves the issue for them as well?

[DrMerlin]

I'll take a look at this today. Thanks!

[DrMerlin]

I finally got my docker set up to run this over and over, and I haven't been able to catch it erroring out yet.

I will keep poking.

[DrMerlin]

I haven't actually verified the PR, but...

Good news: I had a test that I ran on our 2016.11.1 server where it would lose or mix up pillar data in concurrent reactor+orchestrations almost 100% of the time... (I used this test because I could run it on our live server less dangerously than the test reactor in the container)

When I ran that in the docker container, it failed about 3% of the time. So something is different between our master and the docker container- and the version of docker is definitely different. So I'm hoping our success rate shoots up when we can update to 2017.7 (soon).

The 3% of failures are probably what #39948 are there to fix, and they are definitely "missing" pillar errors instead of "mixed up" pillar errors.

That's all nice- but I'm not sure of the best way to pull #39948 into my local clone to test that THAT fix actually closes off the rest of the errors. I'm moderately smart with github, just not that smart.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.