Skip to content

Instantly share code, notes, and snippets.

@aphor

aphor/debug.out

Last active May 29, 2019 21:08
Show Gist options
  • Star 1 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save aphor/9e94a6aef663546575f5d0a13af1e825 to your computer and use it in GitHub Desktop.
Save aphor/9e94a6aef663546575f5d0a13af1e825 to your computer and use it in GitHub Desktop.
Download ZIP
salt orchestration rolling example
Raw
debug.out
$ sudo salt-run --log-level=debug state.orchestrate orch.roll
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] Configuration file path: /opt/local/etc/salt/master
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG ] LazyLoaded state.orchestrate
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/new; data = {'fun': 'runner.state.orchestrate', 'jid': '20180407103835034686', 'user': 'sudo_aphor', 'fun_args': ['orch.roll', {'orchestration_jid': '20180407103835034686'}], '_stamp': '2018-04-07T15:38:39.963441'}
...
[DEBUG ] In saltenv 'base', looking at rel_path 'orch/roll.sls' to resolve 'salt://orch/roll.sls'
[DEBUG ] In saltenv 'base', ** considering ** path '/opt/local/var/cache/salt/master/files/base/orch/roll.sls' to resolve 'salt://orch/roll.sls'
[DEBUG ] Fetching file from saltenv 'base', ** attempting ** 'salt://orch/roll.sls'
[DEBUG ] No dest file found
[INFO ] Fetching file from saltenv 'base', ** done ** 'orch/roll.sls'
[DEBUG ] compile template: /opt/local/var/cache/salt/master/files/base/orch/roll.sls
[DEBUG ] Jinja search path: ['/opt/local/var/cache/salt/master/files/base']
[DEBUG ] LazyLoaded roots.envs
[DEBUG ] Could not LazyLoad roots.init: 'roots.init' is not available.
[PROFILE ] Time (in seconds) to render '/opt/local/var/cache/salt/master/files/base/orch/roll.sls' using 'jinja' renderer: 0.026040077209472656
[DEBUG ] Rendered data from file: /opt/local/var/cache/salt/master/files/base/orch/roll.sls:
prepare for step 1:
salt.function:
- name: test.ping
- tgt: 'un'
step 1:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 1
- kwarg:
bg: True
- arg:
- |
sleep 18 &&
salt-call event.send 'rolling/step/1/success'
step 1 success:
salt.runner:
- name: poc.waitfor
- arg:
- 'rolling/step/1/success'
- kwarg:
timeout: 600
prepare for step 2:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 1 success
step 2:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 2
- kwarg:
bg: True
- arg:
- |
sleep 23 &&
salt-call event.send 'rolling/step/2/success'
step 2 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 2
- arg:
- 'rolling/step/2/success'
- kwarg:
timeout: 600
prepare for step 3:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 2 success
step 3:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 3
- kwarg:
bg: True
- arg:
- |
sleep 44 &&
salt-call event.send 'rolling/step/3/success'
step 3 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 3
- arg:
- 'rolling/step/3/success'
- kwarg:
timeout: 600
prepare for step 4:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 3 success
step 4:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 4
- kwarg:
bg: True
- arg:
- |
sleep 17 &&
salt-call event.send 'rolling/step/4/success'
step 4 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 4
- arg:
- 'rolling/step/4/success'
- kwarg:
timeout: 600
prepare for step 5:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 4 success
step 5:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 5
- kwarg:
bg: True
- arg:
- |
sleep 27 &&
salt-call event.send 'rolling/step/5/success'
step 5 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 5
- arg:
- 'rolling/step/5/success'
- kwarg:
timeout: 600
[DEBUG ] Results of YAML rendering:
OrderedDict([('prepare for step 1', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')])])])), ('step 1', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 1'])]), OrderedDict([('kwarg', OrderedDict([('bg', True)]))]), OrderedDict([('arg', ["sleep 18 &&\nsalt-call event.send 'rolling/step/1/success'\n"])])])])), ('step 1 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('arg', ['rolling/step/1/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 2', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 1 success'])])])])), ('step 2', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 2'])]), OrderedDict([('kwarg', OrderedDict([('bg', True)]))]), OrderedDict([('arg', ["sleep 23 &&\nsalt-call event.send 'rolling/step/2/success'\n"])])])])), ('step 2 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 2'])]), OrderedDict([('arg', ['rolling/step/2/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 3', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 2 success'])])])])), ('step 3', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 3'])]), OrderedDict([('kwarg', OrderedDict([('bg', True)]))]), OrderedDict([('arg', ["sleep 44 &&\nsalt-call event.send 'rolling/step/3/success'\n"])])])])), ('step 3 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 3'])]), OrderedDict([('arg', ['rolling/step/3/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 4', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 3 success'])])])])), ('step 4', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 4'])]), OrderedDict([('kwarg', OrderedDict([('bg', True)]))]), OrderedDict([('arg', ["sleep 17 &&\nsalt-call event.send 'rolling/step/4/success'\n"])])])])), ('step 4 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 4'])]), OrderedDict([('arg', ['rolling/step/4/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 5', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 4 success'])])])])), ('step 5', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 5'])]), OrderedDict([('kwarg', OrderedDict([('bg', True)]))]), OrderedDict([('arg', ["sleep 27 &&\nsalt-call event.send 'rolling/step/5/success'\n"])])])])), ('step 5 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 5'])]), OrderedDict([('arg', ['rolling/step/5/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])]))])
[PROFILE ] Time (in seconds) to render '/opt/local/var/cache/salt/master/files/base/orch/roll.sls' using 'yaml' renderer: 0.0339810848236084
[DEBUG ] LazyLoaded config.option
[DEBUG ] LazyLoaded salt.function
[INFO ] Running state [test.ping] at time 10:38:41.403375
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:38:41.405968'}
[DEBUG ] LazyLoaded saltutil.cmd
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/ff/6bbeba84ef1a0e75221cb0fca02125ff4a6e7d40df29b8fee62fbec08c3e7a/.minions.p
[DEBUG ] get_iter_returns for jid 20180407103841526330 sent to {'un'} will timeout at 10:38:46.536802
[DEBUG ] jid 20180407103841526330 return from un
[DEBUG ] jid 20180407103841526330 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 10:38:41.694594 (duration_in_ms=291.219)
[INFO ] Running state [cmd.shell] at time 10:38:41.695206
[INFO ] Executing state salt.function for [cmd.shell]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'cmd.shell', 'args': {'arg': ["sleep 18 &&\nsalt-call event.send 'rolling/step/1/success'\n"], 'kwarg': OrderedDict([('bg', True)]), 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:38:41.697141'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/92/63e59da5d3d5ddb5f3b12f510d6076db12eea1927b71d8f2f2447d22b28cb9/.minions.p
[DEBUG ] get_iter_returns for jid 20180407103841809759 sent to {'un'} will timeout at 10:38:46.819880
[DEBUG ] jid 20180407103841809759 return from un
[DEBUG ] jid 20180407103841809759 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': None}}
[INFO ] Completed state [cmd.shell] at time 10:38:41.977301 (duration_in_ms=282.095)
[INFO ] Running state [poc.waitfor] at time 10:38:41.977506
[INFO ] Executing state salt.runner for [poc.waitfor]
[DEBUG ] LazyLoaded poc.waitfor
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'runner', 'name': 'poc.waitfor', 'args': ['rolling/step/1/success'], 'kwargs': OrderedDict([('timeout', 600)]), '_stamp': '2018-04-07T15:38:41.990299'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103843123564/new; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407103843123564', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/1/success', {'timeout': 600}], '_stamp': '2018-04-07T15:38:43.145715'}
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407103843123564: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407103843123564/ret; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407103843123564', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/1/success', {'timeout': 600}], '_stamp': '2018-04-07T15:39:01.025471', 'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/1/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407103901003069', '__pub_pid': 15057, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:39:01.019490'}}), 'success': True}
[INFO ] Runner completed: 20180407103843123564
[INFO ] {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/1/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407103901003069', '__pub_pid': 15057, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:39:01.019490'}})}
[INFO ] Completed state [poc.waitfor] at time 10:39:01.026545 (duration_in_ms=19049.038)
[INFO ] Running state [test.ping] at time 10:39:01.027164
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:39:01.029167'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/7c/015e24e2e78a256e3a78e131e88b61963d3a61656f6a5a94cde52a206f0a0f/.minions.p
[DEBUG ] get_iter_returns for jid 20180407103901143255 sent to {'un'} will timeout at 10:39:06.153733
[DEBUG ] jid 20180407103901143255 return from un
[DEBUG ] jid 20180407103901143255 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 10:39:01.316281 (duration_in_ms=289.116)
[INFO ] Running state [cmd.shell] at time 10:39:01.316950
[INFO ] Executing state salt.function for [cmd.shell]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'cmd.shell', 'args': {'arg': ["sleep 23 &&\nsalt-call event.send 'rolling/step/2/success'\n"], 'kwarg': OrderedDict([('bg', True)]), 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:39:01.318986'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/cb/e35eac9ec7b1e289df08eb1e7c61078294a155bde605f865906e98ab14e04d/.minions.p
[DEBUG ] get_iter_returns for jid 20180407103901432876 sent to {'un'} will timeout at 10:39:06.443709
[DEBUG ] jid 20180407103901432876 return from un
[DEBUG ] jid 20180407103901432876 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': None}}
[INFO ] Completed state [cmd.shell] at time 10:39:01.601893 (duration_in_ms=284.943)
[INFO ] Running state [poc.waitfor] at time 10:39:01.602264
[INFO ] Executing state salt.runner for [poc.waitfor]
[DEBUG ] LazyLoaded poc.waitfor
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'runner', 'name': 'poc.waitfor', 'args': ['rolling/step/2/success'], 'kwargs': OrderedDict([('timeout', 600)]), '_stamp': '2018-04-07T15:39:01.614592'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103902735246/new; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407103902735246', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/2/success', {'timeout': 600}], '_stamp': '2018-04-07T15:39:02.759361'}
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407103902735246: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407103902735246/ret; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407103902735246', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/2/success', {'timeout': 600}], '_stamp': '2018-04-07T15:39:25.658782', 'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/2/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407103925637688', '__pub_pid': 15116, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:39:25.653939'}}), 'success': True}
[INFO ] Runner completed: 20180407103902735246
[INFO ] {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/2/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407103925637688', '__pub_pid': 15116, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:39:25.653939'}})}
[INFO ] Completed state [poc.waitfor] at time 10:39:25.659796 (duration_in_ms=24057.531)
[INFO ] Running state [test.ping] at time 10:39:25.660517
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:39:25.662472'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/d3/f9f50baa25fb195187c8fd550a7fa71493a91547350de13a6d72ed977c2ab9/.minions.p
[DEBUG ] get_iter_returns for jid 20180407103925775594 sent to {'un'} will timeout at 10:39:30.786645
[DEBUG ] jid 20180407103925775594 return from un
[DEBUG ] jid 20180407103925775594 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 10:39:25.947920 (duration_in_ms=287.402)
[INFO ] Running state [cmd.shell] at time 10:39:25.948595
[INFO ] Executing state salt.function for [cmd.shell]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'cmd.shell', 'args': {'arg': ["sleep 44 &&\nsalt-call event.send 'rolling/step/3/success'\n"], 'kwarg': OrderedDict([('bg', True)]), 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:39:25.950616'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/28/d1e75b77eca3221503251895dec6ad77b9b2a2a2c869b02c6728ac0df1c5a4/.minions.p
[DEBUG ] get_iter_returns for jid 20180407103926065711 sent to {'un'} will timeout at 10:39:31.076019
[DEBUG ] jid 20180407103926065711 return from un
[DEBUG ] jid 20180407103926065711 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': None}}
[INFO ] Completed state [cmd.shell] at time 10:39:26.237931 (duration_in_ms=289.335)
[INFO ] Running state [poc.waitfor] at time 10:39:26.238301
[INFO ] Executing state salt.runner for [poc.waitfor]
[DEBUG ] LazyLoaded poc.waitfor
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'runner', 'name': 'poc.waitfor', 'args': ['rolling/step/3/success'], 'kwargs': OrderedDict([('timeout', 600)]), '_stamp': '2018-04-07T15:39:26.255032'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103927381219/new; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407103927381219', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/3/success', {'timeout': 600}], '_stamp': '2018-04-07T15:39:27.407616'}
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407103927381219: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407103927381219/ret; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407103927381219', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/3/success', {'timeout': 600}], '_stamp': '2018-04-07T15:40:11.278290', 'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/3/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104011257564', '__pub_pid': 15176, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:11.273658'}}), 'success': True}
[INFO ] Runner completed: 20180407103927381219
[INFO ] {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/3/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104011257564', '__pub_pid': 15176, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:11.273658'}})}
[INFO ] Completed state [poc.waitfor] at time 10:40:11.279383 (duration_in_ms=45041.082)
[INFO ] Running state [test.ping] at time 10:40:11.280280
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:40:11.282256'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/fa/4e9ee468c814cb2a53212c6baee0d7c914d067849603f3b8f0282cf5a7294a/.minions.p
[DEBUG ] get_iter_returns for jid 20180407104011393650 sent to {'un'} will timeout at 10:40:16.404178
[DEBUG ] jid 20180407104011393650 return from un
[DEBUG ] jid 20180407104011393650 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 10:40:11.563678 (duration_in_ms=283.397)
[INFO ] Running state [cmd.shell] at time 10:40:11.564293
[INFO ] Executing state salt.function for [cmd.shell]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'cmd.shell', 'args': {'arg': ["sleep 17 &&\nsalt-call event.send 'rolling/step/4/success'\n"], 'kwarg': OrderedDict([('bg', True)]), 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:40:11.566229'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/d6/dea3013020e9ef6630f9c55b7ca682405ad8bc2cf8d84ddae16d1b9b192c19/.minions.p
[DEBUG ] get_iter_returns for jid 20180407104011677295 sent to {'un'} will timeout at 10:40:16.687809
[DEBUG ] jid 20180407104011677295 return from un
[DEBUG ] jid 20180407104011677295 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': None}}
[INFO ] Completed state [cmd.shell] at time 10:40:11.853459 (duration_in_ms=289.164)
[INFO ] Running state [poc.waitfor] at time 10:40:11.853827
[INFO ] Executing state salt.runner for [poc.waitfor]
[DEBUG ] LazyLoaded poc.waitfor
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'runner', 'name': 'poc.waitfor', 'args': ['rolling/step/4/success'], 'kwargs': OrderedDict([('timeout', 600)]), '_stamp': '2018-04-07T15:40:11.866801'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407104012996844/new; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407104012996844', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/4/success', {'timeout': 600}], '_stamp': '2018-04-07T15:40:13.019574'}
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407104012996844: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407104012996844/ret; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407104012996844', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/4/success', {'timeout': 600}], '_stamp': '2018-04-07T15:40:29.897595', 'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/4/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104029876622', '__pub_pid': 15235, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:29.892871'}}), 'success': True}
[INFO ] Runner completed: 20180407104012996844
[INFO ] {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/4/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104029876622', '__pub_pid': 15235, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:29.892871'}})}
[INFO ] Completed state [poc.waitfor] at time 10:40:29.898628 (duration_in_ms=18044.801)
[INFO ] Running state [test.ping] at time 10:40:29.899376
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:40:29.901348'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/a9/404a16d89fb8fc689129ea4df6ee65855316fb4b93b78d9042733d6b3635c1/.minions.p
[DEBUG ] get_iter_returns for jid 20180407104030014160 sent to {'un'} will timeout at 10:40:35.024049
[DEBUG ] jid 20180407104030014160 return from un
[DEBUG ] jid 20180407104030014160 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 10:40:30.182687 (duration_in_ms=283.31)
[INFO ] Running state [cmd.shell] at time 10:40:30.183319
[INFO ] Executing state salt.function for [cmd.shell]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'function', 'tgt': 'un', 'name': 'cmd.shell', 'args': {'arg': ["sleep 27 &&\nsalt-call event.send 'rolling/step/5/success'\n"], 'kwarg': OrderedDict([('bg', True)]), 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T15:40:30.185313'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/e9/22ae069ce62180d799fce2529825f9da5e0cc525cc3d362657e51ccf1229f0/.minions.p
[DEBUG ] get_iter_returns for jid 20180407104030296007 sent to {'un'} will timeout at 10:40:35.306329
[DEBUG ] jid 20180407104030296007 return from un
[DEBUG ] jid 20180407104030296007 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': None}}
[INFO ] Completed state [cmd.shell] at time 10:40:30.464526 (duration_in_ms=281.207)
[INFO ] Running state [poc.waitfor] at time 10:40:30.464890
[INFO ] Executing state salt.runner for [poc.waitfor]
[DEBUG ] LazyLoaded poc.waitfor
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/args; data = {'type': 'runner', 'name': 'poc.waitfor', 'args': ['rolling/step/5/success'], 'kwargs': OrderedDict([('timeout', 600)]), '_stamp': '2018-04-07T15:40:30.477455'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407104031612117/new; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407104031612117', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/5/success', {'timeout': 600}], '_stamp': '2018-04-07T15:40:31.633461'}
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407104031612117: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407104031612117/ret; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407104031612117', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/5/success', {'timeout': 600}], '_stamp': '2018-04-07T15:40:58.511189', 'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/5/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104058489792', '__pub_pid': 15294, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:58.506225'}}), 'success': True}
[INFO ] Runner completed: 20180407104031612117
[INFO ] {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/5/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104058489792', '__pub_pid': 15294, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:58.506225'}})}
[INFO ] Completed state [poc.waitfor] at time 10:40:58.512267 (duration_in_ms=28047.376)
[DEBUG ] File /opt/local/var/cache/salt/master/accumulator/4427119864 does not exist, no need to cleanup
[DEBUG ] LazyLoaded state.check_result
[DEBUG ] LazyLoaded state.check_result
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407103835034686: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407103835034686/ret; data = {'fun': 'runner.state.orchestrate', 'jid': '20180407103835034686', 'user': 'sudo_aphor', 'fun_args': ['orch.roll', {'orchestration_jid': '20180407103835034686'}], '_stamp': '2018-04-07T15:40:58.517453', 'return': {'data': {'salt-master.local_master': {'salt_|-prepare for step 1_|-test.ping_|-function': {'name': 'test.ping', 'changes': {'out': 'highstate', 'ret': {'un': True}}, 'comment': 'Function ran successfully. Function test.ping ran on un.', 'result': True, '__jid__': '20180407103841526330', '__sls__': 'orch.roll', '__run_num__': 0, 'start_time': '10:38:41.403375', 'duration': 291.219, '__id__': 'prepare for step 1'}, 'salt_|-step 1_|-cmd.shell_|-function': {'name': 'cmd.shell', 'changes': {'out': 'highstate', 'ret': {'un': None}}, 'comment': 'Function ran successfully. Function cmd.shell ran on un.', 'result': True, '__jid__': '20180407103841809759', '__sls__': 'orch.roll', '__run_num__': 1, 'start_time': '10:38:41.695206', 'duration': 282.095, '__id__': 'step 1'}, 'salt_|-step 1 success_|-poc.waitfor_|-runner': {'name': 'poc.waitfor', 'changes': {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/1/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407103901003069', '__pub_pid': 15057, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:39:01.019490'}})}, 'result': True, 'comment': "Runner function 'poc.waitfor' executed.", '__orchestration__': True, '__jid__': '20180407103843123564', '__sls__': 'orch.roll', '__run_num__': 2, 'start_time': '10:38:41.977507', 'duration': 19049.038, '__id__': 'step 1 success'}, 'salt_|-prepare for step 2_|-test.ping_|-function': {'name': 'test.ping', 'changes': {'out': 'highstate', 'ret': {'un': True}}, 'comment': 'Function ran successfully. Function test.ping ran on un.', 'result': True, '__jid__': '20180407103901143255', '__sls__': 'orch.roll', '__run_num__': 3, 'start_time': '10:39:01.027165', 'duration': 289.116, '__id__': 'prepare for step 2'}, 'salt_|-step 2_|-cmd.shell_|-function': {'name': 'cmd.shell', 'changes': {'out': 'highstate', 'ret': {'un': None}}, 'comment': 'Function ran successfully. Function cmd.shell ran on un.', 'result': True, '__jid__': '20180407103901432876', '__sls__': 'orch.roll', '__run_num__': 4, 'start_time': '10:39:01.316950', 'duration': 284.943, '__id__': 'step 2'}, 'salt_|-step 2 success_|-poc.waitfor_|-runner': {'name': 'poc.waitfor', 'changes': {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/2/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407103925637688', '__pub_pid': 15116, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:39:25.653939'}})}, 'result': True, 'comment': "Runner function 'poc.waitfor' executed.", '__orchestration__': True, '__jid__': '20180407103902735246', '__sls__': 'orch.roll', '__run_num__': 5, 'start_time': '10:39:01.602265', 'duration': 24057.531, '__id__': 'step 2 success'}, 'salt_|-prepare for step 3_|-test.ping_|-function': {'name': 'test.ping', 'changes': {'out': 'highstate', 'ret': {'un': True}}, 'comment': 'Function ran successfully. Function test.ping ran on un.', 'result': True, '__jid__': '20180407103925775594', '__sls__': 'orch.roll', '__run_num__': 6, 'start_time': '10:39:25.660518', 'duration': 287.402, '__id__': 'prepare for step 3'}, 'salt_|-step 3_|-cmd.shell_|-function': {'name': 'cmd.shell', 'changes': {'out': 'highstate', 'ret': {'un': None}}, 'comment': 'Function ran successfully. Function cmd.shell ran on un.', 'result': True, '__jid__': '20180407103926065711', '__sls__': 'orch.roll', '__run_num__': 7, 'start_time': '10:39:25.948596', 'duration': 289.335, '__id__': 'step 3'}, 'salt_|-step 3 success_|-poc.waitfor_|-runner': {'name': 'poc.waitfor', 'changes': {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/3/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104011257564', '__pub_pid': 15176, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:11.273658'}})}, 'result': True, 'comment': "Runner function 'poc.waitfor' executed.", '__orchestration__': True, '__jid__': '20180407103927381219', '__sls__': 'orch.roll', '__run_num__': 8, 'start_time': '10:39:26.238301', 'duration': 45041.082, '__id__': 'step 3 success'}, 'salt_|-prepare for step 4_|-test.ping_|-function': {'name': 'test.ping', 'changes': {'out': 'highstate', 'ret': {'un': True}}, 'comment': 'Function ran successfully. Function test.ping ran on un.', 'result': True, '__jid__': '20180407104011393650', '__sls__': 'orch.roll', '__run_num__': 9, 'start_time': '10:40:11.280281', 'duration': 283.397, '__id__': 'prepare for step 4'}, 'salt_|-step 4_|-cmd.shell_|-function': {'name': 'cmd.shell', 'changes': {'out': 'highstate', 'ret': {'un': None}}, 'comment': 'Function ran successfully. Function cmd.shell ran on un.', 'result': True, '__jid__': '20180407104011677295', '__sls__': 'orch.roll', '__run_num__': 10, 'start_time': '10:40:11.564295', 'duration': 289.164, '__id__': 'step 4'}, 'salt_|-step 4 success_|-poc.waitfor_|-runner': {'name': 'poc.waitfor', 'changes': {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/4/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104029876622', '__pub_pid': 15235, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:29.892871'}})}, 'result': True, 'comment': "Runner function 'poc.waitfor' executed.", '__orchestration__': True, '__jid__': '20180407104012996844', '__sls__': 'orch.roll', '__run_num__': 11, 'start_time': '10:40:11.853827', 'duration': 18044.801, '__id__': 'step 4 success'}, 'salt_|-prepare for step 5_|-test.ping_|-function': {'name': 'test.ping', 'changes': {'out': 'highstate', 'ret': {'un': True}}, 'comment': 'Function ran successfully. Function test.ping ran on un.', 'result': True, '__jid__': '20180407104030014160', '__sls__': 'orch.roll', '__run_num__': 12, 'start_time': '10:40:29.899377', 'duration': 283.31, '__id__': 'prepare for step 5'}, 'salt_|-step 5_|-cmd.shell_|-function': {'name': 'cmd.shell', 'changes': {'out': 'highstate', 'ret': {'un': None}}, 'comment': 'Function ran successfully. Function cmd.shell ran on un.', 'result': True, '__jid__': '20180407104030296007', '__sls__': 'orch.roll', '__run_num__': 13, 'start_time': '10:40:30.183319', 'duration': 281.207, '__id__': 'step 5'}, 'salt_|-step 5 success_|-poc.waitfor_|-runner': {'name': 'poc.waitfor', 'changes': {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/5/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407104058489792', '__pub_pid': 15294, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T15:40:58.506225'}})}, 'result': True, 'comment': "Runner function 'poc.waitfor' executed.", '__orchestration__': True, '__jid__': '20180407104031612117', '__sls__': 'orch.roll', '__run_num__': 14, 'start_time': '10:40:30.464891', 'duration': 28047.376, '__id__': 'step 5 success'}}}, 'outputter': 'highstate', 'retcode': 0}, 'success': True}
[DEBUG ] LazyLoaded highstate.output
[DEBUG ] LazyLoaded nested.output
[DEBUG ] LazyLoaded nested.output
[DEBUG ] LazyLoaded nested.output
[DEBUG ] LazyLoaded nested.output
[DEBUG ] LazyLoaded nested.output
salt-master.local_master:
----------
ID: prepare for step 1
Function: salt.function
Name: test.ping
Result: True
Comment: Function ran successfully. Function test.ping ran on un.
Started: 10:38:41.403375
Duration: 291.219 ms
Changes:
un:
True
----------
ID: step 1
Function: salt.function
Name: cmd.shell
Result: True
Comment: Function ran successfully. Function cmd.shell ran on un.
Started: 10:38:41.695206
Duration: 282.095 ms
Changes:
un:
----------
ID: step 1 success
Function: salt.runner
Name: poc.waitfor
Result: True
Comment: Runner function 'poc.waitfor' executed.
Started: 10:38:41.977507
Duration: 19049.038 ms
Changes:
----------
return:
- True
|_
----------
data:
----------
_stamp:
2018-04-07T15:39:01.019490
cmd:
_minion_event
data:
----------
__pub_fun:
event.send
__pub_jid:
20180407103901003069
__pub_pid:
15057
__pub_tgt:
salt-call
id:
un
tag:
rolling/step/1/success
----------
ID: prepare for step 2
Function: salt.function
Name: test.ping
Result: True
Comment: Function ran successfully. Function test.ping ran on un.
Started: 10:39:01.027165
Duration: 289.116 ms
Changes:
un:
True
----------
ID: step 2
Function: salt.function
Name: cmd.shell
Result: True
Comment: Function ran successfully. Function cmd.shell ran on un.
Started: 10:39:01.316950
Duration: 284.943 ms
Changes:
un:
----------
ID: step 2 success
Function: salt.runner
Name: poc.waitfor
Result: True
Comment: Runner function 'poc.waitfor' executed.
Started: 10:39:01.602265
Duration: 24057.531 ms
Changes:
----------
return:
- True
|_
----------
data:
----------
_stamp:
2018-04-07T15:39:25.653939
cmd:
_minion_event
data:
----------
__pub_fun:
event.send
__pub_jid:
20180407103925637688
__pub_pid:
15116
__pub_tgt:
salt-call
id:
un
tag:
rolling/step/2/success
----------
ID: prepare for step 3
Function: salt.function
Name: test.ping
Result: True
Comment: Function ran successfully. Function test.ping ran on un.
Started: 10:39:25.660518
Duration: 287.402 ms
Changes:
un:
True
----------
ID: step 3
Function: salt.function
Name: cmd.shell
Result: True
Comment: Function ran successfully. Function cmd.shell ran on un.
Started: 10:39:25.948596
Duration: 289.335 ms
Changes:
un:
----------
ID: step 3 success
Function: salt.runner
Name: poc.waitfor
Result: True
Comment: Runner function 'poc.waitfor' executed.
Started: 10:39:26.238301
Duration: 45041.082 ms
Changes:
----------
return:
- True
|_
----------
data:
----------
_stamp:
2018-04-07T15:40:11.273658
cmd:
_minion_event
data:
----------
__pub_fun:
event.send
__pub_jid:
20180407104011257564
__pub_pid:
15176
__pub_tgt:
salt-call
id:
un
tag:
rolling/step/3/success
----------
ID: prepare for step 4
Function: salt.function
Name: test.ping
Result: True
Comment: Function ran successfully. Function test.ping ran on un.
Started: 10:40:11.280281
Duration: 283.397 ms
Changes:
un:
True
----------
ID: step 4
Function: salt.function
Name: cmd.shell
Result: True
Comment: Function ran successfully. Function cmd.shell ran on un.
Started: 10:40:11.564295
Duration: 289.164 ms
Changes:
un:
----------
ID: step 4 success
Function: salt.runner
Name: poc.waitfor
Result: True
Comment: Runner function 'poc.waitfor' executed.
Started: 10:40:11.853827
Duration: 18044.801 ms
Changes:
----------
return:
- True
|_
----------
data:
----------
_stamp:
2018-04-07T15:40:29.892871
cmd:
_minion_event
data:
----------
__pub_fun:
event.send
__pub_jid:
20180407104029876622
__pub_pid:
15235
__pub_tgt:
salt-call
id:
un
tag:
rolling/step/4/success
----------
ID: prepare for step 5
Function: salt.function
Name: test.ping
Result: True
Comment: Function ran successfully. Function test.ping ran on un.
Started: 10:40:29.899377
Duration: 283.31 ms
Changes:
un:
True
----------
ID: step 5
Function: salt.function
Name: cmd.shell
Result: True
Comment: Function ran successfully. Function cmd.shell ran on un.
Started: 10:40:30.183319
Duration: 281.207 ms
Changes:
un:
----------
ID: step 5 success
Function: salt.runner
Name: poc.waitfor
Result: True
Comment: Runner function 'poc.waitfor' executed.
Started: 10:40:30.464891
Duration: 28047.376 ms
Changes:
----------
return:
- True
|_
----------
data:
----------
_stamp:
2018-04-07T15:40:58.506225
cmd:
_minion_event
data:
----------
__pub_fun:
event.send
__pub_jid:
20180407104058489792
__pub_pid:
15294
__pub_tgt:
salt-call
id:
un
tag:
rolling/step/5/success
Summary for salt-master.local_master
-------------
Succeeded: 15 (changed=10)
Failed: 0
-------------
Total states run: 15
Total run time: 137.101 s
[INFO ] Runner completed: 20180407103835034686
[DEBUG ] Runner return: {'outputter': 'highstate', 'retcode': 0}
Raw
parallel_step_debug.out
$ sudo salt-run --log-level=debug state.orchestrate orch.roll
...
[DEBUG ] In saltenv 'base', looking at rel_path 'orch/roll.sls' to resolve 'salt://orch/roll.sls'
[DEBUG ] In saltenv 'base', ** considering ** path '/opt/local/var/cache/salt/master/files/base/orch/roll.sls' to resolve 'salt://orch/roll.sls'
[DEBUG ] Fetching file from saltenv 'base', ** attempting ** 'salt://orch/roll.sls'
[DEBUG ] No dest file found
[INFO ] Fetching file from saltenv 'base', ** done ** 'orch/roll.sls'
[DEBUG ] compile template: /opt/local/var/cache/salt/master/files/base/orch/roll.sls
[DEBUG ] Jinja search path: ['/opt/local/var/cache/salt/master/files/base']
[DEBUG ] LazyLoaded roots.envs
[DEBUG ] Could not LazyLoad roots.init: 'roots.init' is not available.
[PROFILE ] Time (in seconds) to render '/opt/local/var/cache/salt/master/files/base/orch/roll.sls' using 'jinja' renderer: 0.02681112289428711
[DEBUG ] Rendered data from file: /opt/local/var/cache/salt/master/files/base/orch/roll.sls:
prepare for step 1:
salt.function:
- name: test.ping
- tgt: 'un'
step 1:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 1
- parallel: True
- kwarg:
bg: False
- arg:
- |
sleep 44 &&
salt-call event.send 'rolling/step/1/success'
step 1 success:
salt.runner:
- name: poc.waitfor
- arg:
- 'rolling/step/1/success'
- kwarg:
timeout: 600
prepare for step 2:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 1 success
step 2:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 2
- parallel: True
- kwarg:
bg: False
- arg:
- |
sleep 10 &&
salt-call event.send 'rolling/step/2/success'
step 2 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 2
- arg:
- 'rolling/step/2/success'
- kwarg:
timeout: 600
prepare for step 3:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 2 success
step 3:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 3
- parallel: True
- kwarg:
bg: False
- arg:
- |
sleep 5 &&
salt-call event.send 'rolling/step/3/success'
step 3 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 3
- arg:
- 'rolling/step/3/success'
- kwarg:
timeout: 600
prepare for step 4:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 3 success
step 4:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 4
- parallel: True
- kwarg:
bg: False
- arg:
- |
sleep 23 &&
salt-call event.send 'rolling/step/4/success'
step 4 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 4
- arg:
- 'rolling/step/4/success'
- kwarg:
timeout: 600
prepare for step 5:
salt.function:
- name: test.ping
- tgt: 'un'
- require:
- step 4 success
step 5:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step 5
- parallel: True
- kwarg:
bg: False
- arg:
- |
sleep 39 &&
salt-call event.send 'rolling/step/5/success'
step 5 success:
salt.runner:
- name: poc.waitfor
- require:
- prepare for step 5
- arg:
- 'rolling/step/5/success'
- kwarg:
timeout: 600
[DEBUG ] Results of YAML rendering:
OrderedDict([('prepare for step 1', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')])])])), ('step 1', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 1'])]), OrderedDict([('parallel', True)]), OrderedDict([('kwarg', OrderedDict([('bg', False)]))]), OrderedDict([('arg', ["sleep 44 &&\nsalt-call event.send 'rolling/step/1/success'\n"])])])])), ('step 1 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('arg', ['rolling/step/1/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 2', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 1 success'])])])])), ('step 2', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 2'])]), OrderedDict([('parallel', True)]), OrderedDict([('kwarg', OrderedDict([('bg', False)]))]), OrderedDict([('arg', ["sleep 10 &&\nsalt-call event.send 'rolling/step/2/success'\n"])])])])), ('step 2 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 2'])]), OrderedDict([('arg', ['rolling/step/2/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 3', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 2 success'])])])])), ('step 3', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 3'])]), OrderedDict([('parallel', True)]), OrderedDict([('kwarg', OrderedDict([('bg', False)]))]), OrderedDict([('arg', ["sleep 5 &&\nsalt-call event.send 'rolling/step/3/success'\n"])])])])), ('step 3 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 3'])]), OrderedDict([('arg', ['rolling/step/3/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 4', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 3 success'])])])])), ('step 4', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 4'])]), OrderedDict([('parallel', True)]), OrderedDict([('kwarg', OrderedDict([('bg', False)]))]), OrderedDict([('arg', ["sleep 23 &&\nsalt-call event.send 'rolling/step/4/success'\n"])])])])), ('step 4 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 4'])]), OrderedDict([('arg', ['rolling/step/4/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])])), ('prepare for step 5', OrderedDict([('salt.function', [OrderedDict([('name', 'test.ping')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['step 4 success'])])])])), ('step 5', OrderedDict([('salt.function', [OrderedDict([('name', 'cmd.shell')]), OrderedDict([('tgt', 'un')]), OrderedDict([('require', ['prepare for step 5'])]), OrderedDict([('parallel', True)]), OrderedDict([('kwarg', OrderedDict([('bg', False)]))]), OrderedDict([('arg', ["sleep 39 &&\nsalt-call event.send 'rolling/step/5/success'\n"])])])])), ('step 5 success', OrderedDict([('salt.runner', [OrderedDict([('name', 'poc.waitfor')]), OrderedDict([('require', ['prepare for step 5'])]), OrderedDict([('arg', ['rolling/step/5/success'])]), OrderedDict([('kwarg', OrderedDict([('timeout', 600)]))])])]))])
[PROFILE ] Time (in seconds) to render '/opt/local/var/cache/salt/master/files/base/orch/roll.sls' using 'yaml' renderer: 0.035021066665649414
[DEBUG ] LazyLoaded config.option
[DEBUG ] LazyLoaded salt.function
[INFO ] Running state [test.ping] at time 11:54:49.350304
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407115441951961/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T16:54:49.352957'}
[DEBUG ] LazyLoaded saltutil.cmd
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: .local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/3b/46c138b70c358c0a8d21acbbf94845e56e61162c9fb5fd54d8a034ea208b1f/.minions.p
[DEBUG ] get_iter_returns for jid 20180407115449479502 sent to {'un'} will timeout at 11:54:54.497291
[DEBUG ] jid 20180407115449479502 return from un
[DEBUG ] jid 20180407115449479502 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 11:54:49.691708 (duration_in_ms=341.405)
[INFO ] Running state [cmd.shell] at time 11:54:49.692334
[INFO ] Executing state salt.function for [cmd.shell]
[INFO ] Started in a seperate process
[INFO ] Completed state [cmd.shell] at time 11:54:49.699555 (duration_in_ms=7.221)
[INFO ] Running state [poc.waitfor] at time 11:54:49.700420
[INFO ] Executing state salt.runner for [poc.waitfor]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407115441951961/args; data = {'type': 'function', 'tgt': 'un', 'name': 'cmd.shell', 'args': {'arg': ["sleep 44 &&\nsalt-call event.send 'rolling/step/1/success'\n"], 'kwarg': OrderedDict([('bg', False)]), 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T16:54:49.707824'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] LazyLoaded poc.waitfor
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407115441951961/args; data = {'type': 'runner', 'name': 'poc.waitfor', 'args': ['rolling/step/1/success'], 'kwargs': OrderedDict([('timeout', 600)]), '_stamp': '2018-04-07T16:54:49.719047'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Including configuration from '/opt/local/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Grains refresh requested. Refreshing grains.
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/19/29bf6f58bee1229a7d9e3a38724b55ce861711d1ad14ce2639725a139dd876/.minions.p
[DEBUG ] get_iter_returns for jid 20180407115449832581 sent to {'un'} will timeout at 11:54:54.852256
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] Loading static grains from /opt/local/etc/salt/grains
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407115450853225/new; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407115450853225', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/1/success', {'timeout': 600}], '_stamp': '2018-04-07T16:54:50.877234'}
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Checking whether jid 20180407115449832581 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] retcode missing from client return
[DEBUG ] Checking whether jid 20180407115449832581 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] retcode missing from client return
[DEBUG ] Checking whether jid 20180407115449832581 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] retcode missing from client return
[DEBUG ] Checking whether jid 20180407115449832581 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] retcode missing from client return
[DEBUG ] Checking whether jid 20180407115449832581 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407115450853225: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407115450853225/ret; data = {'fun': 'runner.poc.waitfor', 'jid': '20180407115450853225', 'user': 'UNKNOWN', 'fun_args': ['rolling/step/1/success', {'timeout': 600}], '_stamp': '2018-04-07T16:55:35.328519', 'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/1/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407115535296875', '__pub_pid': 15387, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T16:55:35.321872'}}), 'success': True}
[INFO ] Runner completed: 20180407115450853225
[INFO ] {'return': (True, {'data': {'cmd': '_minion_event', 'tag': 'rolling/step/1/success', 'data': {'__pub_fun': 'event.send', '__pub_jid': '20180407115535296875', '__pub_pid': 15387, '__pub_tgt': 'salt-call'}, 'id': 'un', '_stamp': '2018-04-07T16:55:35.321872'}})}
[INFO ] Completed state [poc.waitfor] at time 11:55:35.329688 (duration_in_ms=45629.268)
[INFO ] Running state [test.ping] at time 11:55:35.330353
[INFO ] Executing state salt.function for [test.ping]
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20180407115441951961/args; data = {'type': 'function', 'tgt': 'un', 'name': 'test.ping', 'args': {'arg': [], 'kwarg': {}, 'ret': '', 'timeout': None, 'tgt_type': 'glob', 'ssh': False, 'expect_minions': False, '_cmd_meta': True}, '_stamp': '2018-04-07T16:55:35.332427'}
[DEBUG ] Reading configuration from /opt/local/etc/salt/master
[DEBUG ] retcode missing from client return
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/roots.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/roots.conf
[DEBUG ] Including configuration from '/opt/local/etc/salt/master.d/security.conf'
[DEBUG ] Reading configuration from /opt/local/etc/salt/master.d/security.conf
[DEBUG ] Using cached minion ID from /opt/local/etc/salt/minion_id: salt-master.local
[DEBUG ] Missing configuration file: /Users/aphor/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /opt/local/var/run/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/opt/local/etc/salt/pki/master', 'salt-master.local_master', 'tcp://[::]:4506', 'clear')
[DEBUG ] Connecting the Minion to the Master URI (for the return server): tcp://[::]:4506
[DEBUG ] Trying to connect to: tcp://[::]:4506
[DEBUG ] Initializing new IPCClient for path: /opt/local/var/run/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /opt/local/var/cache/salt/master/jobs/6f/32f2b42a9be38d74e2b3f6de6578fe863071b08fddc8ac39e7e36bc3bf7327/.minions.p
[DEBUG ] get_iter_returns for jid 20180407115535451805 sent to {'un'} will timeout at 11:55:40.469241
[DEBUG ] jid 20180407115449832581 return from un
[DEBUG ] jid 20180407115535451805 return from un
[DEBUG ] jid 20180407115449832581 found all minions {'un'}
[ERROR ] An un-handled exception from the multiprocessing process 'MultiprocessingProcess-1' was caught:
Traceback (most recent call last):
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/process.py", line 747, in _run
return self._original_run()
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/multiprocessing/process.py", line 93, in run
self._target(*self._args, **self._kwargs)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 1724, in _call_parallel_target
troot = os.path.join(self.opts['cachedir'], self.jid)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/posixpath.py", line 94, in join
genericpath._check_arg_types('join', a, *p)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/genericpath.py", line 149, in _check_arg_types
(funcname, s.__class__.__name__)) from None
TypeError: join() argument must be str or bytes, not 'NoneType'
Process MultiprocessingProcess-1:
Traceback (most recent call last):
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/multiprocessing/process.py", line 258, in _bootstrap
self.run()
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/process.py", line 747, in _run
return self._original_run()
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/multiprocessing/process.py", line 93, in run
self._target(*self._args, **self._kwargs)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 1724, in _call_parallel_target
troot = os.path.join(self.opts['cachedir'], self.jid)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/posixpath.py", line 94, in join
genericpath._check_arg_types('join', a, *p)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/genericpath.py", line 149, in _check_arg_types
(funcname, s.__class__.__name__)) from None
TypeError: join() argument must be str or bytes, not 'NoneType'
[DEBUG ] jid 20180407115535451805 found all minions {'un'}
[INFO ] {'out': 'highstate', 'ret': {'un': True}}
[INFO ] Completed state [test.ping] at time 11:55:35.665209 (duration_in_ms=334.856)
[DEBUG ] LazyLoaded local_cache.prep_jid
[DEBUG ] Adding minions for job 20180407115441951961: ['salt-master.local_master']
[DEBUG ] Sending event: tag = salt/run/20180407115441951961/ret; data = {'fun': 'runner.state.orchestrate', 'jid': '20180407115441951961', 'user': 'sudo_aphor', 'fun_args': ['orch.roll', {'orchestration_jid': '20180407115441951961'}], '_stamp': '2018-04-07T16:55:35.675245', 'return': 'Exception occurred in runner state.orchestrate: Traceback (most recent call last):\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/client/mixins.py", line 387, in _low\n data[\'return\'] = self.functions[fun](*args, **kwargs)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/runners/state.py", line 106, in orchestrate\n orchestration_jid=orchestration_jid)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/modules/state.py", line 1278, in sls\n ret = st_.state.call_high(high_, orchestration_jid)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2706, in call_high\n ret = self.call_chunks(chunks)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2096, in call_chunks\n running = self.call_chunk(low, running, chunks)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2423, in call_chunk\n status, reqs = self.check_requisite(low, running, chunks, pre=True)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2235, in check_requisite\n self.reconcile_procs(running)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2174, in reconcile_procs\n ret_cache = os.path.join(self.opts[\'cachedir\'], self.jid, _clean_tag(tag))\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 159, in _clean_tag\n return salt.utils.files.safe_filename_leaf(tag)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/files.py", line 573, in safe_filename_leaf\n return re.sub(\'[\\\\\\\\:/*?"<>|]\', _replace, file_basename, flags=re.UNICODE)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/re.py", line 191, in sub\n return _compile(pattern, flags).sub(repl, string, count)\n File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/files.py", line 566, in _replace\n return urllib.quote(re_obj.group(0), safe=\'\')\nAttributeError: module \'urllib\' has no attribute \'quote\'\n', 'success': False}
[DEBUG ] LazyLoaded nested.output
Exception occurred in runner state.orchestrate: Traceback (most recent call last):
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/client/mixins.py", line 387, in _low
data['return'] = self.functions[fun](*args, **kwargs)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/runners/state.py", line 106, in orchestrate
orchestration_jid=orchestration_jid)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/modules/state.py", line 1278, in sls
ret = st_.state.call_high(high_, orchestration_jid)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2706, in call_high
ret = self.call_chunks(chunks)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2096, in call_chunks
running = self.call_chunk(low, running, chunks)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2423, in call_chunk
status, reqs = self.check_requisite(low, running, chunks, pre=True)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2235, in check_requisite
self.reconcile_procs(running)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2174, in reconcile_procs
ret_cache = os.path.join(self.opts['cachedir'], self.jid, _clean_tag(tag))
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 159, in _clean_tag
return salt.utils.files.safe_filename_leaf(tag)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/files.py", line 573, in safe_filename_leaf
return re.sub('[\\\\:/*?"<>|]', _replace, file_basename, flags=re.UNICODE)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/re.py", line 191, in sub
return _compile(pattern, flags).sub(repl, string, count)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/files.py", line 566, in _replace
return urllib.quote(re_obj.group(0), safe='')
AttributeError: module 'urllib' has no attribute 'quote'
[INFO ] Runner completed: 20180407115441951961
[DEBUG ] Runner return: Exception occurred in runner state.orchestrate: Traceback (most recent call last):
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/client/mixins.py", line 387, in _low
data['return'] = self.functions[fun](*args, **kwargs)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/runners/state.py", line 106, in orchestrate
orchestration_jid=orchestration_jid)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/modules/state.py", line 1278, in sls
ret = st_.state.call_high(high_, orchestration_jid)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2706, in call_high
ret = self.call_chunks(chunks)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2096, in call_chunks
running = self.call_chunk(low, running, chunks)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2423, in call_chunk
status, reqs = self.check_requisite(low, running, chunks, pre=True)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2235, in check_requisite
self.reconcile_procs(running)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 2174, in reconcile_procs
ret_cache = os.path.join(self.opts['cachedir'], self.jid, _clean_tag(tag))
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/state.py", line 159, in _clean_tag
return salt.utils.files.safe_filename_leaf(tag)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/files.py", line 573, in safe_filename_leaf
return re.sub('[\\\\:/*?"<>|]', _replace, file_basename, flags=re.UNICODE)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/re.py", line 191, in sub
return _compile(pattern, flags).sub(repl, string, count)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/site-packages/salt/utils/files.py", line 566, in _replace
return urllib.quote(re_obj.group(0), safe='')
AttributeError: module 'urllib' has no attribute 'quote'
Raw
parallel_step_roll.sls
{% for step_number in range(1,6) %}
prepare for step {{ step_number }}:
salt.function:
- name: test.ping
- tgt: 'un'
{%- if step_number > 1 %}
- require:
- step {{ step_number - 1 }} success
{%- endif %}
step {{ step_number }}:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step {{ step_number }}
- parallel: True
- kwarg:
bg: False
- arg:
- |
sleep {{ range(5,45)|random() }} &&
salt-call event.send 'rolling/step/{{step_number}}/success'
step {{ step_number }} success:
salt.runner:
- name: poc.waitfor
{%- if step_number > 1 %}
- require:
- prepare for step {{ step_number }}
{%- endif %}
- arg:
- 'rolling/step/{{step_number}}/success'
- kwarg:
timeout: 600
{% endfor %}
Raw
poc.py
'''
Module for testing waitfor(event_tag, timeout=seconds)
PROOF OF CONCEPT EXPERIMENTAL
'''
from __future__ import absolute_import
import logging
import asyncio
from salt.utils.event import get_master_event as event_listener
log = logging.getLogger(__name__)
def waitfor(tag, timeout=300):
'''
listen and wait for an event by tag, for timeout seconds
'''
opts = __opts__
# get an event event_listener
events = event_listener(opts, opts['sock_dir'], listen=True)
# subscribe, connect, and call get_event to wait for the tag
events.subscribe(tag=tag)
events.connect_pull()
try:
event_catch = events.get_event(wait=float(timeout), tag=tag)
# return the event if caught
# return False if timeout happens
if event_catch:
return True, {'data': event_catch}
except asyncio.TimeoutError:
msg ='timeout waiting {d} seconds for event tag={}'.format(timeout, tag)
return False, msg
Raw
roll.sls
{% for step_number in range(1,6) %}
prepare for step {{ step_number }}:
salt.function:
- name: test.ping
- tgt: 'un'
{%- if step_number > 1 %}
- require:
- step {{ step_number - 1 }} success
{%- endif %}
step {{ step_number }}:
salt.function:
- name: cmd.shell
- tgt: 'un'
- require:
- prepare for step {{ step_number }}
- kwarg:
bg: True
- arg:
- |
sleep {{ range(5,45)|random() }} &&
salt-call event.send 'rolling/step/{{step_number}}/success'
step {{ step_number }} success:
salt.runner:
- name: poc.waitfor
{%- if step_number > 1 %}
- require:
- prepare for step {{ step_number }}
{%- endif %}
- arg:
- 'rolling/step/{{step_number}}/success'
- kwarg:
timeout: 600
{% endfor %}
Raw
versions-report
$ salt-master --versions-report
Salt Version:
Salt: 2018.3.0
Dependency Versions:
cffi: Not Installed
cherrypy: Not Installed
dateutil: 2.6.1
docker-py: Not Installed
gitdb: Not Installed
gitpython: Not Installed
ioflo: Not Installed
Jinja2: 2.10
libgit2: Not Installed
libnacl: Not Installed
M2Crypto: Not Installed
Mako: Not Installed
msgpack-pure: Not Installed
msgpack-python: 0.5.6
mysql-python: Not Installed
pycparser: Not Installed
pycrypto: 2.6.1
pycryptodome: Not Installed
pygit2: Not Installed
Python: 3.6.5 (default, Mar 29 2018, 15:38:43)
python-gnupg: Not Installed
PyYAML: 3.12
PyZMQ: 17.0.0
RAET: Not Installed
smmap: Not Installed
timelib: Not Installed
Tornado: 4.5.2
ZMQ: 4.2.5
System Versions:
dist:
locale: UTF-8
machine: x86_64
release: 16.7.0
system: Darwin
version: 10.12.6 x86_64
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment