saltstack / salt

Software to automate the management and configuration of any infrastructure or application at scale. Install Salt from the Salt package repositories here:
https://docs.saltproject.io/salt/install-guide/en/latest/
Apache License 2.0
14.23k stars 5.49k forks source link

[2016.11.0rc1] empty top file with older minion #36868

Closed sjorge closed 8 years ago

sjorge commented 8 years ago

Description of Issue/Question

I updated most of my minions except a critical one. I also updated my master.

Now the critical minion kept back at 2016.3.3 is no longer working.

state.show_top shows an empty top file.

Setup

top.sls

base:
  '*':
    - test

test.sls

debugging:
  test.show_notification:
    - text: super minimal

Steps to Reproduce Issue

running state.apply or state.show_top on oldminion salt oldminion state.show_top

Versions Report

minion:

Salt Version:
           Salt: 2016.3.3

Dependency Versions:
           cffi: 1.5.2
       cherrypy: 2.3.0
       dateutil: 2.4.2
          gitdb: 0.6.4
      gitpython: 1.0.1
          ioflo: 1.5.0
         Jinja2: 2.8
        libgit2: Not Installed
        libnacl: 1.4.5
       M2Crypto: 0.21.1
           Mako: 1.0.3
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: 2.14
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.7.12 (default, Jul  1 2016, 15:12:24)
   python-gnupg: 0.3.8
         PyYAML: 3.11
          PyZMQ: 15.2.0
           RAET: 0.6.5
          smmap: 0.9.0
        timelib: 0.2.4
        Tornado: 4.2.1
            ZMQ: 4.1.4

System Versions:
           dist: Ubuntu 16.04 xenial
        machine: x86_64
        release: 4.3.0
         system: Linux
        version: Ubuntu 16.04 xenial

master

Salt Version:
           Salt: 2016.11.0rc1

Dependency Versions:
           cffi: 1.4.2
       cherrypy: 3.8.0
       dateutil: 2.4.0
          gitdb: 0.6.4
      gitpython: 2.0.8
          ioflo: 1.6.1
         Jinja2: 2.7.3
        libgit2: Not Installed
        libnacl: 1.5.0
       M2Crypto: 0.22
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: Not Installed
      pycparser: 2.14
       pycrypto: 2.6.1
         pygit2: Not Installed
         Python: 2.7.12 (default, Jul 20 2016, 14:22:30)
   python-gnupg: 0.3.9
         PyYAML: 3.11
          PyZMQ: 14.4.1
           RAET: 0.6.5
          smmap: 0.9.0
        timelib: 0.2.4
        Tornado: 4.3
            ZMQ: 4.1.3

System Versions:
           dist:
        machine: i86pc
        release: 5.11
         system: SunOS
        version: Not Installed
sjorge commented 8 years ago

a broken 2016.3.3 minion

salt-call -l trace state.apply
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/smtp.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/smtp.conf
[TRACE   ] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[DEBUG   ] Configuration file path: /etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/smtp.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/smtp.conf
[TRACE   ] Loading core.hwaddr_interfaces grain
[TRACE   ] Loading core.hostname grain
[TRACE   ] Loading core.get_master grain
[TRACE   ] Loading core.pythonversion grain
[TRACE   ] Loading core.path grain
[TRACE   ] Loading core.get_server_id grain
[TRACE   ] Loading core.saltversion grain
[TRACE   ] Loading core.saltpath grain
[TRACE   ] Loading core.pythonexecutable grain
[TRACE   ] Loading core.ip_fqdn grain
[TRACE   ] Loading core.dns grain
[TRACE   ] Loading core.ip6_interfaces grain
[TRACE   ] Loading core.ip4_interfaces grain
[TRACE   ] Loading core.append_domain grain
[TRACE   ] Loading core.os_data grain
[TRACE   ] 'lspci' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
[DEBUG   ] The `lspci` binary is not available on the system. GPU grains will not be available.
[TRACE   ] DMI system-uuid value /dev/mem: No such file or directory is an invalid UUID
[TRACE   ] DMI system-uuid value /dev/mem: No such file or directory is an invalid UUID
[TRACE   ] 'virt-what' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
[DEBUG   ] Please install 'virt-what' to improve results of the 'virtual' grain.
[WARNING ] /usr/lib/python2.7/dist-packages/salt/grains/core.py:1493: DeprecationWarning: The "osmajorrelease" will be a type of an integer.

[TRACE   ] Loading core.zmqversion grain
[TRACE   ] Loading core.saltversioninfo grain
[TRACE   ] Loading core.pythonpath grain
[TRACE   ] Loading core.id_ grain
[TRACE   ] Loading core.locale_info grain
[TRACE   ] Loading core.get_machine_id grain
[TRACE   ] Loading core.ip_interfaces grain
[DEBUG   ] Connecting to master. Attempt 1 of 1
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506')
[DEBUG   ] Generated random reconnect delay between '1000ms' and '11000ms' (7921)
[DEBUG   ] Setting zmq_reconnect_ivl to '7921ms'
[DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'clear')
[TRACE   ] Inserted key into loop_instance_map id 140737407999080 for key ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'clear') and process 74848
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 140737407996416 for key ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 74848
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded state.apply
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 140737407115848 for key ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 74848
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 140737407163352 for key ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 74848
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[ERROR   ] No contents found in top file
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 140737407115560 for key ('/salt/config/pki/minion', 'artemis', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 74848
[DEBUG   ] LazyLoaded highstate.output
[TRACE   ] data = {'local': {'no_|-states_|-states_|-None': {'comment': u'No Top file or external nodes data matches found.', 'name': 'No States', 'start_time': u'', 'result': False, 'duration': u'', '__run_num__': 0, 'changes': {}}}}
local:
----------
          ID: states
    Function: no.None
      Result: False
     Comment: No Top file or external nodes data matches found.
     Started:
    Duration:
     Changes:

Summary for local
------------
Succeeded: 0
Failed:    1
------------
Total states run:     1
Total run time:   0.000 ms

master.log during salt-call

[TRACE   ] _get_event() waited 5 seconds and received nothing
[INFO    ] Authentication request from artemis
[INFO    ] Authentication accepted from artemis
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc
[TRACE   ] IPCServer: Handling connection to address:
[DEBUG   ] Sending event: tag = salt/auth; data = {'id': 'artemis', '_stamp': '2016-10-08T21:15:00.976309', 'result': True, 'pub': '-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAyZHFb4gifJHx5SuIV22O\n3pUKq0vUNuH3Votp//yoC+DH92Pd/46k+V+7j3m4FZR9CNTur13lINePZ9Shm6aI\nqxJMoR2vR+L5LUbQLnmlO9agvkt4DYlt7+YOiCW6Z5nq+AUb9OmjfEhBVTuSKEzw\nQXOSBx4Ya5Uz6YTmMcJe+hF0EJc1VmvZcEA1XUnuNgMuv/6xrM+0faxIUueZ00sB\nAH/IZeLzZsVyeZHBnqPxQNqyQ4VzDEGlCuNlyPeD7+tvY5MJTbe4nBcAfGG8FNYn\nT72xInnLLfheOYNex8rrKmmI2+zB9K+/3t2ZuJ4mJ3NZwIM6X8NbaVGm7ljUWdCu\npQIDAQAB\n-----END PUBLIC KEY-----\n', 'act': 'accept'}
[TRACE   ] get_event() received = {'tag': 'salt/auth', 'data': {'_stamp': '2016-10-08T21:15:00.976309', 'act': 'accept', 'id': 'artemis', 'pub': '-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAyZHFb4gifJHx5SuIV22O\n3pUKq0vUNuH3Votp//yoC+DH92Pd/46k+V+7j3m4FZR9CNTur13lINePZ9Shm6aI\nqxJMoR2vR+L5LUbQLnmlO9agvkt4DYlt7+YOiCW6Z5nq+AUb9OmjfEhBVTuSKEzw\nQXOSBx4Ya5Uz6YTmMcJe+hF0EJc1VmvZcEA1XUnuNgMuv/6xrM+0faxIUueZ00sB\nAH/IZeLzZsVyeZHBnqPxQNqyQ4VzDEGlCuNlyPeD7+tvY5MJTbe4nBcAfGG8FNYn\nT72xInnLLfheOYNex8rrKmmI2+zB9K+/3t2ZuJ4mJ3NZwIM6X8NbaVGm7ljUWdCu\npQIDAQAB\n-----END PUBLIC KEY-----\n', 'result': True}}
[DEBUG   ] Gathering reactors for tag salt/auth
[TRACE   ] AES payload received with command _pillar
[DEBUG   ] Determining pillar cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] compile template: /salt/pillar/top.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'jinja' renderer: 0.0146918296814
[DEBUG   ] Rendered data from file: /salt/pillar/top.sls:
######
## top pillar
## -----------------------------------
######

base:
  ## everything (last because minion config should win)
  '*':
    - salt

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['salt'])]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'yaml' renderer: 0.113229990005
[DEBUG   ] compound_match: artemis ? *
[DEBUG   ] compound_match artemis ? "*" => "True"
[DEBUG   ] compile template: /salt/pillar/salt.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'jinja' renderer: 0.00413703918457
[DEBUG   ] Rendered data from file: /salt/pillar/salt.sls:
######
## salt pillar data
## -----------------------------------
######

####
## Template: (required) [optional]
##
## salt:
##   prefix: (/salt/config)       # location for salt configuration files
##   master: (master.example.org) # salt master host
##   pkg_provider: [pkgin]        # overwrite package provider
##   schedule_apply: (0)          # schedule auto highstate runs every X minutes
##   log_level_logfile: (warning) # log level
##   smtp:
##     server: (smtp.example.org) # smtp server
##     tls: (true)                # use tls
####

salt:
  master: cronos.acheron.be
  schedule_apply: 20
  smtp:
    server: exosphere.acheron.be
    tls: true

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] Results of YAML rendering:
OrderedDict([('salt', OrderedDict([('master', 'cronos.acheron.be'), ('schedule_apply', 20), ('smtp', OrderedDict([('server', 'exosphere.acheron.be'), ('tls', True)]))]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'yaml' renderer: 0.0097541809082
[DEBUG   ] LazyLoaded localfs.store
[TRACE   ] Master function call _pillar took 0.28388094902 seconds
[TRACE   ] AES payload received with command _master_opts
[DEBUG   ] LazyLoaded roots.envs
[TRACE   ] Master function call _master_opts took 0.00274276733398 seconds
[TRACE   ] AES payload received with command _file_envs
[TRACE   ] Master function call _file_envs took 0.000266075134277 seconds
[TRACE   ] AES payload received with command _file_envs
[TRACE   ] Master function call _file_envs took 0.000289916992188 seconds
[TRACE   ] AES payload received with command _file_list
[DEBUG   ] LazyLoaded roots.envs
[TRACE   ] Lockfile /var/cache/salt/master/file_lists/roots/.base.w created
[TRACE   ] Lockfile /var/cache/salt/master/file_lists/roots/.base.w removed
[TRACE   ] Master function call _file_list took 0.0466001033783 seconds
[TRACE   ] AES payload received with command _pillar
[DEBUG   ] Determining pillar cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] compile template: /salt/pillar/top.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'jinja' renderer: 0.00322294235229
[DEBUG   ] Rendered data from file: /salt/pillar/top.sls:
######
## top pillar
## -----------------------------------
######

base:
  ## everything (last because minion config should win)
  '*':
    - salt

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['salt'])]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'yaml' renderer: 0.00576901435852
[DEBUG   ] compound_match: artemis ? *
[DEBUG   ] compound_match artemis ? "*" => "True"
[DEBUG   ] compile template: /salt/pillar/salt.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'jinja' renderer: 0.00324702262878
[DEBUG   ] Rendered data from file: /salt/pillar/salt.sls:
######
## salt pillar data
## -----------------------------------
######

####
## Template: (required) [optional]
##
## salt:
##   prefix: (/salt/config)       # location for salt configuration files
##   master: (master.example.org) # salt master host
##   pkg_provider: [pkgin]        # overwrite package provider
##   schedule_apply: (0)          # schedule auto highstate runs every X minutes
##   log_level_logfile: (warning) # log level
##   smtp:
##     server: (smtp.example.org) # smtp server
##     tls: (true)                # use tls
####

salt:
  master: cronos.acheron.be
  schedule_apply: 20
  smtp:
    server: exosphere.acheron.be
    tls: true

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] Results of YAML rendering:
OrderedDict([('salt', OrderedDict([('master', 'cronos.acheron.be'), ('schedule_apply', 20), ('smtp', OrderedDict([('server', 'exosphere.acheron.be'), ('tls', True)]))]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'yaml' renderer: 0.0093297958374
[TRACE   ] Master function call _pillar took 0.145024061203 seconds
[TRACE   ] AES payload received with command _ext_nodes
[TRACE   ] Master function call _ext_nodes took 0.0299818515778 seconds
[TRACE   ] AES payload received with command _return
[DEBUG   ] LazyLoaded local_cache.prep_jid
[DEBUG   ] Adding minions for job 20161008231501739421: ['artemis']
[INFO    ] Got return from artemis for job 20161008231501739421
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc
[TRACE   ] IPCServer: Handling connection to address:
[DEBUG   ] Sending event: tag = salt/job/20161008231501739421/ret/artemis; data = {'tgt_type': 'glob', 'fun_args': [], 'jid': '20161008231501739421', 'return': {'no_|-states_|-states_|-None': {'comment': 'No Top file or external nodes data matches found.', '__run_num__': 0, 'changes': {}, 'result': False, 'name': 'No States'}}, 'retcode': 2, 'tgt': 'artemis', 'cmd': '_return', '_stamp': '2016-10-08T21:15:01.747562', 'arg': [], 'fun': 'state.apply', 'id': 'artemis', 'out': 'highstate'}
[TRACE   ] get_event() received = {'tag': 'salt/job/20161008231501739421/ret/artemis', 'data': {'tgt_type': 'glob', 'fun_args': [], 'jid': '20161008231501739421', 'return': {'no_|-states_|-states_|-None': {'comment': 'No Top file or external nodes data matches found.', '__run_num__': 0, 'changes': {}, 'result': False, 'name': 'No States'}}, 'retcode': 2, 'tgt': 'artemis', 'cmd': '_return', '_stamp': '2016-10-08T21:15:01.747562', 'arg': [], 'fun': 'state.apply', 'id': 'artemis', 'out': 'highstate'}}
[DEBUG   ] Gathering reactors for tag salt/job/20161008231501739421/ret/artemis
[TRACE   ] Master function call _return took 0.0174200534821 seconds
[TRACE   ] _get_event() waited 5 seconds and received nothing
[TRACE   ] _get_event() waited 5 seconds and received nothing
[TRACE   ] _get_event() waited 5 seconds and received nothing
sjorge commented 8 years ago

a working 2016.11.0rc1 minion

salt-call -l trace state.apply
[DEBUG   ] Reading configuration from /opt/local/etc/salt/minion
[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   ] Including configuration from '/opt/local/etc/salt/minion.d/smtp.conf'
[DEBUG   ] Reading configuration from /opt/local/etc/salt/minion.d/smtp.conf
[TRACE   ] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[DEBUG   ] Configuration file path: /opt/local/etc/salt/minion
[WARNING ] Insecure logging configuration detected! Sensitive data may be logged.
[DEBUG   ] Reading configuration from /opt/local/etc/salt/minion
[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   ] Including configuration from '/opt/local/etc/salt/minion.d/smtp.conf'
[DEBUG   ] Reading configuration from /opt/local/etc/salt/minion.d/smtp.conf
[TRACE   ] 'dmidecode' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[TRACE   ] Loading core.hwaddr_interfaces grain
[TRACE   ] 'ip' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[TRACE   ] Loading core.hostname grain
[TRACE   ] Loading core.get_master grain
[TRACE   ] Loading core.pythonversion grain
[TRACE   ] Loading core.path grain
[TRACE   ] Loading core.get_server_id grain
[TRACE   ] Loading core.saltversion grain
[TRACE   ] Loading core.saltpath grain
[TRACE   ] Loading core.pythonexecutable grain
[TRACE   ] Loading core.ip_fqdn grain
[TRACE   ] 'ip' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[TRACE   ] 'ip' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[TRACE   ] Loading core.dns grain
[WARNING ] /etc/resolv.conf: The domain and search keywords are mutually exclusive.
[TRACE   ] Loading core.ip6_interfaces grain
[TRACE   ] Loading core.ip4_interfaces grain
[TRACE   ] Loading core.append_domain grain
[TRACE   ] Loading core.os_data grain
[TRACE   ] 'dmidecode' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[TRACE   ] 'virt-what' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[DEBUG   ] Please install 'virt-what' to improve results of the 'virtual' grain.
[TRACE   ] 'sysctl' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/opt/local/sbin', '/opt/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/usr/gnu/bin', '/usr/sfw/bin', '/bin']'
[TRACE   ] Loading core.zmqversion grain
[TRACE   ] Loading core.saltversioninfo grain
[TRACE   ] Loading core.pythonpath grain
[TRACE   ] Loading core.id_ grain
[TRACE   ] Loading core.locale_info grain
[TRACE   ] Loading core.get_machine_id grain
[TRACE   ] Loading core.ip_interfaces grain
[TRACE   ] Disk grain does not support OS
[DEBUG   ] Connecting to master. Attempt 1 of 1
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[DEBUG   ] Generated random reconnect delay between '1000ms' and '11000ms' (2201)
[DEBUG   ] Setting zmq_reconnect_ivl to '2201ms'
[DEBUG   ] Setting zmq_reconnect_ivl_max to '11000ms'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'clear')
[TRACE   ] Inserted key into loop_instance_map id 18446741324884837728 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'clear') and process 64944
[DEBUG   ] Decrypting the current master AES key
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_8d3aa1a6f2_pub.ipc
[DEBUG   ] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_8d3aa1a6f2_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/minion/minion_event_8d3aa1a6f2_pull.ipc
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_8d3aa1a6f2_pull.ipc
[DEBUG   ] Sending event: tag = salt/auth/creds; data = {'_stamp': '2016-10-08T21:16:22.389406', 'creds': {'publish_port': 4505, 'aes': 'Aq7jMBt0cvBlvppHvC8CHpyhBLibHX9Zty0ehI30RHW7AwLw9LX4eof8PHSlBy3jyLY71BTo6e0=', 'master_uri': 'tcp://[2001:470:7ee7:30::130]:4506'}, 'key': ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')}
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324885264792 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded state.apply
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324879573720 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324879638112 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] In saltenv 'base', looking at rel_path 'top.sls' to resolve 'salt://top.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/top.sls' to resolve 'salt://top.sls'
[DEBUG   ] Fetching file from saltenv 'base', ** attempting ** 'salt://top.sls'
[DEBUG   ] No dest file found
[INFO    ] Fetching file from saltenv 'base', ** done ** 'top.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/top.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/top.sls' using 'jinja' renderer: 0.0119230747223
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/top.sls:
######
## top state
## -----------------------------------
######
base:
  '*':
    - test

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['test'])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/top.sls' using 'yaml' renderer: 0.0195322036743
[DEBUG   ] compound_match: apollo ? *
[DEBUG   ] compound_match apollo ? "*" => "True"
[DEBUG   ] Loaded minion key: /salt/config/pki/minion/minion.pem
[DEBUG   ] LazyLoaded saltutil.sync_all
[DEBUG   ] Syncing all
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/beacons'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874081344 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing beacons for environment 'base'
[INFO    ] Loading cache from salt://_beacons, for base)
[INFO    ] Caching directory '_beacons/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_beacons'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324873601320 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing modules for environment 'base'
[INFO    ] Loading cache from salt://_modules, for base)
[INFO    ] Caching directory '_modules/' for environment 'base'
[DEBUG   ] In saltenv 'base', looking at rel_path '_modules/rbac_solaris.py' to resolve 'salt://_modules/rbac_solaris.py'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/_modules/rbac_solaris.py' to resolve 'salt://_modules/rbac_solaris.py'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/rbac_solaris.py', mode up-to-date
[DEBUG   ] In saltenv 'base', looking at rel_path '_modules/x509.py' to resolve 'salt://_modules/x509.py'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/_modules/x509.py' to resolve 'salt://_modules/x509.py'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_modules/x509.py', mode up-to-date
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_modules'
[INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/rbac_solaris.py' to '/var/cache/salt/minion/extmods/modules/rbac_solaris.py'
[INFO    ] Copying '/var/cache/salt/minion/files/base/_modules/x509.py' to '/var/cache/salt/minion/extmods/modules/x509.py'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324873633592 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing states for environment 'base'
[INFO    ] Loading cache from salt://_states, for base)
[INFO    ] Caching directory '_states/' for environment 'base'
[DEBUG   ] In saltenv 'base', looking at rel_path '_states/rbac_solaris.py' to resolve 'salt://_states/rbac_solaris.py'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/_states/rbac_solaris.py' to resolve 'salt://_states/rbac_solaris.py'
[INFO    ] Fetching file from saltenv 'base', ** skipped ** latest already in cache 'salt://_states/rbac_solaris.py', mode up-to-date
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_states'
[INFO    ] Copying '/var/cache/salt/minion/files/base/_states/rbac_solaris.py' to '/var/cache/salt/minion/extmods/states/rbac_solaris.py'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/sdb'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874028384 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing sdb for environment 'base'
[INFO    ] Loading cache from salt://_sdb, for base)
[INFO    ] Caching directory '_sdb/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_sdb'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/grains'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324879411248 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing grains for environment 'base'
[INFO    ] Loading cache from salt://_grains, for base)
[INFO    ] Caching directory '_grains/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_grains'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/renderers'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874043832 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing renderers for environment 'base'
[INFO    ] Loading cache from salt://_renderers, for base)
[INFO    ] Caching directory '_renderers/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_renderers'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/returners'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324879351464 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing returners for environment 'base'
[INFO    ] Loading cache from salt://_returners, for base)
[INFO    ] Caching directory '_returners/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_returners'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/output'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874110088 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing output for environment 'base'
[INFO    ] Loading cache from salt://_output, for base)
[INFO    ] Caching directory '_output/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_output'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/utils'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874075888 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing utils for environment 'base'
[INFO    ] Loading cache from salt://_utils, for base)
[INFO    ] Caching directory '_utils/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_utils'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/log_handlers'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324879217152 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing log_handlers for environment 'base'
[INFO    ] Loading cache from salt://_log_handlers, for base)
[INFO    ] Caching directory '_log_handlers/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_log_handlers'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/proxy'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874082064 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing proxy for environment 'base'
[INFO    ] Loading cache from salt://_proxy, for base)
[INFO    ] Caching directory '_proxy/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_proxy'
[INFO    ] Creating module dir '/var/cache/salt/minion/extmods/engines'
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324874080200 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[INFO    ] Syncing engines for environment 'base'
[INFO    ] Loading cache from salt://_engines, for base)
[INFO    ] Caching directory '_engines/' for environment 'base'
[DEBUG   ] Local cache dir: '/var/cache/salt/minion/files/base/_engines'
[DEBUG   ] Refreshing modules...
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] LazyLoaded saltutil.refresh_modules
[DEBUG   ] LazyLoaded event.fire
[DEBUG   ] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_8d3aa1a6f2_pub.ipc
[DEBUG   ] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_8d3aa1a6f2_pull.ipc
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/minion/minion_event_8d3aa1a6f2_pull.ipc
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_8d3aa1a6f2_pull.ipc
[DEBUG   ] Sending event: tag = module_refresh; data = {'_stamp': '2016-10-08T21:16:24.278465'}
[DEBUG   ] In saltenv 'base', looking at rel_path 'test.sls' to resolve 'salt://test.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test.sls' to resolve 'salt://test.sls'
[DEBUG   ] Fetching file from saltenv 'base', ** attempting ** 'salt://test.sls'
[DEBUG   ] No dest file found
[INFO    ] Fetching file from saltenv 'base', ** done ** 'test.sls'
[INFO    ] Fetching file from saltenv 'base', ** done ** 'test.sls', mode set to 0644
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/test.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test.sls' using 'jinja' renderer: 0.00271916389465
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/test.sls:
debugging:
  test.show_notification:
    - text: super minimal

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('debugging', OrderedDict([('test.show_notification', [OrderedDict([('text', 'super minimal')])])]))])
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/test.sls' using 'yaml' renderer: 0.00601005554199
[DEBUG   ] LazyLoaded test.show_notification
[INFO    ] Running state [debugging] at time 23:16:24.321856
[INFO    ] Executing state test.show_notification for debugging
[INFO    ] super minimal
[INFO    ] Completed state [debugging] at time 23:16:24.323335 duration_in_ms=1.479
[DEBUG   ] File /var/cache/salt/minion/accumulator/18446741324879638608 does not exist, no need to cleanup.
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] Initializing new AsyncZeroMQReqChannel for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes')
[DEBUG   ] Initializing new AsyncAuth for ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506')
[TRACE   ] Inserted key into loop_instance_map id 18446741324879577032 for key ('/salt/config/pki/minion', 'apollo', 'tcp://[2001:470:7ee7:30::130]:4506', 'aes') and process 64944
[DEBUG   ] LazyLoaded highstate.output
[TRACE   ] data = {'local': {'test_|-debugging_|-debugging_|-show_notification': {'comment': 'super minimal', 'name': 'debugging', 'start_time': '23:16:24.321856', 'result': True, 'duration': 1.479, '__run_num__': 0, 'changes': {}, '__id__': 'debugging'}}}
local:
  Name: debugging - Function: test.show_notification - Result: Clean Started: - 23:16:24.321856 Duration: 1.479 ms

