salt-run state.orchestrate fails because it tries to run a second task while a first is ongoing

[bernieke]

To start off with, this problem seems somehow related to disk speed. We can reliably reproduce the problem on sata backed virtual machines, but not on ssd backed virtual machines. (Two different openstack flavors on for the rest the same hardware.)
Probably because it takes longer to execute the task on a sata disk. (There's a lot of deb installing going on, so this would make sense.)

This is the relevant part of the output:

# salt-run state.orchestrate orchestration.sls
awingu_master:
----------
          ID: common
    Function: salt.state
      Result: True
     Comment: States ran successfully.
     Started: 12:50:39.093757
    Duration: 63217.649 ms
     Changes:   
----------
          ID: dns_server
    Function: salt.state
      Result: False
     Comment: Run failed on minions: awingu
              Failures:
                  awingu:
                      Data failed to compile:
                  ----------
                      The function "state.sls" is running as PID 6334 and was started at 2014, Nov 28 12:50:39.102732 with jid 20141128125039102732
     Started: 12:51:42.312406
    Duration: 630.701 ms

The error doesn't always occur in that part of the orchestration, sometimes it happens in a later task, but always right after a task which takes a long time to run (several minutes.)

When I check right after the error, I can see that the job referenced is in fact still ongoing. Also issueing salt 'awingu' saltutil.running confirms this.
The job will, in time, do its thing and finish properly.
This job runs the "common" task preceding the dns_server task. (And which the dns_server task requires!)

So it's pretty clear that the orchestrate deems the "common" task finished, while in truth it has not.

It looks like a salt execution returns prematurely, before the task actually being finished (I've noted this on one or two occasions), but apart from that being a bug, I would expect the salt runner to be smarter and check the job queue?

For us this currently is a major issue, so any recommendations on how to handle this would be extremely welcome. Even a dirty monkeypatch to apply on top of 2014.7.0 would mean the world to us!

[bernieke]

One more factor which could be important is that our virtual network has been known to glitch a bit. Visible to us by ssh sessions which hang a few seconds.

In fact, one of the failures I noted happened exactly during one of those glitches! I remember turning around to ask my colleague if he had done something to the vm because my ssh sessions had frozen, and when I turned back, they had come back and it was displaying the error.

[bernieke]

I just build the raet dependencies, and tried using the raet transport, but got the exact same problem.

So it's not transport related at least.

[bernieke]

Increasing the salt timeout in the master config fixes the problem for us.

It seems like occasionally our vm, disk or network hangs long enough for some communication to timeout.

Is there some kind of polling mechanism during tasks which could cause this? (Since it only seems to happen on either of our two long running / intensive tasks.)

And is this the expected behavior? If so, salt-run should probably fail in a manner which is more clear to what went wrong, instead of simply continuing with the next task. (The same goes for the regular salt execution I guess, where it now just returns it should probably raise an error instead?)

I'll leave the ticket open since I'm not sure if and how you guys/gals will want to address this, but feel free to close it if you believe the behavior is the way you intended.

[bernieke]

what appears in /var/log/salt/master:

2014-12-01 14:06:11,928 [salt.master      ][INFO    ] Authentication request from awingu
2014-12-01 14:06:11,929 [salt.master      ][INFO    ] Authentication accepted from awingu
2014-12-01 14:06:12,023 [salt.utils.event ][DEBUG   ] Sending event - data = {'id': 'awingu', '_stamp': '2014-12-01T14:06:12.022995', 'result': True, 'pub': '-----BEGIN PUBLIC KEY-----\nMIICIjANBgkqhkiG9w0BAQEFAAOCAg8AMIICCgKCAgEA59rxDBn1Q8kaMYuNsb0S\nyrFKEHlhFw/gNTRiAphS8pGoZsYwFvTwYm/J3LmrsxP0HtU6m7vNXGK1LnvVfgP1\nKSjnkv49Q6IPcz7Nyqfzz9gyxz5fAsAzGRj4iDj4qGPRjv60PgEujYUTH4N8nhTY\noKW8hIClyXh2eiX5mjb4kY/98KXsPeSRjTQnBTMkvXlXSHllKoCKjgD3FBAVZF/m\ncRNAUvaPIGvZiaracd6cDStT3GXeK9PxCBzpL9Hg7QH28myLaVwcDNPe5MESFpvS\nu3TL2wWaIURQWAndg28lqDEg9MSp8jRy/nViy3O7RaVypGQ0ySLEjX0adv1EC0w2\nFh0wvktYXa2r7ixL9OdKbGgExrZSWv+T5VR8QwndAaJmwVkHENndLv5JMq+eLXLx\nlBdaHLZkYf/S2c5OtZC7LlNhEHNYrSGqriUBdOIHpT1NFabgzAkH3QZY+BgXf/un\nCq4HWFJJL8TWDTLeJm1xSu3n6ylwiaGZFSn/Rqig3P2c3urgQx662eVcSD7YjmW3\nN2Hp6Zrl7DqU/sw2pF5qEFcc2zdJpLycZlXFeVpBcgaPh4Ph8mWSPcxUPij2638T\nMZLZZsOfYXM1GSQiqHsdSFeAcY1RdPyuJKw8y64hFF7lsVF5/qS4xqGbMp3i0GeA\nPe90QbaJPoKcqrrJ2WfEEBcCAwEAAQ==\n-----END PUBLIC KEY-----\n', 'act': 'accept'}
2014-12-01 14:06:12,125 [salt.master      ][INFO    ] AES payload received with command _return
2014-12-01 14:06:12,126 [salt.master      ][INFO    ] Got return from awingu for job 20141201140611872022
2014-12-01 14:06:12,126 [salt.utils.event ][DEBUG   ] Sending event - data = {'fun_args': ['20141201140511389244'], 'jid': '20141201140611872022', 'return': {'tgt_type': 'glob', 'jid': '20141201140511389244', 'tgt': '*', 'pid': 5298, 'ret': {}, 'user': 'root', 'arg': ['bootstrap,packages.circus,packages.diamond,packages.logstash', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls'}, 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2014-12-01T14:06:12.125992', 'fun': 'saltutil.find_job', 'id': 'awingu'}
2014-12-01 14:06:12,127 [salt.utils.event ][DEBUG   ] Sending event - data = {'fun_args': ['20141201140511389244'], 'jid': '20141201140611872022', 'return': {'tgt_type': 'glob', 'jid': '20141201140511389244', 'tgt': '*', 'pid': 5298, 'ret': {}, 'user': 'root', 'arg': ['bootstrap,packages.circus,packages.diamond,packages.logstash', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls'}, 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2014-12-01T14:06:12.126474', 'fun': 'saltutil.find_job', 'id': 'awingu'}
2014-12-01 14:06:16,923 [salt.master      ][INFO    ] Clear payload received with command publish
2014-12-01 14:06:16,925 [salt.utils.event ][DEBUG   ] Sending event - data = {'_stamp': '2014-12-01T14:06:16.924474', 'minions': ['awingu']}
2014-12-01 14:06:16,927 [salt.utils.event ][DEBUG   ] Sending event - data = {'tgt_type': 'glob', 'jid': '20141201140616923716', 'tgt': '*', '_stamp': '2014-12-01T14:06:16.926372', 'user': 'root', 'arg': ['20141201140511389244'], 'fun': 'saltutil.find_job', 'minions': ['awingu']}
2014-12-01 14:06:16,928 [salt.utils.event ][DEBUG   ] Sending event - data = {'tgt_type': 'glob', 'jid': '20141201140616923716', 'tgt': '*', '_stamp': '2014-12-01T14:06:16.928203', 'user': 'root', 'arg': ['20141201140511389244'], 'fun': 'saltutil.find_job', 'minions': ['awingu']}
2014-12-01 14:06:16,930 [salt.master      ][INFO    ] User root Published command saltutil.find_job with jid 20141201140616923716
2014-12-01 14:06:16,931 [salt.master      ][DEBUG   ] Published command details {'tgt_type': 'glob', 'jid': '20141201140616923716', 'tgt': '*', 'ret': '', 'user': 'root', 'arg': ['20141201140511389244'], 'fun': 'saltutil.find_job'}
2014-12-01 14:06:16,980 [salt.master      ][INFO    ] Clear payload received with command _auth
2014-12-01 14:06:16,980 [salt.master      ][INFO    ] Authentication request from awingu
2014-12-01 14:06:16,980 [salt.master      ][INFO    ] Authentication accepted from awingu
2014-12-01 14:06:17,073 [salt.utils.event ][DEBUG   ] Sending event - data = {'id': 'awingu', '_stamp': '2014-12-01T14:06:17.073252', 'result': True, 'pub': '-----BEGIN PUBLIC KEY-----\nMIICIjANBgkqhkiG9w0BAQEFAAOCAg8AMIICCgKCAgEA59rxDBn1Q8kaMYuNsb0S\nyrFKEHlhFw/gNTRiAphS8pGoZsYwFvTwYm/J3LmrsxP0HtU6m7vNXGK1LnvVfgP1\nKSjnkv49Q6IPcz7Nyqfzz9gyxz5fAsAzGRj4iDj4qGPRjv60PgEujYUTH4N8nhTY\noKW8hIClyXh2eiX5mjb4kY/98KXsPeSRjTQnBTMkvXlXSHllKoCKjgD3FBAVZF/m\ncRNAUvaPIGvZiaracd6cDStT3GXeK9PxCBzpL9Hg7QH28myLaVwcDNPe5MESFpvS\nu3TL2wWaIURQWAndg28lqDEg9MSp8jRy/nViy3O7RaVypGQ0ySLEjX0adv1EC0w2\nFh0wvktYXa2r7ixL9OdKbGgExrZSWv+T5VR8QwndAaJmwVkHENndLv5JMq+eLXLx\nlBdaHLZkYf/S2c5OtZC7LlNhEHNYrSGqriUBdOIHpT1NFabgzAkH3QZY+BgXf/un\nCq4HWFJJL8TWDTLeJm1xSu3n6ylwiaGZFSn/Rqig3P2c3urgQx662eVcSD7YjmW3\nN2Hp6Zrl7DqU/sw2pF5qEFcc2zdJpLycZlXFeVpBcgaPh4Ph8mWSPcxUPij2638T\nMZLZZsOfYXM1GSQiqHsdSFeAcY1RdPyuJKw8y64hFF7lsVF5/qS4xqGbMp3i0GeA\nPe90QbaJPoKcqrrJ2WfEEBcCAwEAAQ==\n-----END PUBLIC KEY-----\n', 'act': 'accept'}
2014-12-01 14:06:26,735 [salt.master      ][INFO    ] Clear payload received with command publish
2014-12-01 14:06:26,736 [salt.utils.event ][DEBUG   ] Sending event - data = {'_stamp': '2014-12-01T14:06:26.735978', 'minions': ['awingu']}
2014-12-01 14:06:26,736 [salt.utils.event ][DEBUG   ] Sending event - data = {'tgt_type': 'list', 'jid': '20141201140626735604', 'tgt': 'awingu', '_stamp': '2014-12-01T14:06:26.736329', 'user': 'root', 'arg': ['services.dns', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls', 'minions': ['awingu']}
2014-12-01 14:06:26,737 [salt.utils.event ][DEBUG   ] Sending event - data = {'tgt_type': 'list', 'jid': '20141201140626735604', 'tgt': 'awingu', '_stamp': '2014-12-01T14:06:26.736586', 'user': 'root', 'arg': ['services.dns', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls', 'minions': ['awingu']}
2014-12-01 14:06:26,737 [salt.master      ][INFO    ] User root Published command state.sls with jid 20141201140626735604
2014-12-01 14:06:26,737 [salt.master      ][DEBUG   ] Published command details {'tgt_type': 'list', 'jid': '20141201140626735604', 'tgt': 'awingu', 'ret': {}, 'user': 'root', 'arg': ['services.dns', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls'}
2014-12-01 14:06:26,769 [salt.master      ][INFO    ] AES payload received with command _return
2014-12-01 14:06:26,769 [salt.master      ][INFO    ] Got return from awingu for job 20141201140616923716
2014-12-01 14:06:26,769 [salt.utils.event ][DEBUG   ] Sending event - data = {'fun_args': ['20141201140511389244'], 'jid': '20141201140616923716', 'return': {'tgt_type': 'glob', 'jid': '20141201140511389244', 'tgt': '*', 'pid': 5298, 'ret': {}, 'user': 'root', 'arg': ['bootstrap,packages.circus,packages.diamond,packages.logstash', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls'}, 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2014-12-01T14:06:26.769319', 'fun': 'saltutil.find_job', 'id': 'awingu'}
2014-12-01 14:06:26,770 [salt.utils.event ][DEBUG   ] Sending event - data = {'fun_args': ['20141201140511389244'], 'jid': '20141201140616923716', 'return': {'tgt_type': 'glob', 'jid': '20141201140511389244', 'tgt': '*', 'pid': 5298, 'ret': {}, 'user': 'root', 'arg': ['bootstrap,packages.circus,packages.diamond,packages.logstash', {'concurrent': False, 'saltenv': 'base', '__kwarg__': True}], 'fun': 'state.sls'}, 'retcode': 0, 'success': True, 'cmd': '_return', '_stamp': '2014-12-01T14:06:26.769699', 'fun': 'saltutil.find_job', 'id': 'awingu'}
2014-12-01 14:06:26,785 [salt.master      ][INFO    ] Clear payload received with command _auth
2014-12-01 14:06:26,786 [salt.master      ][INFO    ] Authentication request from awingu
2014-12-01 14:06:26,786 [salt.master      ][INFO    ] Authentication accepted from awingu
2014-12-01 14:06:27,018 [salt.utils.event ][DEBUG   ] Sending event - data = {'id': 'awingu', '_stamp': '2014-12-01T14:06:27.017407', 'result': True, 'pub': '-----BEGIN PUBLIC KEY-----\nMIICIjANBgkqhkiG9w0BAQEFAAOCAg8AMIICCgKCAgEA59rxDBn1Q8kaMYuNsb0S\nyrFKEHlhFw/gNTRiAphS8pGoZsYwFvTwYm/J3LmrsxP0HtU6m7vNXGK1LnvVfgP1\nKSjnkv49Q6IPcz7Nyqfzz9gyxz5fAsAzGRj4iDj4qGPRjv60PgEujYUTH4N8nhTY\noKW8hIClyXh2eiX5mjb4kY/98KXsPeSRjTQnBTMkvXlXSHllKoCKjgD3FBAVZF/m\ncRNAUvaPIGvZiaracd6cDStT3GXeK9PxCBzpL9Hg7QH28myLaVwcDNPe5MESFpvS\nu3TL2wWaIURQWAndg28lqDEg9MSp8jRy/nViy3O7RaVypGQ0ySLEjX0adv1EC0w2\nFh0wvktYXa2r7ixL9OdKbGgExrZSWv+T5VR8QwndAaJmwVkHENndLv5JMq+eLXLx\nlBdaHLZkYf/S2c5OtZC7LlNhEHNYrSGqriUBdOIHpT1NFabgzAkH3QZY+BgXf/un\nCq4HWFJJL8TWDTLeJm1xSu3n6ylwiaGZFSn/Rqig3P2c3urgQx662eVcSD7YjmW3\nN2Hp6Zrl7DqU/sw2pF5qEFcc2zdJpLycZlXFeVpBcgaPh4Ph8mWSPcxUPij2638T\nMZLZZsOfYXM1GSQiqHsdSFeAcY1RdPyuJKw8y64hFF7lsVF5/qS4xqGbMp3i0GeA\nPe90QbaJPoKcqrrJ2WfEEBcCAwEAAQ==\n-----END PUBLIC KEY-----\n', 'act': 'accept'}
2014-12-01 14:06:28,413 [salt.master      ][INFO    ] AES payload received with command _return
2014-12-01 14:06:28,414 [salt.master      ][INFO    ] Got return from awingu for job 20141201140626735604
2014-12-01 14:06:28,415 [salt.utils.event ][DEBUG   ] Sending event - data = {'fun_args': ['services.dns', {'concurrent': False, 'saltenv': 'base'}], 'jid': '20141201140626735604', 'return': ['The function "state.sls" is running as PID 5298 and was started at 2014, Dec 01 14:05:11.389244 with jid 20141201140511389244'], 'retcode': 1, 'success': True, 'cmd': '_return', '_stamp': '2014-12-01T14:06:28.414676', 'fun': 'state.sls', 'id': 'awingu', 'out': 'highstate'}
2014-12-01 14:06:28,416 [salt.utils.event ][DEBUG   ] Sending event - data = {'fun_args': ['services.dns', {'concurrent': False, 'saltenv': 'base'}], 'jid': '20141201140626735604', 'return': ['The function "state.sls" is running as PID 5298 and was started at 2014, Dec 01 14:05:11.389244 with jid 20141201140511389244'], 'retcode': 1, 'success': True, 'cmd': '_return', '_stamp': '2014-12-01T14:06:28.415561', 'fun': 'state.sls', 'id': 'awingu', 'out': 'highstate'}
2014-12-01 14:06:28,458 [salt.state       ][ERROR   ] Run failed on minions: awingu
Failures:
    ^[[01;31mawingu:^[[0m
        ^[[01;31mData failed to compile:^[[0m
    ^[[01;31m----------
        The function "state.sls" is running as PID 5298 and was started at 2014, Dec 01 14:05:11.389244 with jid 20141201140511389244^[[0m

Seems like one of the find_job tasks would've timed out, but can't really see any evidence of it in the log?

[UtahDave]

@bernieke can you post a sanitized version of your orchestrate.sls as well as the output of :

salt <minion> test.versions_report

and

salt-master --versions-report

[bernieke]

The minion and the master are the same machine.

root@awingu ❯ salt 'awingu' test.versions_report
awingu:
               Salt: 2014.7.0
             Python: 2.7.6 (default, Mar 22 2014, 22:59:56)
             Jinja2: 2.7.2
           M2Crypto: 0.21.1
     msgpack-python: 0.3.0
       msgpack-pure: Not Installed
           pycrypto: 2.6.1
            libnacl: Not Installed
             PyYAML: 3.10
              ioflo: Not Installed
              PyZMQ: 14.0.1
               RAET: Not Installed
                ZMQ: 4.0.4
               Mako: Not Installed
~
root@awingu ❯ salt-master --versions-report
           Salt: 2014.7.0
         Python: 2.7.6 (default, Mar 22 2014, 22:59:56)
         Jinja2: 2.7.2
       M2Crypto: 0.21.1
 msgpack-python: 0.3.0
   msgpack-pure: Not Installed
       pycrypto: 2.6.1
        libnacl: Not Installed
         PyYAML: 3.10
          ioflo: Not Installed
          PyZMQ: 14.3.1
           RAET: Not Installed
            ZMQ: 4.0.4
           Mako: Not Installed

I'm not sure what you're looking for in my states? This is my complete orchestration.sls:

root@awingu ❯ cat /srv/salt/orchestration.sls 
common:
  salt.state:
    - tgt: '*'
    - sls:
      - bootstrap
      - packages.circus
      - packages.diamond
      - packages.logstash

dns_server:
  salt.state:
    - require:
      - salt: common
    - tgt_type: list
    - tgt: '{{ pillar.services.dns|join(',') }}'
    - sls: services.dns

dns:
  salt.state:
    - require:
      - salt: common
      - salt: dns_server
    - tgt: '*'
    - sls: dns

mq:
  salt.state:
    - require:
      - salt: dns
    - tgt: '{{ pillar.services.mq[0] }}'
    - sls: services.mq

all:
  salt.state:
    - require:
      - salt: dns
      - salt: mq
    - tgt: '*'
    - highstate: true

populate_metering:
  salt.state:
    - require:
      - salt: all
    - tgt: '{{ pillar.services.metering[0] }}'
    - sls: populate_metering

restart:
  salt.state:
    - require:
      - salt: all
      - salt: populate_metering
    - tgt: '*'
    - sls: restart

populate_frontend:
  salt.state:
    - require:
      - salt: restart
    - tgt: '{{ pillar.services.frontend[0] }}'
    - sls: populate_frontend

Do note that the states work fine when there's no timeout conditions being reached.

[rallytime]

Hey @bernieke - sorry we never came back around here. Is this still an issue on the latest release (2014.7.5) for you? Have you had a chance to try this again?

[bernieke]

The issue is still there on 2014.7.5

I've just verified it by setting the timeout to 1sec, and executing a salt-run to 15 nodes.

One of the states run by salt-run (the restart state from the above orchestration) only went through on 5 of the 15 nodes, but salt-run happily continued with the next state (populate_frontend), without even so much as a warning printed. (In the output you see the same as you would normally, except it only mentions 5 minion names in the list of updated nodes in the "States ran successfully" comment part of the output instead of the 15 minion names you otherwise see.)

----------
          ID: restart
    Function: salt.state
      Result: True
     Comment: States ran successfully. Updating bernie-timeout-node12, bernie-timeout-node1, bernie-timeout-node11, bernie-timeout-node3, bernie-timeout-node4.
     Started: 10:38:15.569083
    Duration: 15929.754 ms
     Changes: