DEBUG statement "Passing on Saltutil error. This may be an error in saltclient." appearing while waiting for provisioning to finish on Windows.

[RobertSwirsky]

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

[Ch3LL]

@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: #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.

[RobertSwirsky]

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.

[dxiri]

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'

[ton3r]

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

[mikemol]

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.

[dthom91]

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.

[pgporada]

I'm on Cent7 for my testing with Salt 2016.11.4 and seeing this too.

[jdelic]

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 vmware-archive/salt-pack#183 is fixed.

The result is that the master hangs while looping waiting for the job to return.

[supriti]

I see this issue on salt- version 2016.11.4 and sles12

[knowledgewarrior]

I have the same issue on salt 2016.11.2 on CentOS 6.8, Windows 10 minion running 'salt -l debug winminion state.highstate'

[stale]

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

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