Summary for local
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   1.479 ms

master.log during salt-call

[TRACE   ] _get_event() waited 5 seconds and received nothing
[TRACE   ] _get_event() waited 5 seconds and received nothing
[INFO    ] Authentication request from apollo
[INFO    ] Authentication accepted from apollo
[DEBUG   ] Initializing new IPCClient for path: /var/run/salt/master/master_event_pull.ipc
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc
[TRACE   ] IPCServer: Handling connection to address:
[DEBUG   ] Sending event: tag = salt/auth; data = {'id': 'apollo', '_stamp': '2016-10-08T21:16:22.351055', 'result': True, 'pub': '-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAxKTpchYLfcKcaaprKBtd\nt0134CIMsPmHvk8lzbUFzNaRZGE2hterObOKXP0hD+kVg7jg6VUyoEPYqVyQwX/C\nD7p3O+YnyxWq0fQdk+kQ6FdEuG4D1BYxQuLld61Rn5cFvfzyu+9rWtyCFhZLFhqg\nh5cynvuKoKlQ1QJJeAw/QtvpmuK3SvqXqPn+WOIvwxZQ3bUAmfM/Rd0QZvE7zfBf\nsWBnotK9JGNRSu3y8Otv7c1A6JhYAn++TuFS/j8nykAM9JG4kvfPSwR7s4HWhIfc\nhmhV3tNYVRgLAs0BtWcPbla1cVja6Jbh+J1WU5jtWM8mlzfnkdlAZPtG2efH7LZq\nbQIDAQAB\n-----END PUBLIC KEY-----\n', 'act': 'accept'}
[TRACE   ] get_event() received = {'tag': 'salt/auth', 'data': {'_stamp': '2016-10-08T21:16:22.351055', 'act': 'accept', 'id': 'apollo', 'pub': '-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAxKTpchYLfcKcaaprKBtd\nt0134CIMsPmHvk8lzbUFzNaRZGE2hterObOKXP0hD+kVg7jg6VUyoEPYqVyQwX/C\nD7p3O+YnyxWq0fQdk+kQ6FdEuG4D1BYxQuLld61Rn5cFvfzyu+9rWtyCFhZLFhqg\nh5cynvuKoKlQ1QJJeAw/QtvpmuK3SvqXqPn+WOIvwxZQ3bUAmfM/Rd0QZvE7zfBf\nsWBnotK9JGNRSu3y8Otv7c1A6JhYAn++TuFS/j8nykAM9JG4kvfPSwR7s4HWhIfc\nhmhV3tNYVRgLAs0BtWcPbla1cVja6Jbh+J1WU5jtWM8mlzfnkdlAZPtG2efH7LZq\nbQIDAQAB\n-----END PUBLIC KEY-----\n', 'result': True}}
[DEBUG   ] Gathering reactors for tag salt/auth
[TRACE   ] AES payload received with command _pillar
[DEBUG   ] Determining pillar cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] compile template: /salt/pillar/top.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'jinja' renderer: 0.0216407775879
[DEBUG   ] Rendered data from file: /salt/pillar/top.sls:
######
## top pillar
## -----------------------------------
######

