Salt: DEBUG statement "Passing on Saltutil error. This may be an error in saltclient." appearing while waiting for provisioning to finish on Windows.
Description of Issue/Question
While waiting for a (successful!) provisioning of a VirtualBox Centos machine on a Windows 10 host environment we see this message dozens of times:
[DEBUG]"Passing on saltutil error. This may be an error in saltclient. 'retcode'
The full context of how this appears is this:
[DEBUG ] Checking whether jid 20170103194912598560 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', '10.0.1.156_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] jid 20170103194912598560 return from reference
Everything completed OK. It seems harmless, but it is a relatively new behavior so I thought I'd raise it as an issue because apparently some developer wanted to note when this happened.
Setup
(Please provide relevant configs and/or SLS files (Be sure to remove sensitive info).)
Windows 10 host. Using Vagrant to start salt. Running Salt Minion and Master on one Centos/7 Virtualbox VM that was booted with Vagrant and provisioned with saltstack. Using Powershell.
The same setup works on a Mac host and we don't see the
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
statement
Steps to Reproduce Issue
(Include debug logs if possible and relevant.)
Bring up a saltstack provisioned master/minion instance on Virtualbox with a Windows 10 host. We see this on all our projects.
Versions Report
(Provided by running salt --versions-report. Please also mention any differences in master/minion versions.)
Last login: Tue Jan 3 19:53:28 2017
[vagrant@loadtest ~]$ salt --versions-report
Salt Version:
Salt: 2016.11.1
Dependency Versions:
cffi: Not Installed
cherrypy: Not Installed
dateutil: 2.1
gitdb: Not Installed
gitpython: Not Installed
ioflo: Not Installed
Jinja2: 2.7.2
libgit2: Not Installed
libnacl: Not Installed
M2Crypto: Not Installed
Mako: Not Installed
msgpack-pure: Not Installed
msgpack-python: 0.4.8
mysql-python: 1.2.5
pycparser: Not Installed
pycrypto: 2.6.1
pygit2: Not Installed
Python: 2.7.5 (default, Nov 6 2016, 00:28:07)
python-gnupg: Not Installed
PyYAML: 3.11
PyZMQ: 15.3.0
RAET: Not Installed
smmap: Not Installed
timelib: Not Installed
Tornado: 4.2.1
ZMQ: 4.1.4
System Versions:
dist: centos 7.3.1611 Core
machine: x86_64
release: 3.10.0-514.2.2.el7.x86_64
system: Linux
version: CentOS Linux 7.3.1611 Core
RobertSwirsky
All 11 comments
@chatterbeak the only time i'm able to replicate this is if the minion is not running and attempting to make a call to the minion for example (salt '*' test.ping -ldebug). Looking at the change in this pr: https://github.com/saltstack/salt/pull/35446 it seems it checks for retcode in data which is not going to be the in there each time. Also looks like there is conversation on that pr about this issue
ping @cachedout looks like you had a fix in mind to ensure we only enter the block if retcode is present. I'm not seeing if this ever was added or not so not sure if you still want to add this or are intentionally leaving that keyerror exception in there.
Ch3LL
on 6 Jan 2017
Thanks. I'm configuring a test box that has minion and master running on one box. I haven't tried other configurations because this is our standard test configuration.
RobertSwirsky
on 10 Jan 2017
I am having a similar issue but not sure if its directly related to this:
I am trying to deploy a VM using salt virt by following the instructions at https://docs.saltstack.com/en/latest/topics/tutorials/cloud_controller.html#cloud-controller
During the VM deployment salt enters into a neverending loop:
root@sjociara03:/srv/salt# salt-run -l debug virt.init centosTEST 4 2048 salt://centos6-base.img
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Using cached minion ID from /etc/salt/minion_id: sjociara03
[DEBUG ] Missing configuration file: /root/.saltrc
[DEBUG ] Configuration file path: /etc/salt/master
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG ] LazyLoaded virt.init
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG ] Using cached minion ID from /etc/salt/minion_id: sjociara03
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Please install 'virt-what' to improve results of the 'virtual' grain.
[DEBUG ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20170221183757236813/new; data = {'fun': 'runner.virt.init', 'fun_args': ['centosTEST', 4, 2048, 'salt://centos6-base.img'], 'jid': '20170221183757236813', 'user': 'root', '_stamp': '2017-02-22T00:37:57.439397'}
[DEBUG ] Sending event: tag = salt/run/20170221183757236813/progress; data = {'message': 'Searching for hosts', '_stamp': '2017-02-22T00:37:57.439690'}
[DEBUG ] LazyLoaded nested.output
event:
----------
_stamp:
2017-02-22T00:37:57.439690
message:
Searching for hosts
suffix:
progress
[WARNING ] 'quiet' is deprecated. Please migrate to --quiet
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Using cached minion ID from /etc/salt/minion_id: sjociara03
[DEBUG ] Missing configuration file: /root/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /var/cache/salt/master/jobs/15/3114a99fe2215d835f20e080e925e5f9c63dd005e7c2b5dc03a1e9ac475a9a/.minions.p
[DEBUG ] get_iter_returns for jid 20170221183757487101 sent to set(['a172-25-151-61.deploy.akamaitechnologies.com', 'a172-25-151-56.deploy']) will timeout at 18:38:02.489700
[DEBUG ] jid 20170221183757487101 return from a172-25-151-56.deploy
[DEBUG ] Checking whether jid 20170221183757487101 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Sending event: tag = salt/run/20170221183757236813/progress; data = {'message': 'Minion will be preseeded', '_stamp': '2017-02-22T00:38:12.637850'}
[DEBUG ] LazyLoaded nested.output
event:
----------
_stamp:
2017-02-22T00:38:12.637850
message:
Minion will be preseeded
suffix:
progress
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Using cached minion ID from /etc/salt/minion_id: sjociara03
[DEBUG ] Missing configuration file: /root/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG ] Sending event: tag = salt/run/20170221183757236813/progress; data = {'message': 'Creating VM centosTEST on host a172-25-151-56.deploy', '_stamp': '2017-02-22T00:38:12.863436'}
[DEBUG ] LazyLoaded nested.output
event:
----------
_stamp:
2017-02-22T00:38:12.863436
message:
Creating VM centosTEST on host a172-25-151-56.deploy
suffix:
progress
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /var/cache/salt/master/jobs/16/7111851b5526c3be7c271621663077a16cf812fbc4956e925cd945da9383e5/.minions.p
[DEBUG ] get_iter_returns for jid 20170221183812866496 sent to set(['a172-25-151-56.deploy']) will timeout at 18:48:12.868966
[DEBUG ] Checking whether jid 20170221183812866496 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170221183812866496 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170221183812866496 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170221183812866496 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170221183812866496 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'sjociara03_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
dxiri
on 22 Feb 2017
I'm running in the same problem. At the end the call is finished and done fine. But I think there is a loop about 4 times which logs on saltmaster with "Passing on saltutil error. This may be an error in saltclient. 'retcode'"
On the requested minion I found no errors. May be I don't interpret them as errors..
Both, master and minion are 2016.11.3 (Carbon)
I've the following state file which is provided with file_roots on the master :
tomtest:
cmd.run:
- name: 'echo `date` >> /tmp/loglog.txt'
On my master I start :
```
time salt vmg-dev-epg-002.intern.loc state.sls tomtest
[DEBUG ] Configuration file path: /etc/salt/master
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG ] Reading configuration from /etc/salt/master
[DEBUG ] Using cached minion ID from /etc/salt/minion_id: vmg-dev-fosp-saltmaster-001.intern.loc
[DEBUG ] Missing configuration file: /root/.saltrc
[DEBUG ] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'vmg-dev-fosp-saltmaster-001.intern.loc_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pub.ipc
[DEBUG ] LazyLoaded local_cache.get_load
[DEBUG ] Reading minion list from /var/cache/salt/master/jobs/bb/ae208ab0162aeb72712cd52482f7a65add62c7226228326c434ffe668f6f82/.minions.p
[DEBUG ] get_iter_returns for jid 20170309154911080531 sent to set(['vmg-dev-epg-002.intern.loc']) will timeout at 15:49:16.090376
[DEBUG ] Checking whether jid 20170309154911080531 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'vmg-dev-fosp-saltmaster-001.intern.loc_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170309154911080531 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'vmg-dev-fosp-saltmaster-001.intern.loc_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170309154911080531 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'vmg-dev-fosp-saltmaster-001.intern.loc_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] Checking whether jid 20170309154911080531 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'vmg-dev-fosp-saltmaster-001.intern.loc_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
[DEBUG ] jid 20170309154911080531 return from vmg-dev-epg-002.intern.loc
[DEBUG ] LazyLoaded highstate.output
[DEBUG ] LazyLoaded nested.output
vmg-dev-epg-002.intern.loc:
----------
ID: tomtest
Function: cmd.run
Name: echo `date` >> /tmp/loglog.txt
Result: True
Comment: Command "echo `date` >> /tmp/loglog.txt" run
Started: 16:40:46.369809
Duration: 20.496 ms
Changes:
----------
pid:
17509
retcode:
0
stderr:
stdout:
Summary for vmg-dev-epg-002.intern.loc
------------
Succeeded: 1 (changed=1)
Failed: 0
------------
Total states run: 1
Total run time: 20.496 ms
[DEBUG ] jid 20170309154911080531 found all minions set(['vmg-dev-epg-002.intern.loc'])
real 0m44.010s
user 0m1.721s
sys 0m0.137s
As you can see the plain runtime is about 20ms. But the real runtime is about 44 seconds.
On my minion side the following debug output is written. At least at timestamp "2017-03-09 16:40:46,188" starts the real action.
2017-03-09 16:40:03,761 [salt.minion ][INFO ][17099] User root Executing command state.sls with jid 20170309154911080531
2017-03-09 16:40:03,763 [salt.minion ][DEBUG ][17099] Command details {'tgt_type': 'glob', 'jid': '20170309154911080531', 'tgt': 'vmg-dev-epg-002.intern.loc', 'ret': '', 'user': 'root', 'arg': ['tomtest'], 'fun': 'state.sls'}
2017-03-09 16:40:03,791 [salt.minion ][INFO ][17344] Starting a new job with PID 17344
2017-03-09 16:40:03,809 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded state.sls
2017-03-09 16:40:03,813 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded direct_call.get
2017-03-09 16:40:03,826 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded saltutil.is_running
2017-03-09 16:40:03,829 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded grains.get
2017-03-09 16:40:03,841 [salt.transport.zeromq][DEBUG ][17344] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:03,842 [salt.crypt ][DEBUG ][17344] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
2017-03-09 16:40:08,876 [salt.minion ][INFO ][17099] User root Executing command saltutil.find_job with jid 20170309154916192662
2017-03-09 16:40:08,878 [salt.minion ][DEBUG ][17099] Command details {'tgt_type': 'list', 'jid': '20170309154916192662', 'tgt': ['vmg-dev-epg-002.intern.loc'], 'ret': '', 'user': 'root', 'arg': ['20170309154911080531'], 'fun': 'saltutil.find_job'}
2017-03-09 16:40:08,924 [salt.minion ][INFO ][17364] Starting a new job with PID 17364
2017-03-09 16:40:08,945 [salt.utils.lazy ][DEBUG ][17364] LazyLoaded saltutil.find_job
2017-03-09 16:40:08,949 [salt.utils.lazy ][DEBUG ][17364] LazyLoaded direct_call.get
2017-03-09 16:40:08,953 [salt.minion ][DEBUG ][17364] Minion return retry timer set to 5 seconds (randomized)
2017-03-09 16:40:08,955 [salt.minion ][INFO ][17364] Returning information for job: 20170309154916192662
2017-03-09 16:40:08,957 [salt.transport.zeromq][DEBUG ][17364] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:08,958 [salt.crypt ][DEBUG ][17364] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
2017-03-09 16:40:18,921 [salt.minion ][INFO ][17099] User root Executing command saltutil.find_job with jid 20170309154926240004
2017-03-09 16:40:18,923 [salt.minion ][DEBUG ][17099] Command details {'tgt_type': 'list', 'jid': '20170309154926240004', 'tgt': ['vmg-dev-epg-002.intern.loc'], 'ret': '', 'user': 'root', 'arg': ['20170309154911080531'], 'fun': 'saltutil.find_job'}
2017-03-09 16:40:18,963 [salt.minion ][INFO ][17487] Starting a new job with PID 17487
2017-03-09 16:40:18,999 [salt.utils.lazy ][DEBUG ][17487] LazyLoaded saltutil.find_job
2017-03-09 16:40:19,004 [salt.utils.lazy ][DEBUG ][17487] LazyLoaded direct_call.get
2017-03-09 16:40:19,011 [salt.minion ][DEBUG ][17487] Minion return retry timer set to 9 seconds (randomized)
2017-03-09 16:40:19,013 [salt.minion ][INFO ][17487] Returning information for job: 20170309154926240004
2017-03-09 16:40:19,015 [salt.transport.zeromq][DEBUG ][17487] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:19,021 [salt.crypt ][DEBUG ][17487] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
2017-03-09 16:40:28,988 [salt.minion ][INFO ][17099] User root Executing command saltutil.find_job with jid 20170309154936307252
2017-03-09 16:40:28,990 [salt.minion ][DEBUG ][17099] Command details {'tgt_type': 'list', 'jid': '20170309154936307252', 'tgt': ['vmg-dev-epg-002.intern.loc'], 'ret': '', 'user': 'root', 'arg': ['20170309154911080531'], 'fun': 'saltutil.find_job'}
2017-03-09 16:40:29,015 [salt.minion ][INFO ][17494] Starting a new job with PID 17494
2017-03-09 16:40:29,032 [salt.utils.lazy ][DEBUG ][17494] LazyLoaded saltutil.find_job
2017-03-09 16:40:29,035 [salt.utils.lazy ][DEBUG ][17494] LazyLoaded direct_call.get
2017-03-09 16:40:29,038 [salt.minion ][DEBUG ][17494] Minion return retry timer set to 9 seconds (randomized)
2017-03-09 16:40:29,039 [salt.minion ][INFO ][17494] Returning information for job: 20170309154936307252
2017-03-09 16:40:29,041 [salt.transport.zeromq][DEBUG ][17494] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:29,042 [salt.crypt ][DEBUG ][17494] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
2017-03-09 16:40:39,000 [salt.minion ][INFO ][17099] User root Executing command saltutil.find_job with jid 20170309154946319431
2017-03-09 16:40:39,002 [salt.minion ][DEBUG ][17099] Command details {'tgt_type': 'list', 'jid': '20170309154946319431', 'tgt': ['vmg-dev-epg-002.intern.loc'], 'ret': '', 'user': 'root', 'arg': ['20170309154911080531'], 'fun': 'saltutil.find_job'}
2017-03-09 16:40:39,031 [salt.minion ][INFO ][17504] Starting a new job with PID 17504
2017-03-09 16:40:39,055 [salt.utils.lazy ][DEBUG ][17504] LazyLoaded saltutil.find_job
2017-03-09 16:40:39,059 [salt.utils.lazy ][DEBUG ][17504] LazyLoaded direct_call.get
2017-03-09 16:40:39,062 [salt.minion ][DEBUG ][17504] Minion return retry timer set to 10 seconds (randomized)
2017-03-09 16:40:39,063 [salt.minion ][INFO ][17504] Returning information for job: 20170309154946319431
2017-03-09 16:40:39,065 [salt.transport.zeromq][DEBUG ][17504] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:39,066 [salt.crypt ][DEBUG ][17504] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
2017-03-09 16:40:43,778 [salt.pillar ][DEBUG ][17344] Determining pillar cache
2017-03-09 16:40:43,780 [salt.transport.zeromq][DEBUG ][17344] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:43,781 [salt.crypt ][DEBUG ][17344] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
2017-03-09 16:40:46,188 [salt.crypt ][DEBUG ][17344] Loaded minion key: /etc/salt/pki/minion/minion.pem
2017-03-09 16:40:46,234 [salt.state ][INFO ][17344] Loading fresh modules for state activity
2017-03-09 16:40:46,275 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded jinja.render
2017-03-09 16:40:46,277 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded yaml.render
2017-03-09 16:40:46,339 [salt.fileclient ][DEBUG ][17344] In saltenv 'base', looking at rel_path 'tomtest.sls' to resolve 'salt://tomtest.sls'
2017-03-09 16:40:46,341 [salt.fileclient ][DEBUG ][17344] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/tomtest.sls' to resolve 'salt://tomtest.sls'
2017-03-09 16:40:46,342 [salt.fileclient ][INFO ][17344] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://tomtest.sls', mode up-to-date
2017-03-09 16:40:46,343 [salt.template ][DEBUG ][17344] compile template: /var/cache/salt/minion/files/base/tomtest.sls
2017-03-09 16:40:46,345 [salt.utils.jinja ][DEBUG ][17344] Jinja search path: ['/var/cache/salt/minion/files/base']
2017-03-09 16:40:46,354 [salt.template ][PROFILE ][17344] Time (in seconds) to render '/var/cache/salt/minion/files/base/tomtest.sls' using 'jinja' renderer: 0.00933313369751
2017-03-09 16:40:46,355 [salt.template ][DEBUG ][17344] Rendered data from file: /var/cache/salt/minion/files/base/tomtest.sls:
tomtest:
cmd.run:
- name: 'echo `date` >> /tmp/loglog.txt'
2017-03-09 16:40:46,362 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded config.get
2017-03-09 16:40:46,363 [salt.loaded.int.render.yaml][DEBUG ][17344] Results of YAML rendering:
OrderedDict([('tomtest', OrderedDict([('cmd.run', [OrderedDict([('name', 'echo `date` >> /tmp/loglog.txt')])])]))])
2017-03-09 16:40:46,365 [salt.template ][PROFILE ][17344] Time (in seconds) to render '/var/cache/salt/minion/files/base/tomtest.sls' using 'yaml' renderer: 0.00731801986694
2017-03-09 16:40:46,368 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded cmd.run
2017-03-09 16:40:46,369 [salt.state ][INFO ][17344] Running state [echo `date` >> /tmp/loglog.txt] at time 16:40:46.369810
2017-03-09 16:40:46,371 [salt.state ][INFO ][17344] Executing state cmd.run for echo `date` >> /tmp/loglog.txt
2017-03-09 16:40:46,377 [salt.utils.lazy ][DEBUG ][17344] LazyLoaded cmd.run_all
2017-03-09 16:40:46,379 [salt.loaded.int.module.cmdmod][INFO ][17344] Executing command 'echo `date` >> /tmp/loglog.txt' in directory '/root'
2017-03-09 16:40:46,388 [salt.state ][INFO ][17344] {'pid': 17509, 'retcode': 0, 'stderr': '', 'stdout': ''}
2017-03-09 16:40:46,390 [salt.state ][INFO ][17344] Completed state [echo `date` >> /tmp/loglog.txt] at time 16:40:46.390305 duration_in_ms=20.496
2017-03-09 16:40:46,391 [salt.state ][DEBUG ][17344] File /var/cache/salt/minion/accumulator/139770902976144 does not exist, no need to cleanup.
2017-03-09 16:40:46,395 [salt.minion ][DEBUG ][17344] Minion return retry timer set to 6 seconds (randomized)
2017-03-09 16:40:46,396 [salt.minion ][INFO ][17344] Returning information for job: 20170309154911080531
2017-03-09 16:40:46,397 [salt.transport.zeromq][DEBUG ][17344] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506', 'aes')
2017-03-09 16:40:46,399 [salt.crypt ][DEBUG ][17344] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'vmg-dev-epg-002.intern.loc', 'tcp://10.8.81.11:4506')
```
I have no clue what the minion is doing before the real action. It looks for me that it hungs a while or do nothing. On the other hand the logging output from the master irritates me : Passing on saltutil error. This may be an error in saltclient. 'retcode'
But I found nothing to check. What do the minion errornous return?!
I hope to find here some help. The calls needs to long to run.
regards,
Tom
ton3r
on 10 Mar 2017
I'm seeing the same message, "This may be an error in saltclient. 'retcode'". Difference from above, I'm operating purely in a CentOS environment right now.
I'll note that there's a delay right around each occurrence of it, which leads me to suspect a timeout is in play, possibly a firewall, DNS or other network issue that gets worked around somehow.
Everything continues and finishes, so it's frankly the 'retcode' that annoys me; I can't quickly drill down without an actual error code to work with.
mikemol
on 4 May 2017
I'm also getting this message in a case where I'm running Carbon salt-master on a CentOS host and Carbon salt-minion on a Windows Server 2012 host. May only be a manifestation of a deeper problem, but it's interfering with my troubleshooting.
dthom91
on 10 May 2017
I'm on Cent7 for my testing with Salt 2016.11.4 and seeing this too.
pgporada
on 11 May 2017
I'm seeing this with the latest Salt packages available for Debian Stretch (2016.11.2+ds-1) and it breaks during simple operations like salt '*' pkg.upgrade. The only related logs are
on the minion
2017-05-25 14:37:26,017 [salt.minion ][INFO ][30767] Returning information for job: 20170525143353242097
May 25 14:37:26 test salt-minion[4423]: [DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/minion', 'test.maurusnet.test', 'tcp://192.168.56.88:4506', 'aes')
on the master:
[DEBUG ] Checking whether jid 20170525143353242097 is still running
[DEBUG ] Initializing new AsyncZeroMQReqChannel for ('/etc/salt/pki/master', 'saltmaster.maurusnet.test_master', 'tcp://127.0.0.1:4506', 'clear')
[DEBUG ] Passing on saltutil error. This may be an error in saltclient. 'retcode'
Unfortunately I have to way to check newer versions until saltstack/salt-pack#183 is fixed.
The result is that the master hangs while looping waiting for the job to return.
jdelic
on 25 May 2017
I see this issue on salt- version 2016.11.4 and sles12
supriti
on 13 Jul 2017
I have the same issue on salt 2016.11.2 on CentOS 6.8, Windows 10 minion running 'salt -l debug winminion state.highstate'
knowledgewarrior
on 6 Oct 2017
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.
![stale[bot] picture](https://avatars.githubusercontent.com/in/1724?v=4&s=40)
stale[bot]
on 7 Feb 2019
Related issues
sagetherage
路
3Comments
Arguros
路
3Comments
seanacais
路
3Comments
allyunion
路
3Comments
saurabhnemade
路
3Comments
Most helpful comment
I see this issue on salt- version 2016.11.4 and sles12