base:
  ## everything (last because minion config should win)
  '*':
    - salt

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['salt'])]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'yaml' renderer: 0.112420082092
[DEBUG   ] compound_match: apollo ? *
[DEBUG   ] compound_match apollo ? "*" => "True"
[DEBUG   ] compile template: /salt/pillar/salt.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'jinja' renderer: 0.00339007377625
[DEBUG   ] Rendered data from file: /salt/pillar/salt.sls:
######
## salt pillar data
## -----------------------------------
######

####
## Template: (required) [optional]
##
## salt:
##   prefix: (/salt/config)       # location for salt configuration files
##   master: (master.example.org) # salt master host
##   pkg_provider: [pkgin]        # overwrite package provider
##   schedule_apply: (0)          # schedule auto highstate runs every X minutes
##   log_level_logfile: (warning) # log level
##   smtp:
##     server: (smtp.example.org) # smtp server
##     tls: (true)                # use tls
####

salt:
  master: cronos.acheron.be
  schedule_apply: 20
  smtp:
    server: exosphere.acheron.be
    tls: true

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] Results of YAML rendering:
OrderedDict([('salt', OrderedDict([('master', 'cronos.acheron.be'), ('schedule_apply', 20), ('smtp', OrderedDict([('server', 'exosphere.acheron.be'), ('tls', True)]))]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'yaml' renderer: 0.0095808506012
[DEBUG   ] LazyLoaded localfs.store
[TRACE   ] Master function call _pillar took 0.293902873993 seconds
[TRACE   ] AES payload received with command _master_opts
[TRACE   ] Master function call _master_opts took 0.000181913375854 seconds
[TRACE   ] AES payload received with command _file_envs
[TRACE   ] Master function call _file_envs took 0.000187158584595 seconds
[TRACE   ] AES payload received with command _file_list
[DEBUG   ] LazyLoaded roots.envs
[TRACE   ] Lockfile /var/cache/salt/master/file_lists/roots/.base.w created
[TRACE   ] Lockfile /var/cache/salt/master/file_lists/roots/.base.w removed
[TRACE   ] Master function call _file_list took 0.0477108955383 seconds
[TRACE   ] AES payload received with command _pillar
[DEBUG   ] Determining pillar cache
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] compile template: /salt/pillar/top.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'jinja' renderer: 0.0208029747009
[DEBUG   ] Rendered data from file: /salt/pillar/top.sls:
######
## top pillar
## -----------------------------------
######

base:
  ## everything (last because minion config should win)
  '*':
    - salt

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] LazyLoaded config.get
[DEBUG   ] Results of YAML rendering:
OrderedDict([('base', OrderedDict([('*', ['salt'])]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/top.sls' using 'yaml' renderer: 0.110960006714
[DEBUG   ] compound_match: apollo ? *
[DEBUG   ] compound_match apollo ? "*" => "True"
[DEBUG   ] compile template: /salt/pillar/salt.sls
[DEBUG   ] Jinja search path: ['/salt/pillar']
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'jinja' renderer: 0.00347208976746
[DEBUG   ] Rendered data from file: /salt/pillar/salt.sls:
######
## salt pillar data
## -----------------------------------
######

####
## Template: (required) [optional]
##
## salt:
##   prefix: (/salt/config)       # location for salt configuration files
##   master: (master.example.org) # salt master host
##   pkg_provider: [pkgin]        # overwrite package provider
##   schedule_apply: (0)          # schedule auto highstate runs every X minutes
##   log_level_logfile: (warning) # log level
##   smtp:
##     server: (smtp.example.org) # smtp server
##     tls: (true)                # use tls
####

salt:
  master: cronos.acheron.be
  schedule_apply: 20
  smtp:
    server: exosphere.acheron.be
    tls: true

# vim: tabstop=2 expandtab shiftwidth=2 softtabstop=2

[DEBUG   ] Results of YAML rendering:
OrderedDict([('salt', OrderedDict([('master', 'cronos.acheron.be'), ('schedule_apply', 20), ('smtp', OrderedDict([('server', 'exosphere.acheron.be'), ('tls', True)]))]))])
[PROFILE ] Time (in seconds) to render '/salt/pillar/salt.sls' using 'yaml' renderer: 0.00965619087219
[DEBUG   ] LazyLoaded localfs.store
[TRACE   ] Master function call _pillar took 0.285093069077 seconds
[TRACE   ] AES payload received with command _file_envs
[TRACE   ] Master function call _file_envs took 0.000202894210815 seconds
[TRACE   ] AES payload received with command _file_hash
[TRACE   ] Master function call _file_hash took 0.00163102149963 seconds
[TRACE   ] AES payload received with command _file_find
[TRACE   ] Master function call _file_find took 0.000546932220459 seconds
[TRACE   ] AES payload received with command _serve_file
[TRACE   ] Master function call _serve_file took 0.000769853591919 seconds
[TRACE   ] AES payload received with command _serve_file
[TRACE   ] Master function call _serve_file took 0.000799894332886 seconds
[TRACE   ] AES payload received with command _ext_nodes
[TRACE   ] Master function call _ext_nodes took 0.0203199386597 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00361704826355 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00360798835754 seconds
[TRACE   ] AES payload received with command _file_hash
[TRACE   ] Master function call _file_hash took 0.0018470287323 seconds
[TRACE   ] AES payload received with command _file_find
[TRACE   ] Master function call _file_find took 0.000333070755005 seconds
[TRACE   ] AES payload received with command _file_hash
[TRACE   ] Master function call _file_hash took 0.00233888626099 seconds
[TRACE   ] AES payload received with command _file_find
[TRACE   ] Master function call _file_find took 0.000349044799805 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00336003303528 seconds
[TRACE   ] AES payload received with command _file_hash
[TRACE   ] Master function call _file_hash took 0.00132989883423 seconds
[TRACE   ] AES payload received with command _file_find
[TRACE   ] Master function call _file_find took 0.00035285949707 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00342011451721 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00335001945496 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00332713127136 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00331282615662 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00349092483521 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00321793556213 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00324296951294 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00325393676758 seconds
[TRACE   ] AES payload received with command _file_list
[TRACE   ] Returning file_lists cache data from /var/cache/salt/master/file_lists/roots/base.p
[TRACE   ] Master function call _file_list took 0.00336718559265 seconds
[TRACE   ] AES payload received with command _file_hash
[TRACE   ] Master function call _file_hash took 0.00148892402649 seconds
[TRACE   ] AES payload received with command _file_find
[TRACE   ] Master function call _file_find took 0.000396013259888 seconds
[TRACE   ] AES payload received with command _serve_file
[TRACE   ] Master function call _serve_file took 0.000669002532959 seconds
[TRACE   ] AES payload received with command _serve_file
[TRACE   ] Master function call _serve_file took 0.000646114349365 seconds
[TRACE   ] AES payload received with command _return
[DEBUG   ] Adding minions for job 20161008231624349825: ['apollo']
[INFO    ] Got return from apollo for job 20161008231624349825
[DEBUG   ] Sending event: tag = salt/job/20161008231624349825/ret/apollo; data = {'tgt_type': 'glob', 'fun_args': [], 'jid': '20161008231624349825', 'return': {'test_|-debugging_|-debugging_|-show_notification': {'comment': 'super minimal', 'name': 'debugging', 'start_time': '23:16:24.321856', 'result': True, 'duration': 1.479, '__run_num__': 0, 'changes': {}, '__id__': 'debugging'}}, 'retcode': 0, 'tgt': 'apollo', 'cmd': '_return', '_stamp': '2016-10-08T21:16:24.353335', 'arg': [], 'fun': 'state.apply', 'id': 'apollo', 'out': 'highstate'}
[TRACE   ] get_event() received = {'tag': 'salt/job/20161008231624349825/ret/apollo', 'data': {'tgt_type': 'glob', 'fun_args': [], 'jid': '20161008231624349825', 'return': {'test_|-debugging_|-debugging_|-show_notification': {'comment': 'super minimal', 'name': 'debugging', 'start_time': '23:16:24.321856', 'result': True, 'duration': 1.479, '__run_num__': 0, 'changes': {}, '__id__': 'debugging'}}, 'retcode': 0, 'tgt': 'apollo', 'cmd': '_return', '_stamp': '2016-10-08T21:16:24.353335', 'arg': [], 'fun': 'state.apply', 'id': 'apollo', 'out': 'highstate'}}
[TRACE   ] Master function call _return took 0.00683903694153 seconds
[DEBUG   ] Gathering reactors for tag salt/job/20161008231624349825/ret/apollo
sjorge commented 8 years ago

Upgrading the minion to 2016.11.0rc3 fixed them problem, I did clobber the official salt package with the pip one for this though.

I guess this can be closed? Unless a new master should work with older minions?

kev009 commented 8 years ago

Yeah a new master is supposed to support older minions

Ch3LL commented 8 years ago

yes as @kev009 confirmed a new master is definitely suppose to support older minions.

I am able to confirm this behavior as shown below:

[root@cent-test-M1 ~]# salt '*' state.show_top
cent-test-M1.c7.saltstack.net:
    ----------
    base:
        - test
cent-test-min1.c7.saltstack.net:
    ----------
    base:
        - test
cent-test-min2.c7.saltstack.net:
    ----------
[root@cent-test-M1 ~]# salt '*' test.version                                                                                                                         
cent-test-min1.c7.saltstack.net:
    2016.11.0rc1
cent-test-min2.c7.saltstack.net:
    2016.3.3
cent-test-M1.c7.saltstack.net:
    2016.11.0rc1
[root@cent-test-M1 ~]# salt '*' state.apply
cent-test-min2.c7.saltstack.net:
----------
          ID: states
    Function: no.None
      Result: False
     Comment: No Top file or external nodes data matches found.
     Changes:   

Summary for cent-test-min2.c7.saltstack.net
------------
Succeeded: 0
Failed:    1
------------
Total states run:     1
Total run time:   0.000 ms
cent-test-M1.c7.saltstack.net:
----------
          ID: debugging
    Function: test.show_notification
      Result: True
     Comment: super minimal
     Started: 15:40:11.121751
    Duration: 0.605 ms
     Changes:   

Summary for cent-test-M1.c7.saltstack.net
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   0.605 ms
cent-test-min1.c7.saltstack.net:
----------
          ID: debugging
    Function: test.show_notification
      Result: True
     Comment: super minimal
     Started: 15:40:10.463821
    Duration: 0.55 ms
     Changes:   

Summary for cent-test-min1.c7.saltstack.net
------------
Succeeded: 1
Failed:    0
------------
Total states run:     1
Total run time:   0.550 ms
ERROR: Minions returned with non-zero exit code

We will definitely need to get this fixed up. Thanks for bringing this to our attention!

rallytime commented 8 years ago

I ran a git bisect on this to see where it broke, which points to #35822. Which makes a lot of sense. Git bisect specifically pointed to a28d2aaa9239c1b51c0a3af619d0e892dc82c103.

rallytime commented 8 years ago

I spoke with @terminalmage about this offline, but that is definitely where this is breaking. He knows where and how to fix it, so I am assigning this to him.

terminalmage commented 8 years ago

Yeah, so I thought I had tested this such that it would not cause problems with older minion versions. I considered this exact possibility. But it looks like I was wrong/did not test properly. Sorry for the oversight, and thanks for helping bring this to my attention. #36922 reverts the change in naming, to avoid this problem, as well as updates the docs.

meggiebot commented 8 years ago

Closing this as resolved, please re-open if this issue arises again.

ccrivelli commented 7 years ago

Well, I've just updated salt-master, salt-minion and salt-cloud from 2016.3.1-1 to 2016.11.0 and - from that time - I keep having this error when running the highstate:

----------
          ID: states
    Function: no.None
      Result: False
     Comment: No Top file or external nodes data matches found.
     Changes:   

Summary for minion.internal
------------
Succeeded: 0
Failed:    1
------------

I also tried upgrading to 2016.11.1, same error. I have only one topfile in one of my environments and I cannot figure out what the problem is (there's no change in the configuration).

As you can see, all the components are running the same version (Centos7 box):

# rpm -qa | grep salt
salt-master-2016.11.1-1.el7.noarch
salt-2016.11.1-1.el7.noarch
salt-minion-2016.11.1-1.el7.noarch
salt-cloud-2016.11.1-1.el7.noarch

I guess this issue should be re-opened @meggiebot @terminalmage

terminalmage commented 7 years ago

You say there's "no change in the configuration", but you've provided no configuration that we could use to attempt to reproduce.