Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Sync / Refresh is causing grains to be refreshed twice #55174

Closed
jtraub91 opened this issue Oct 31, 2019 · 9 comments
Closed

Sync / Refresh is causing grains to be refreshed twice #55174

jtraub91 opened this issue Oct 31, 2019 · 9 comments
Assignees
@cmcmarrow
Labels
Bug broken, incorrect, or confusing behavior Confirmed Salt engineer has confirmed bug/feature - often including a MCVE fixed-pls-verify fix is linked, bug author to confirm fix Grains v2019.2.3 unsupported version
Milestone
Approved

Comments

@jtraub91
Copy link
Contributor

jtraub91 commented Oct 31, 2019 •
edited
Loading

Description of Issue

When issuing a sync / refresh via saltutil.sync_grains or saltutil.refresh_grains, the grains functions are being evaluated at least twice.

Setup

Normal salt installation. Minion config log_level set to 'trace'. Create custom test grain to add clarity to the problem (not needed)

# /srv/salt/_grains/test_grains.py

import logging

log = logging.getLogger(__name__)


def test_grain():
    log.debug("test_grain is running")
    return {'test_grain': True}

Steps to Reproduce Issue

salt \* saltutil.sync_grains

Logs from /var/log/salt/minion:

cat /var/log/salt/minion
2019-10-31 14:48:44,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:45,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:46,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:47,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:48,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:49,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:50,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:51,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:52,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:53,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:54,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:55,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:56,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:57,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:58,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:48:59,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:00,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:01,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:02,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:03,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:04,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:05,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:06,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:07,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:08,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:09,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:10,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:11,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:12,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:13,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:14,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:15,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:16,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:17,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:18,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:19,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:20,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:21,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:22,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:23,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:24,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:25,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:26,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:27,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:28,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:29,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:30,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:31,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:32,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:33,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:34,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:35,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:36,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:37,960 [salt.transport.mixins.auth:35  ][TRACE   ][297] Decoding payload: {'load': 'g\xc4\x80[3\xad}2\x81\x83\xb1\x18\xfa\xaa\xf2\xa9\x8b\x93`\x18\xa7;\x1f\xf3\xc3{d\r\xd3\x92\xbe\xac^\xcb\xb1P\xfa\xa9\x15\x94\x03\xea\xd2\x84\xbe\x8d\xe3\x83B_\x85\nhi\x99@\xf3\x9c@\x9c\x11\x18\xda3\x92\xee\x9aJ\x80r\xf4\xb8j\x8a"\xe1\x89\xe4aCj\xc9\xa4\x99\x12\x0c\xeb\x1fe\xce\xd0mb\xbb\x89RI\xdd\xf5\x992@\x9e\x0b\x94\xad\x0fW\xd0\x97U\xda\x0e\xad\x18\xc6\x9e\x9f\x05P\xbaJcq\x10?\xa0+N\xdbN\xe8\x8f\xf5\xab\xff\x9a^\xe2\xc0\x1b78Z\x15+}\x8d.\xb0\x80\xad\xa8-\x05~\x8e\xd8Cu', 'enc': 'aes', 'sig': 'P\xbc\x86#\xd9\xc0m\xc4\xee\xa2\xd8/W\x13|.\x0e\x0b\xa3O0\x19\x1c@>\xba\xc4\xd1+nA\xea\xcb\xe6\x0f\x97\xe3$\xd5v\xc2s\xd7Jr\x82\x07i6\x8f`\x17L\n\x96\xad9\xb0z\x966\xa3T\xd6<\xbf\xbe\x9a\xf1\x8d\x95\xcb\xdd\x86\x00h\xdf\xe5l\x0f\x81\x13\xd4\xa0{\xcb\xe7\xe9#\x93{\xf2%-C"I\xa5iZ/\x851\xce\xd8\x014\x95\xd8\xda\x8c\xc9\x1b\xd7\x1d\x91\xa36\xc3\xaax{\xfa\xf4\xac)G\xb8\x01\xbc\x00\x08\xce\xac\xc6<NY\xb2B\x0baP(\x8c\xa7\xb7\xd1\xdc~\xb6\\\xf2[\xf5is\x8d.\xc3V\x87X#\xe4\xdd\x90\xc33\xbcO\x82u\xb8\xd5oY,iY\xfe"F\xe0H\xd1\x8b4\xad\xe2 \x97\x0e \x16\x0c\xdcU\x7f\xa9\x03#*+`y\xf2@}\x9a\x88\xce\xcf\xb3L\xfa\xba\x00]IA\xd4I\xe4F\x89L\x86\xf68c\x1c=!,\x87\xb3\xd5\xbf\xea\xc4\xf1I\x17\xf8=>\xca\xcaJ\x08mm=}\x05'}
2019-10-31 14:49:37,961 [salt.utils.lazy  :104 ][DEBUG   ][297] LazyLoaded glob_match.match
2019-10-31 14:49:37,962 [salt.minion      :1482][INFO    ][297] User root Executing command saltutil.sync_grains with jid 20191031144937954137
2019-10-31 14:49:37,962 [salt.minion      :1489][DEBUG   ][297] Command details {u'tgt_type': u'glob', u'jid': u'20191031144937954137', u'tgt': u'*', u'ret': u'', u'user': u'root', u'arg': [], u'fun': u'saltutil.sync_grains'}
2019-10-31 14:49:37,963 [salt.minion      :35  ][TRACE   ][297] Started JIDs: [u'20191031142534320962', u'20191031143139063706', u'20191031143855618609']
2019-10-31 14:49:37,968 [salt.utils.process:860 ][DEBUG   ][297] Subprocess SignalHandlingMultiprocessingProcess-1:6-Job-20191031144937954137 added
2019-10-31 14:49:37,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:38,012 [salt.utils.lazy  :104 ][DEBUG   ][734] LazyLoaded jinja.render
2019-10-31 14:49:38,014 [salt.utils.lazy  :104 ][DEBUG   ][734] LazyLoaded yaml.render
2019-10-31 14:49:38,015 [salt.minion      :1609][INFO    ][734] Starting a new job 20191031144937954137 with PID 734
2019-10-31 14:49:38,016 [salt.loader      :35  ][TRACE   ][734] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
2019-10-31 14:49:38,017 [salt.utils.lazy  :107 ][DEBUG   ][734] Could not LazyLoad {0}.allow_missing_func: '{0}.allow_missing_func' is not available.
2019-10-31 14:49:38,025 [salt.utils.lazy  :104 ][DEBUG   ][734] LazyLoaded saltutil.sync_grains
2019-10-31 14:49:38,025 [salt.minion      :35  ][TRACE   ][734] Executors list [u'direct_call']
2019-10-31 14:49:38,031 [salt.transport.zeromq:138 ][DEBUG   ][734] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes')
2019-10-31 14:49:38,031 [salt.crypt       :464 ][DEBUG   ][734] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506')
2019-10-31 14:49:38,032 [salt.transport.zeromq:209 ][DEBUG   ][734] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-10-31 14:49:38,033 [salt.transport.zeromq:1189][DEBUG   ][734] Trying to connect to: tcp://127.0.0.1:4506
2019-10-31 14:49:38,033 [salt.transport.zeromq:35  ][TRACE   ][734] Inserted key into loop_instance_map id 139946412914376 for key (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes') and process 734
2019-10-31 14:49:38,045 [salt.state       :736 ][DEBUG   ][734] Gathering pillar data for state run
2019-10-31 14:49:38,045 [salt.pillar      :57  ][DEBUG   ][734] Determining pillar cache
2019-10-31 14:49:38,046 [salt.transport.zeromq:138 ][DEBUG   ][734] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes')
2019-10-31 14:49:38,046 [salt.crypt       :464 ][DEBUG   ][734] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506')
2019-10-31 14:49:38,046 [salt.transport.zeromq:209 ][DEBUG   ][734] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-10-31 14:49:38,047 [salt.transport.zeromq:1189][DEBUG   ][734] Trying to connect to: tcp://127.0.0.1:4506
2019-10-31 14:49:38,047 [salt.transport.zeromq:35  ][TRACE   ][734] Inserted key into loop_instance_map id 139946413577136 for key (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes') and process 734
2019-10-31 14:49:38,048 [salt.pillar      :35  ][TRACE   ][734] ext_pillar_extra_data = {}
2019-10-31 14:49:38,095 [salt.crypt       :200 ][DEBUG   ][734] salt.crypt.get_rsa_key: Loading private key
2019-10-31 14:49:38,096 [salt.crypt       :802 ][DEBUG   ][734] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-31 14:49:38,099 [salt.transport.zeromq:233 ][DEBUG   ][734] Closing AsyncZeroMQReqChannel instance
2019-10-31 14:49:38,100 [salt.state       :750 ][DEBUG   ][734] Finished gathering pillar data for state run
2019-10-31 14:49:38,101 [salt.state       :966 ][INFO    ][734] Loading fresh modules for state activity
2019-10-31 14:49:38,132 [salt.utils.lazy  :104 ][DEBUG   ][734] LazyLoaded jinja.render
2019-10-31 14:49:38,133 [salt.utils.lazy  :104 ][DEBUG   ][734] LazyLoaded yaml.render
2019-10-31 14:49:38,144 [salt.fileclient  :1072][DEBUG   ][734] Could not find file 'salt://top.sls' in saltenv 'base'
2019-10-31 14:49:38,145 [salt.state       :3083][DEBUG   ][734] No contents loaded for saltenv 'base'
2019-10-31 14:49:38,145 [salt.state       :3100][DEBUG   ][734] No contents found in top file. If this is not expected, verify that the 'file_roots' specified in 'etc/master' are accessible. The 'file_roots' configuration is: {u'base': []}
2019-10-31 14:49:38,145 [salt.transport.zeromq:233 ][DEBUG   ][734] Closing AsyncZeroMQReqChannel instance
2019-10-31 14:49:38,154 [salt.transport.zeromq:138 ][DEBUG   ][734] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes')
2019-10-31 14:49:38,154 [salt.crypt       :464 ][DEBUG   ][734] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506')
2019-10-31 14:49:38,155 [salt.transport.zeromq:209 ][DEBUG   ][734] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-10-31 14:49:38,155 [salt.transport.zeromq:1189][DEBUG   ][734] Trying to connect to: tcp://127.0.0.1:4506
2019-10-31 14:49:38,156 [salt.transport.zeromq:35  ][TRACE   ][734] Inserted key into loop_instance_map id 139946412473664 for key (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes') and process 734
2019-10-31 14:49:38,156 [salt.utils.extmods:90  ][INFO    ][734] Syncing grains for environment 'base'
2019-10-31 14:49:38,156 [salt.utils.extmods:94  ][INFO    ][734] Loading cache from salt://_grains, for base)
2019-10-31 14:49:38,156 [salt.fileclient  :234 ][INFO    ][734] Caching directory '_grains/' for environment 'base'
2019-10-31 14:49:38,164 [salt.fileclient  :1093][DEBUG   ][734] In saltenv 'base', looking at rel_path '_grains/test_grain.py' to resolve 'salt://_grains/test_grain.py'
2019-10-31 14:49:38,165 [salt.fileclient  :1101][DEBUG   ][734] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/_grains/test_grain.py' to resolve 'salt://_grains/test_grain.py'
2019-10-31 14:49:38,165 [salt.utils.extmods:109 ][DEBUG   ][734] Local cache dir: '/var/cache/salt/minion/files/base/_grains'
2019-10-31 14:49:38,165 [salt.utils.extmods:119 ][INFO    ][734] Copying '/var/cache/salt/minion/files/base/_grains/test_grain.py' to '/var/cache/salt/minion/extmods/grains/test_grain.py'
2019-10-31 14:49:38,166 [salt.transport.zeromq:233 ][DEBUG   ][734] Closing AsyncZeroMQReqChannel instance
2019-10-31 14:49:38,167 [salt.utils.lazy  :104 ][DEBUG   ][734] LazyLoaded event.fire
2019-10-31 14:49:38,167 [salt.utils.event :322 ][DEBUG   ][734] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_877546f325_pub.ipc
2019-10-31 14:49:38,167 [salt.utils.event :323 ][DEBUG   ][734] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:38,168 [salt.transport.ipc:35  ][TRACE   ][734] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:38,168 [salt.utils.event :737 ][DEBUG   ][734] Sending event: tag = module_refresh; data = {u'_stamp': '2019-10-31T14:49:38.168925'}
2019-10-31 14:49:38,169 [salt.transport.ipc:35  ][TRACE   ][297] IPCServer: Handling connection to address:
2019-10-31 14:49:38,169 [salt.transport.ipc:364 ][DEBUG   ][734] Closing IPCMessageClient instance
2019-10-31 14:49:38,169 [salt.utils.event :322 ][DEBUG   ][734] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_877546f325_pub.ipc
2019-10-31 14:49:38,170 [salt.utils.event :323 ][DEBUG   ][734] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:38,170 [salt.transport.ipc:35  ][TRACE   ][734] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:38,170 [salt.transport.ipc:35  ][TRACE   ][297] Client disconnected from IPC /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:38,170 [salt.utils.event :737 ][DEBUG   ][734] Sending event: tag = pillar_refresh; data = {u'_stamp': '2019-10-31T14:49:38.170710'}
2019-10-31 14:49:38,170 [salt.transport.ipc:35  ][TRACE   ][297] IPCServer: Handling connection to address:
2019-10-31 14:49:38,171 [salt.transport.ipc:364 ][DEBUG   ][734] Closing IPCMessageClient instance
2019-10-31 14:49:38,171 [salt.minion      :807 ][DEBUG   ][734] Minion return retry timer set to 8 seconds (randomized)
2019-10-31 14:49:38,171 [salt.minion      :1937][INFO    ][734] Returning information for job: 20191031144937954137
2019-10-31 14:49:38,171 [salt.transport.ipc:35  ][TRACE   ][297] Client disconnected from IPC /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:38,171 [salt.minion      :35  ][TRACE   ][734] Return data: {u'fun_args': [], u'jid': u'20191031144937954137', u'return': [], u'retcode': 0, u'success': True, u'fun': u'saltutil.sync_grains'}
2019-10-31 14:49:38,172 [salt.transport.zeromq:138 ][DEBUG   ][734] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes')
2019-10-31 14:49:38,172 [salt.crypt       :464 ][DEBUG   ][734] Initializing new AsyncAuth for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506')
2019-10-31 14:49:38,172 [salt.transport.zeromq:209 ][DEBUG   ][734] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-10-31 14:49:38,172 [salt.minion      :2360][DEBUG   ][297] Minion of 'localhost' is handling event tag 'module_refresh'
2019-10-31 14:49:38,172 [salt.minion      :2161][DEBUG   ][297] Refreshing modules. Notify=False
2019-10-31 14:49:38,173 [salt.transport.zeromq:1189][DEBUG   ][734] Trying to connect to: tcp://127.0.0.1:4506
2019-10-31 14:49:38,173 [salt.loader      :747 ][DEBUG   ][297] Grains refresh requested. Refreshing grains.
2019-10-31 14:49:38,173 [salt.transport.zeromq:35  ][TRACE   ][734] Inserted key into loop_instance_map id 139946412323760 for key (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes') and process 734
2019-10-31 14:49:38,173 [salt.config      :2185][DEBUG   ][297] Reading configuration from /etc/salt/minion
2019-10-31 14:49:38,176 [salt.config      :2329][DEBUG   ][297] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2019-10-31 14:49:38,177 [salt.config      :2185][DEBUG   ][297] Reading configuration from /etc/salt/minion.d/_schedule.conf
2019-10-31 14:49:38,180 [salt.transport.zeromq:233 ][DEBUG   ][734] Closing AsyncZeroMQReqChannel instance
2019-10-31 14:49:38,183 [salt.minion      :35  ][TRACE   ][734] ret_val = None
2019-10-31 14:49:38,183 [salt.minion      :1787][DEBUG   ][734] minion return: {u'fun_args': [], u'jid': u'20191031144937954137', u'return': [], u'retcode': 0, u'success': True, u'fun': u'saltutil.sync_grains'}
2019-10-31 14:49:38,186 [salt.loader      :35  ][TRACE   ][297] Error loading grains.napalm: "napalm"" (/usr/lib/python2.7/dist-packages/salt/grains/napalm.pyc) cannot be loaded: NAPALM is not installed: ``pip install napalm``
2019-10-31 14:49:38,187 [salt.loader      :35  ][TRACE   ][297] Loading core.append_domain grain
2019-10-31 14:49:38,188 [salt.loader      :35  ][TRACE   ][297] Loading core.default_gateway grain
2019-10-31 14:49:38,188 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,189 [salt.loader      :35  ][TRACE   ][297] Loading core.dns grain
2019-10-31 14:49:38,189 [salt.loader      :35  ][TRACE   ][297] Loading core.fqdns grain
2019-10-31 14:49:38,189 [salt.loader      :35  ][TRACE   ][297] Loading core.get_machine_id grain
2019-10-31 14:49:38,190 [salt.loader      :35  ][TRACE   ][297] Loading core.get_master grain
2019-10-31 14:49:38,190 [salt.loader      :35  ][TRACE   ][297] Loading core.get_server_id grain
2019-10-31 14:49:38,190 [salt.loader      :35  ][TRACE   ][297] Loading core.hostname grain
2019-10-31 14:49:38,191 [salt.loader      :35  ][TRACE   ][297] Loading core.hwaddr_interfaces grain
2019-10-31 14:49:38,191 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,192 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,192 [salt.loader      :35  ][TRACE   ][297] Loading core.id_ grain
2019-10-31 14:49:38,192 [salt.loader      :35  ][TRACE   ][297] Loading core.ip4_interfaces grain
2019-10-31 14:49:38,193 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,193 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,193 [salt.loader      :35  ][TRACE   ][297] Loading core.ip6_interfaces grain
2019-10-31 14:49:38,194 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,194 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,195 [salt.loader      :35  ][TRACE   ][297] Loading core.ip_fqdn grain
2019-10-31 14:49:38,195 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,196 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,196 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,197 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,197 [salt.loader      :35  ][TRACE   ][297] Loading core.ip_interfaces grain
2019-10-31 14:49:38,198 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,198 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:38,198 [salt.loader      :35  ][TRACE   ][297] Loading core.linux_distribution grain
2019-10-31 14:49:38,199 [salt.loader      :35  ][TRACE   ][297] Loading core.locale_info grain
2019-10-31 14:49:38,199 [salt.loader      :35  ][TRACE   ][297] Loading core.os_data grain
2019-10-31 14:49:39,200 [salt.loaded.int.grains.core:35  ][TRACE   ][297] Adding init grain
2019-10-31 14:49:39,201 [salt.utils.path  :35  ][TRACE   ][297] 'dumb-init' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:39,202 [salt.utils.path  :35  ][TRACE   ][297] 'tini' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:39,202 [salt.loaded.int.grains.core:1768][DEBUG   ][297] Could not determine init system from command line: (/bin/bash)
2019-10-31 14:49:39,202 [salt.loaded.int.grains.core:35  ][TRACE   ][297] Getting lsb_release distro information
2019-10-31 14:49:39,202 [salt.loaded.int.grains.core:35  ][TRACE   ][297] Getting OS name, release, and codename from platform.linux_distribution()
2019-10-31 14:49:40,270 [salt.utils.path  :35  ][TRACE   ][297] 'virt-what' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:40,271 [salt.utils.path  :35  ][TRACE   ][297] 'systemd-detect-virt' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:40,272 [salt.utils.path  :35  ][TRACE   ][297] 'virt-what' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,757 [salt.loaded.int.grains.core:1063][INFO    ][297] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-10-31 14:49:41,758 [salt.loader      :35  ][TRACE   ][297] Loading core.path grain
2019-10-31 14:49:41,758 [salt.loader      :35  ][TRACE   ][297] Loading core.pythonexecutable grain
2019-10-31 14:49:41,759 [salt.loader      :35  ][TRACE   ][297] Loading core.pythonpath grain
2019-10-31 14:49:41,759 [salt.loader      :35  ][TRACE   ][297] Loading core.pythonversion grain
2019-10-31 14:49:41,760 [salt.loader      :35  ][TRACE   ][297] Loading core.saltpath grain
2019-10-31 14:49:41,760 [salt.loader      :35  ][TRACE   ][297] Loading core.saltversion grain
2019-10-31 14:49:41,760 [salt.loader      :35  ][TRACE   ][297] Loading core.saltversioninfo grain
2019-10-31 14:49:41,760 [salt.loader      :35  ][TRACE   ][297] Loading core.zmqversion grain
2019-10-31 14:49:41,761 [salt.loader      :35  ][TRACE   ][297] Loading test_grain.test_grain grain
2019-10-31 14:49:41,761 [salt.loaded.ext.grains.test_grain:8   ][DEBUG   ][297] test_grain is running
2019-10-31 14:49:41,761 [salt.loader      :35  ][TRACE   ][297] Loading disks.disks grain
2019-10-31 14:49:41,762 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop1 reports itself as an HDD
2019-10-31 14:49:41,762 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop6 reports itself as an HDD
2019-10-31 14:49:41,763 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device vdb reports itself as an HDD
2019-10-31 14:49:41,763 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop4 reports itself as an HDD
2019-10-31 14:49:41,764 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop2 reports itself as an HDD
2019-10-31 14:49:41,764 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop0 reports itself as an HDD
2019-10-31 14:49:41,764 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop7 reports itself as an HDD
2019-10-31 14:49:41,764 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop5 reports itself as an HDD
2019-10-31 14:49:41,765 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device vda reports itself as an HDD
2019-10-31 14:49:41,765 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop3 reports itself as an HDD
2019-10-31 14:49:41,765 [salt.loader      :35  ][TRACE   ][297] Loading extra.config grain
2019-10-31 14:49:41,766 [salt.loader      :35  ][TRACE   ][297] Loading extra.shell grain
2019-10-31 14:49:41,766 [salt.loader      :35  ][TRACE   ][297] Loading mdadm.mdadm grain
2019-10-31 14:49:41,766 [salt.loader      :35  ][TRACE   ][297] Loading minion_process.grains grain
2019-10-31 14:49:41,767 [salt.loader      :35  ][TRACE   ][297] Loading opts.opts grain
2019-10-31 14:49:41,767 [salt.loader      :35  ][TRACE   ][297] Loading zfs.zfs grain
2019-10-31 14:49:41,768 [salt.utils.path  :35  ][TRACE   ][297] 'zfs-fuse' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,769 [salt.utils.path  :35  ][TRACE   ][297] 'zpool' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,795 [salt.minion      :2360][DEBUG   ][297] Minion of 'localhost' is handling event tag 'pillar_refresh'
2019-10-31 14:49:41,795 [salt.minion      :2190][DEBUG   ][297] Refreshing pillar
2019-10-31 14:49:41,796 [salt.transport.zeromq:138 ][DEBUG   ][297] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes')
2019-10-31 14:49:41,796 [salt.crypt       :472 ][DEBUG   ][297] Re-using AsyncAuth for (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506')
2019-10-31 14:49:41,796 [salt.transport.zeromq:209 ][DEBUG   ][297] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-10-31 14:49:41,797 [salt.transport.zeromq:1189][DEBUG   ][297] Trying to connect to: tcp://127.0.0.1:4506
2019-10-31 14:49:41,798 [salt.transport.zeromq:35  ][TRACE   ][297] Inserted key into loop_instance_map id 139946413579944 for key (u'/etc/salt/pki/minion', u'ubuntu-salt-test', u'tcp://127.0.0.1:4506', u'aes') and process 297
2019-10-31 14:49:41,798 [salt.pillar      :35  ][TRACE   ][297] ext_pillar_extra_data = {}
2019-10-31 14:49:41,800 [salt.utils.lazy  :104 ][DEBUG   ][297] LazyLoaded config.merge
2019-10-31 14:49:41,800 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:41,801 [salt.utils.lazy  :104 ][DEBUG   ][297] LazyLoaded mine.update
2019-10-31 14:49:41,801 [salt.utils.process:869 ][DEBUG   ][297] Subprocess SignalHandlingMultiprocessingProcess-1:6-Job-20191031144937954137 cleaned up
2019-10-31 14:49:41,840 [salt.crypt       :200 ][DEBUG   ][297] salt.crypt.get_rsa_key: Loading private key
2019-10-31 14:49:41,841 [salt.crypt       :802 ][DEBUG   ][297] Loaded minion key: /etc/salt/pki/minion/minion.pem
2019-10-31 14:49:41,844 [salt.transport.zeromq:233 ][DEBUG   ][297] Closing AsyncZeroMQReqChannel instance
2019-10-31 14:49:41,844 [salt.minion      :2161][DEBUG   ][297] Refreshing modules. Notify=False
2019-10-31 14:49:41,844 [salt.loader      :747 ][DEBUG   ][297] Grains refresh requested. Refreshing grains.
2019-10-31 14:49:41,845 [salt.config      :2185][DEBUG   ][297] Reading configuration from /etc/salt/minion
2019-10-31 14:49:41,845 [salt.config      :2329][DEBUG   ][297] Including configuration from '/etc/salt/minion.d/_schedule.conf'
2019-10-31 14:49:41,846 [salt.config      :2185][DEBUG   ][297] Reading configuration from /etc/salt/minion.d/_schedule.conf
2019-10-31 14:49:41,851 [salt.loader      :35  ][TRACE   ][297] Error loading grains.napalm: "napalm"" (/usr/lib/python2.7/dist-packages/salt/grains/napalm.pyc) cannot be loaded: NAPALM is not installed: ``pip install napalm``
2019-10-31 14:49:41,852 [salt.loader      :35  ][TRACE   ][297] Loading core.append_domain grain
2019-10-31 14:49:41,852 [salt.loader      :35  ][TRACE   ][297] Loading core.default_gateway grain
2019-10-31 14:49:41,852 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,852 [salt.loader      :35  ][TRACE   ][297] Loading core.dns grain
2019-10-31 14:49:41,853 [salt.loader      :35  ][TRACE   ][297] Loading core.fqdns grain
2019-10-31 14:49:41,853 [salt.loader      :35  ][TRACE   ][297] Loading core.get_machine_id grain
2019-10-31 14:49:41,853 [salt.loader      :35  ][TRACE   ][297] Loading core.get_master grain
2019-10-31 14:49:41,853 [salt.loader      :35  ][TRACE   ][297] Loading core.get_server_id grain
2019-10-31 14:49:41,853 [salt.loader      :35  ][TRACE   ][297] Loading core.hostname grain
2019-10-31 14:49:41,854 [salt.loader      :35  ][TRACE   ][297] Loading core.hwaddr_interfaces grain
2019-10-31 14:49:41,854 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,854 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,854 [salt.loader      :35  ][TRACE   ][297] Loading core.id_ grain
2019-10-31 14:49:41,854 [salt.loader      :35  ][TRACE   ][297] Loading core.ip4_interfaces grain
2019-10-31 14:49:41,855 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,855 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,855 [salt.loader      :35  ][TRACE   ][297] Loading core.ip6_interfaces grain
2019-10-31 14:49:41,856 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,856 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,856 [salt.loader      :35  ][TRACE   ][297] Loading core.ip_fqdn grain
2019-10-31 14:49:41,856 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,857 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,857 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,857 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,857 [salt.loader      :35  ][TRACE   ][297] Loading core.ip_interfaces grain
2019-10-31 14:49:41,858 [salt.utils.path  :35  ][TRACE   ][297] 'ip' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,858 [salt.utils.path  :35  ][TRACE   ][297] 'ifconfig' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:41,858 [salt.loader      :35  ][TRACE   ][297] Loading core.linux_distribution grain
2019-10-31 14:49:41,858 [salt.loader      :35  ][TRACE   ][297] Loading core.locale_info grain
2019-10-31 14:49:41,859 [salt.loader      :35  ][TRACE   ][297] Loading core.os_data grain
2019-10-31 14:49:42,869 [salt.loaded.int.grains.core:35  ][TRACE   ][297] Adding init grain
2019-10-31 14:49:42,870 [salt.utils.path  :35  ][TRACE   ][297] 'dumb-init' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:42,871 [salt.utils.path  :35  ][TRACE   ][297] 'tini' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:42,871 [salt.loaded.int.grains.core:1768][DEBUG   ][297] Could not determine init system from command line: (/bin/bash)
2019-10-31 14:49:42,871 [salt.loaded.int.grains.core:35  ][TRACE   ][297] Getting lsb_release distro information
2019-10-31 14:49:42,872 [salt.loaded.int.grains.core:35  ][TRACE   ][297] Getting OS name, release, and codename from platform.linux_distribution()
2019-10-31 14:49:43,880 [salt.utils.path  :35  ][TRACE   ][297] 'virt-what' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:43,881 [salt.utils.path  :35  ][TRACE   ][297] 'systemd-detect-virt' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:43,881 [salt.utils.path  :35  ][TRACE   ][297] 'virt-what' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:45,432 [salt.loaded.int.grains.core:1063][INFO    ][297] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-10-31 14:49:45,434 [salt.loader      :35  ][TRACE   ][297] Loading core.path grain
2019-10-31 14:49:45,434 [salt.loader      :35  ][TRACE   ][297] Loading core.pythonexecutable grain
2019-10-31 14:49:45,434 [salt.loader      :35  ][TRACE   ][297] Loading core.pythonpath grain
2019-10-31 14:49:45,435 [salt.loader      :35  ][TRACE   ][297] Loading core.pythonversion grain
2019-10-31 14:49:45,435 [salt.loader      :35  ][TRACE   ][297] Loading core.saltpath grain
2019-10-31 14:49:45,435 [salt.loader      :35  ][TRACE   ][297] Loading core.saltversion grain
2019-10-31 14:49:45,436 [salt.loader      :35  ][TRACE   ][297] Loading core.saltversioninfo grain
2019-10-31 14:49:45,436 [salt.loader      :35  ][TRACE   ][297] Loading core.zmqversion grain
2019-10-31 14:49:45,436 [salt.loader      :35  ][TRACE   ][297] Loading test_grain.test_grain grain
2019-10-31 14:49:45,437 [salt.loaded.ext.grains.test_grain:8   ][DEBUG   ][297] test_grain is running
2019-10-31 14:49:45,437 [salt.loader      :35  ][TRACE   ][297] Loading disks.disks grain
2019-10-31 14:49:45,438 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop1 reports itself as an HDD
2019-10-31 14:49:45,439 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop6 reports itself as an HDD
2019-10-31 14:49:45,439 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device vdb reports itself as an HDD
2019-10-31 14:49:45,440 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop4 reports itself as an HDD
2019-10-31 14:49:45,440 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop2 reports itself as an HDD
2019-10-31 14:49:45,440 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop0 reports itself as an HDD
2019-10-31 14:49:45,441 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop7 reports itself as an HDD
2019-10-31 14:49:45,441 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop5 reports itself as an HDD
2019-10-31 14:49:45,441 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device vda reports itself as an HDD
2019-10-31 14:49:45,441 [salt.loaded.int.grains.disks:35  ][TRACE   ][297] Device loop3 reports itself as an HDD
2019-10-31 14:49:45,441 [salt.loader      :35  ][TRACE   ][297] Loading extra.config grain
2019-10-31 14:49:45,441 [salt.loader      :35  ][TRACE   ][297] Loading extra.shell grain
2019-10-31 14:49:45,441 [salt.loader      :35  ][TRACE   ][297] Loading mdadm.mdadm grain
2019-10-31 14:49:45,442 [salt.loader      :35  ][TRACE   ][297] Loading minion_process.grains grain
2019-10-31 14:49:45,442 [salt.loader      :35  ][TRACE   ][297] Loading opts.opts grain
2019-10-31 14:49:45,442 [salt.loader      :35  ][TRACE   ][297] Loading zfs.zfs grain
2019-10-31 14:49:45,442 [salt.utils.path  :35  ][TRACE   ][297] 'zfs-fuse' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:45,443 [salt.utils.path  :35  ][TRACE   ][297] 'zpool' could not be found in the following search path: '[u'/usr/local/sbin', u'/usr/local/bin', u'/usr/sbin', u'/usr/bin', u'/sbin', u'/bin']'
2019-10-31 14:49:45,470 [salt.minion      :2180][DEBUG   ][297] Refreshing matchers.
2019-10-31 14:49:45,471 [salt.minion      :2173][DEBUG   ][297] Refreshing beacons.
2019-10-31 14:49:45,473 [salt.utils.event :322 ][DEBUG   ][297] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_877546f325_pub.ipc
2019-10-31 14:49:45,473 [salt.utils.event :323 ][DEBUG   ][297] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:45,474 [salt.transport.ipc:35  ][TRACE   ][297] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_877546f325_pub.ipc
2019-10-31 14:49:45,474 [salt.transport.ipc:35  ][TRACE   ][297] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:45,474 [salt.utils.event :737 ][DEBUG   ][297] Sending event: tag = /salt/minion/minion_pillar_refresh_complete; data = {u'_stamp': '2019-10-31T14:49:45.474908', u'complete': True}
2019-10-31 14:49:45,475 [salt.transport.ipc:364 ][DEBUG   ][297] Closing IPCMessageSubscriber instance
2019-10-31 14:49:45,475 [salt.transport.ipc:364 ][DEBUG   ][297] Closing IPCMessageClient instance
2019-10-31 14:49:45,475 [salt.transport.ipc:35  ][TRACE   ][297] IPCServer: Handling connection to address:
2019-10-31 14:49:45,476 [salt.transport.ipc:35  ][TRACE   ][297] IPCServer: Handling connection to address:
2019-10-31 14:49:45,476 [salt.transport.ipc:35  ][TRACE   ][297] Client disconnected from IPC /var/run/salt/minion/minion_event_877546f325_pull.ipc
2019-10-31 14:49:45,477 [salt.utils.lazy  :104 ][DEBUG   ][297] LazyLoaded config.merge
2019-10-31 14:49:45,477 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:45,478 [salt.utils.lazy  :104 ][DEBUG   ][297] LazyLoaded mine.update
2019-10-31 14:49:45,478 [salt.transport.ipc:35  ][TRACE   ][297] Client disconnected from IPC /var/run/salt/minion/minion_event_877546f325_pub.ipc
2019-10-31 14:49:45,478 [salt.minion      :2360][DEBUG   ][297] Minion of 'localhost' is handling event tag '/salt/minion/minion_pillar_refresh_complete'
2019-10-31 14:49:45,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:46,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:47,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:48,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:49,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:50,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:51,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:52,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:53,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:54,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:55,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:56,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:57,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:58,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:49:59,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:00,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:01,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:02,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:03,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:04,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:05,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:06,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:07,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:08,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:09,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:10,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:11,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:12,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:13,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:14,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:15,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:16,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:17,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:18,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:19,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:20,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:21,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:22,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:23,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:24,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:25,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:26,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:27,989 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====
2019-10-31 14:50:28,988 [salt.utils.schedule:35  ][TRACE   ][297] ==== evaluating schedule now None =====

Versions Report

Salt Version:
           Salt: 2019.2.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 2.6.1
      docker-py: Not Installed
          gitdb: 2.0.3
      gitpython: 2.1.8
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 1.0.7
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.15+ (default, Oct  7 2019, 17:39:04)
   python-gnupg: 0.4.1
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: 2.0.3
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.5

System Versions:
           dist: Ubuntu 18.04 bionic
         locale: ANSI_X3.4-1968
        machine: x86_64
        release: 5.0.0-32-generic
         system: Linux
        version: Ubuntu 18.04 bionic
@cmcmarrow cmcmarrow added Confirmed Salt engineer has confirmed bug/feature - often including a MCVE v2019.2.2 unsupported version Grains labels Oct 31, 2019
@cmcmarrow cmcmarrow added this to the Approved milestone Oct 31, 2019
@cmcmarrow
Copy link
Contributor

Thanks @jtraub91 for reporting this performance problem!

@cmcmarrow cmcmarrow added the Bug broken, incorrect, or confusing behavior label Oct 31, 2019
@KChandrashekhar KChandrashekhar added v2019.2.3 unsupported version and removed v2019.2.2 unsupported version labels Nov 5, 2019
@jtraub91
Copy link
Contributor Author

jtraub91 commented Nov 7, 2019 •
edited
Loading

Furthermore, for proxy minions, upon boot, the grains are refreshed 8 times !

The following proxy pillar was setup:

# /srv/pillar/dummy_proxy.sls

proxy:
  proxytype: dummy


# /srv/pillar/top.sls

base:
  'dummy_proxy'
    - dummy_proxy

With a test grain:

# /srv/salt/_grains/test_grain.py

import logging

__proxyenabled__ = ['*']

log = logging.getLogger(__name__)


def test_grain():
    log.debug("test_grain is running")
    return {'test_grain': True}

Start the proxy:

salt-proxy --proxyid=dummy_proxy -d

Proof:

# tail -n 500 /var/log/salt/proxy | grep "Setting up"
2019-11-07 20:13:07,538 [salt.cli.daemons :85  ][INFO    ][29500] Setting up "dummy_proxy" the Salt ProxyMinion

Observe the setup timestamp ^

# tail -n 400 /var/log/salt/proxy | grep "test_grain is running"
2019-11-07 20:13:10,605 [salt.loaded.ext.grains.test_grain                     :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:12,522 [salt.loaded.ext.grains.test_grain                     :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:14,125 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:16,179 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:18,697 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:20,246 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:21,908 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:23,464 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running

Full debug logs:

2019-11-07 20:13:07,538 [salt.utils.verify:558 ][WARNING ][29500] Insecure logging configuration detected! Sensitive data may be logged.
2019-11-07 20:13:07,538 [salt.cli.daemons :85  ][INFO    ][29500] Setting up "dummy_proxy" the Salt ProxyMinion
2019-11-07 20:13:07,585 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'base64_encode' as a jinja filter
2019-11-07 20:13:07,585 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'base64_decode' as a jinja filter
2019-11-07 20:13:07,585 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'md5' as a jinja filter
2019-11-07 20:13:07,586 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'sha256' as a jinja filter
2019-11-07 20:13:07,586 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'sha512' as a jinja filter
2019-11-07 20:13:07,586 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'hmac' as a jinja filter
2019-11-07 20:13:07,586 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'random_hash' as a jinja filter
2019-11-07 20:13:07,586 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'rand_str' as a jinja filter
2019-11-07 20:13:07,586 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'file_hashsum' as a jinja filter
2019-11-07 20:13:07,683 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'http_query' as a jinja filter
2019-11-07 20:13:07,685 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'strftime' as a jinja filter
2019-11-07 20:13:07,685 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'date_format' as a jinja filter
2019-11-07 20:13:07,685 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'yaml_dquote' as a jinja filter
2019-11-07 20:13:07,685 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'yaml_squote' as a jinja filter
2019-11-07 20:13:07,685 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'yaml_encode' as a jinja filter
2019-11-07 20:13:07,688 [salt.utils.decorators.jinja              :81  ][DEBUG   ][29500] Marking 'raise' as a jinja global
2019-11-07 20:13:07,688 [salt.utils.decorators.jinja              :56  ][DEBUG   ][29500] Marking 'match' as a jinja test
2019-11-07 20:13:07,688 [salt.utils.decorators.jinja              :56  ][DEBUG   ][29500] Marking 'equalto' as a jinja test
2019-11-07 20:13:07,688 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'skip' as a jinja filter
2019-11-07 20:13:07,688 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'sequence' as a jinja filter
2019-11-07 20:13:07,688 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'to_bool' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'tojson' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'quote' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'regex_escape' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'regex_search' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'regex_match' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'regex_replace' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'uuid' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'unique' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'min' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'max' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'avg' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'union' as a jinja filter
2019-11-07 20:13:07,689 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'intersect' as a jinja filter
2019-11-07 20:13:07,690 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'difference' as a jinja filter
2019-11-07 20:13:07,690 [salt.utils.decorators.jinja              :31  ][DEBUG   ][29500] Marking 'symmetric_difference' as a jinja filter
2019-11-07 20:13:07,709 [salt.utils.process                       :206 ][DEBUG   ][29508] Created pidfile: /var/run/salt/dummy_proxy/salt-minion.pid
2019-11-07 20:13:07,710 [salt.cli.daemons                         :85  ][INFO    ][29508] The Proxy Minion is starting up the Salt ProxyMinion
2019-11-07 20:13:07,710 [salt.utils.event                         :981 ][DEBUG   ][29508] AsyncEventPublisher PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:07,710 [salt.utils.event                         :983 ][DEBUG   ][29508] AsyncEventPublisher PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:07,710 [salt.utils.event                         :1019][INFO    ][29508] Starting pull socket on /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:07,711 [salt.utils.event                         :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:07,711 [salt.utils.event                         :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:07,713 [salt.minion                              :1151][INFO    ][29508] Creating minion process manager
2019-11-07 20:13:07,713 [salt.utils.process                       :515 ][DEBUG   ][29508] Process Manager starting!
2019-11-07 20:13:07,713 [salt.utils.process                       :515 ][DEBUG   ][29508] Process Manager starting!
2019-11-07 20:13:07,713 [salt.minion                              :726 ][DEBUG   ][29508] Connecting to master. Attempt 1 of 1
2019-11-07 20:13:07,714 [salt.utils.network                       :2004][DEBUG   ][29508] "localhost" Not an IP address? Assuming it is a hostname.
2019-11-07 20:13:07,715 [salt.minion                              :236 ][DEBUG   ][29508] Master URI: tcp://127.0.0.1:4506
2019-11-07 20:13:07,794 [git.cmd                                  :719 ][DEBUG   ][29508] Popen(['git', 'version'], cwd=/, universal_newlines=False, shell=None)
2019-11-07 20:13:08,306 [git.cmd                                  :719 ][DEBUG   ][29508] Popen(['git', 'version'], cwd=/, universal_newlines=False, shell=None)
2019-11-07 20:13:08,808 [salt.crypt                               :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:08,811 [salt.transport.zeromq                    :449 ][DEBUG   ][29508] Generated random reconnect delay between '1000ms' and '11000ms' (7121)
2019-11-07 20:13:08,811 [salt.transport.zeromq                    :452 ][DEBUG   ][29508] Setting zmq_reconnect_ivl to '7121ms'
2019-11-07 20:13:08,811 [salt.transport.zeromq                    :458 ][DEBUG   ][29508] Setting zmq_reconnect_ivl_max to '11000ms'
2019-11-07 20:13:08,812 [salt.transport.zeromq                    :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', 'clear')
2019-11-07 20:13:08,812 [salt.transport.zeromq                    :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:08,813 [salt.transport.zeromq                    :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:08,813 [salt.crypt                               :208 ][DEBUG   ][29508] salt.crypt.get_rsa_pub_key: Loading public key
2019-11-07 20:13:08,826 [salt.crypt                               :873 ][DEBUG   ][29508] Decrypting the current master AES key
2019-11-07 20:13:08,826 [salt.crypt                               :200 ][DEBUG   ][29508] salt.crypt.get_rsa_key: Loading private key
2019-11-07 20:13:08,827 [salt.crypt                               :180 ][DEBUG   ][29508] salt.crypt._get_key_with_evict: Loading private key
2019-11-07 20:13:08,830 [salt.crypt                               :802 ][DEBUG   ][29508] Loaded minion key: /etc/salt/pki/proxy/minion.pem
2019-11-07 20:13:08,836 [salt.crypt                               :208 ][DEBUG   ][29508] salt.crypt.get_rsa_pub_key: Loading public key
2019-11-07 20:13:08,840 [salt.transport.zeromq                    :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:08,841 [salt.transport.zeromq                    :509 ][DEBUG   ][29508] Connecting the Minion to the Master publish port, using the URI: tcp://127.0.0.1:4505
2019-11-07 20:13:08,841 [salt.crypt                               :200 ][DEBUG   ][29508] salt.crypt.get_rsa_key: Loading private key
2019-11-07 20:13:08,841 [salt.crypt                               :802 ][DEBUG   ][29508] Loaded minion key: /etc/salt/pki/proxy/minion.pem
2019-11-07 20:13:08,845 [salt.utils.lazy                          :104 ][DEBUG   ][29508] LazyLoaded proxy.post_master_init
2019-11-07 20:13:08,846 [salt.loaded.int.metaproxy.proxy          :72  ][DEBUG   ][29508] subclassed LazyLoaded _post_master_init
2019-11-07 20:13:08,846 [salt.transport.zeromq                    :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:08,846 [salt.crypt                               :472 ][DEBUG   ][29508] Re-using AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:08,846 [salt.transport.zeromq                    :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:08,846 [salt.transport.zeromq                    :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:08,899 [salt.crypt                               :200 ][DEBUG   ][29508] salt.crypt.get_rsa_key: Loading private key
2019-11-07 20:13:08,899 [salt.crypt                               :802 ][DEBUG   ][29508] Loaded minion key: /etc/salt/pki/proxy/minion.pem
2019-11-07 20:13:08,902 [salt.transport.zeromq                    :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:08,903 [salt.loader                              :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:08,903 [salt.config                              :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:08,904 [salt.config                              :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:08,904 [salt.config                              :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:10,603 [salt.loaded.int.grains.core                           :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:10,604 [salt.loaded.int.grains.core                           :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:10,605 [salt.loaded.ext.grains.test_grain                     :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:10,605 [salt.loaded.int.grains.extra                          :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:10,645 [salt.utils.lazy                                       :104 ][DEBUG   ][29508] LazyLoaded saltutil.sync_all
2019-11-07 20:13:10,646 [salt.loader.localhost.int.module.saltutil             :968 ][DEBUG   ][29508] Syncing all
2019-11-07 20:13:10,654 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,655 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,656 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,656 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,669 [salt.state                                            :736 ][DEBUG   ][29508] Gathering pillar data for state run
2019-11-07 20:13:10,670 [salt.state                                            :750 ][DEBUG   ][29508] Finished gathering pillar data for state run
2019-11-07 20:13:10,670 [salt.state                                            :966 ][INFO    ][29508] Loading fresh modules for state activity
2019-11-07 20:13:10,704 [salt.utils.lazy                                       :104 ][DEBUG   ][29508] LazyLoaded jinja.render
2019-11-07 20:13:10,705 [salt.utils.lazy                                       :104 ][DEBUG   ][29508] LazyLoaded yaml.render
2019-11-07 20:13:10,715 [salt.fileclient                                       :1072][DEBUG   ][29508] Could not find file 'salt://top.sls' in saltenv 'base'
2019-11-07 20:13:10,715 [salt.state                                            :3083][DEBUG   ][29508] No contents loaded for saltenv 'base'
2019-11-07 20:13:10,715 [salt.state                                            :3100][DEBUG   ][29508] No contents found in top file. If this is not expected, verify that the 'file_roots' specified in 'etc/master' are accessible. The 'file_roots' configuration is: {u'base': []}
2019-11-07 20:13:10,715 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,716 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/clouds'
2019-11-07 20:13:10,723 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,724 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,724 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,725 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,725 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing clouds for environment 'base'
2019-11-07 20:13:10,725 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_clouds, for base)
2019-11-07 20:13:10,725 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_clouds/' for environment 'base'
2019-11-07 20:13:10,729 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_clouds'
2019-11-07 20:13:10,730 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,737 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,737 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,738 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,738 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,739 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing beacons for environment 'base'
2019-11-07 20:13:10,739 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_beacons, for base)
2019-11-07 20:13:10,739 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_beacons/' for environment 'base'
2019-11-07 20:13:10,752 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_beacons/pcap_watch.py' to resolve 'salt://_beacons/pcap_watch.py'
2019-11-07 20:13:10,752 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_beacons/pcap_watch.py' to resolve 'salt://_beacons/pcap_watch.py'
2019-11-07 20:13:10,758 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_beacons/tshark.py' to resolve 'salt://_beacons/tshark.py'
2019-11-07 20:13:10,758 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_beacons/tshark.py' to resolve 'salt://_beacons/tshark.py'
2019-11-07 20:13:10,758 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_beacons'
2019-11-07 20:13:10,758 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_beacons/pcap_watch.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/beacons/pcap_watch.py'
2019-11-07 20:13:10,759 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_beacons/tshark.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/beacons/tshark.py'
2019-11-07 20:13:10,759 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,765 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,765 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,766 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,766 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,766 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing modules for environment 'base'
2019-11-07 20:13:10,766 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_modules, for base)
2019-11-07 20:13:10,766 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_modules/' for environment 'base'
2019-11-07 20:13:10,774 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_modules/example.py' to resolve 'salt://_modules/example.py'
2019-11-07 20:13:10,775 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_modules/example.py' to resolve 'salt://_modules/example.py'
2019-11-07 20:13:10,779 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_modules/jason.py' to resolve 'salt://_modules/jason.py'
2019-11-07 20:13:10,780 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_modules/jason.py' to resolve 'salt://_modules/jason.py'
2019-11-07 20:13:10,780 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_modules'
2019-11-07 20:13:10,780 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_modules/example.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/modules/example.py'
2019-11-07 20:13:10,780 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_modules/jason.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/modules/jason.py'
2019-11-07 20:13:10,780 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,781 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/states'
2019-11-07 20:13:10,787 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,787 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,787 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,788 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,788 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing states for environment 'base'
2019-11-07 20:13:10,788 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_states, for base)
2019-11-07 20:13:10,788 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_states/' for environment 'base'
2019-11-07 20:13:10,792 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_states'
2019-11-07 20:13:10,792 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,793 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/sdb'
2019-11-07 20:13:10,799 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,799 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,800 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,800 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,800 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing sdb for environment 'base'
2019-11-07 20:13:10,800 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_sdb, for base)
2019-11-07 20:13:10,800 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_sdb/' for environment 'base'
2019-11-07 20:13:10,804 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_sdb'
2019-11-07 20:13:10,804 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,810 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,810 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,811 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,811 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,812 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing grains for environment 'base'
2019-11-07 20:13:10,812 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_grains, for base)
2019-11-07 20:13:10,812 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_grains/' for environment 'base'
2019-11-07 20:13:10,818 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_grains/test_grain.py' to resolve 'salt://_grains/test_grain.py'
2019-11-07 20:13:10,819 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_grains/test_grain.py' to resolve 'salt://_grains/test_grain.py'
2019-11-07 20:13:10,819 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_grains'
2019-11-07 20:13:10,819 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_grains/test_grain.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/grains/test_grain.py'
2019-11-07 20:13:10,820 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,821 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/renderers'
2019-11-07 20:13:10,826 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,827 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,827 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,827 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,828 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing renderers for environment 'base'
2019-11-07 20:13:10,828 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_renderers, for base)
2019-11-07 20:13:10,828 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_renderers/' for environment 'base'
2019-11-07 20:13:10,832 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_renderers'
2019-11-07 20:13:10,832 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,834 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/returners'
2019-11-07 20:13:10,840 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,840 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,840 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,841 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,841 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing returners for environment 'base'
2019-11-07 20:13:10,841 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_returners, for base)
2019-11-07 20:13:10,841 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_returners/' for environment 'base'
2019-11-07 20:13:10,845 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_returners'
2019-11-07 20:13:10,846 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,846 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/output'
2019-11-07 20:13:10,852 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,853 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,853 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,854 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,854 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing output for environment 'base'
2019-11-07 20:13:10,854 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_output, for base)
2019-11-07 20:13:10,854 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_output/' for environment 'base'
2019-11-07 20:13:10,857 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_output'
2019-11-07 20:13:10,858 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,863 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,864 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,864 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,865 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,865 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing utils for environment 'base'
2019-11-07 20:13:10,865 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_utils, for base)
2019-11-07 20:13:10,865 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_utils/' for environment 'base'
2019-11-07 20:13:10,874 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_utils/general.py' to resolve 'salt://_utils/general.py'
2019-11-07 20:13:10,874 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_utils/general.py' to resolve 'salt://_utils/general.py'
2019-11-07 20:13:10,879 [salt.fileclient                                       :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_utils/math.py' to resolve 'salt://_utils/math.py'
2019-11-07 20:13:10,879 [salt.fileclient                                       :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_utils/math.py' to resolve 'salt://_utils/math.py'
2019-11-07 20:13:10,879 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_utils'
2019-11-07 20:13:10,880 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_utils/general.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/utils/general.py'
2019-11-07 20:13:10,880 [salt.utils.extmods                                    :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_utils/math.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/utils/math.py'
2019-11-07 20:13:10,880 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,881 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/log_handlers'
2019-11-07 20:13:10,887 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,887 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,888 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,888 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,888 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing log_handlers for environment 'base'
2019-11-07 20:13:10,889 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_log_handlers, for base)
2019-11-07 20:13:10,889 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_log_handlers/' for environment 'base'
2019-11-07 20:13:10,892 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_log_handlers'
2019-11-07 20:13:10,892 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,893 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/proxy'
2019-11-07 20:13:10,898 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,899 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,899 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,900 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,900 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing proxy for environment 'base'
2019-11-07 20:13:10,900 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_proxy, for base)
2019-11-07 20:13:10,900 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_proxy/' for environment 'base'
2019-11-07 20:13:10,903 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_proxy'
2019-11-07 20:13:10,903 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,904 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/engines'
2019-11-07 20:13:10,910 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,910 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,911 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,911 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,912 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing engines for environment 'base'
2019-11-07 20:13:10,912 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_engines, for base)
2019-11-07 20:13:10,912 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_engines/' for environment 'base'
2019-11-07 20:13:10,916 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_engines'
2019-11-07 20:13:10,916 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,917 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/thorium'
2019-11-07 20:13:10,925 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,925 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,926 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,926 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,927 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing thorium for environment 'base'
2019-11-07 20:13:10,927 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_thorium, for base)
2019-11-07 20:13:10,927 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_thorium/' for environment 'base'
2019-11-07 20:13:10,930 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_thorium'
2019-11-07 20:13:10,931 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,932 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/serializers'
2019-11-07 20:13:10,938 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,938 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,939 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,939 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,940 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing serializers for environment 'base'
2019-11-07 20:13:10,940 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_serializers, for base)
2019-11-07 20:13:10,940 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_serializers/' for environment 'base'
2019-11-07 20:13:10,943 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_serializers'
2019-11-07 20:13:10,943 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,944 [salt.utils.extmods                                    :79  ][INFO    ][29508] Creating module dir '/var/cache/salt/proxy/extmods/dummy_proxy/matchers'
2019-11-07 20:13:10,950 [salt.transport.zeromq                                 :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:10,950 [salt.crypt                                            :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:10,951 [salt.transport.zeromq                                 :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:10,951 [salt.transport.zeromq                                 :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:10,952 [salt.utils.extmods                                    :90  ][INFO    ][29508] Syncing matchers for environment 'base'
2019-11-07 20:13:10,952 [salt.utils.extmods                                    :94  ][INFO    ][29508] Loading cache from salt://_matchers, for base)
2019-11-07 20:13:10,952 [salt.fileclient                                       :234 ][INFO    ][29508] Caching directory '_matchers/' for environment 'base'
2019-11-07 20:13:10,954 [salt.utils.extmods                                    :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_matchers'
2019-11-07 20:13:10,955 [salt.transport.zeromq                                 :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:10,956 [salt.utils.lazy                                       :104 ][DEBUG   ][29508] LazyLoaded event.fire
2019-11-07 20:13:10,956 [salt.utils.event                                      :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:10,956 [salt.utils.event                                      :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:10,957 [salt.utils.event                                      :737 ][DEBUG   ][29508] Sending event: tag = module_refresh; data = {u'_stamp': '2019-11-07T20:13:10.957625'}
2019-11-07 20:13:10,958 [salt.transport.ipc                                    :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:10,958 [salt.utils.event                                      :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:10,958 [salt.utils.event                                      :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:10,958 [salt.utils.event                                      :737 ][DEBUG   ][29508] Sending event: tag = pillar_refresh; data = {u'_stamp': '2019-11-07T20:13:10.958899'}
2019-11-07 20:13:10,959 [salt.transport.ipc                                    :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:10,965 [salt.loader                                           :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:10,965 [salt.config                                           :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:10,966 [salt.config                                           :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:10,966 [salt.config                                           :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:12,520 [salt.loaded.int.grains.core                           :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:12,521 [salt.loaded.int.grains.core                           :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:12,522 [salt.loaded.ext.grains.test_grain                     :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:12,522 [salt.loaded.int.grains.extra                          :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:12,525 [/usr/lib/python2.7/dist-packages/salt/proxy/dummy.pyc :37  ][DEBUG   ][29508] dummy proxy __virtual__() called...
2019-11-07 20:13:12,526 [salt.utils.lazy                                       :104 ][DEBUG   ][29508] LazyLoaded dummy.grains
2019-11-07 20:13:12,558 [/usr/lib/python2.7/dist-packages/salt/proxy/dummy.pyc  :37  ][DEBUG   ][29508] dummy proxy __virtual__() called...
2019-11-07 20:13:12,563 [/usr/lib/python2.7/dist-packages/salt/proxy/nxos.pyc    :117 ][INFO    ][29508] nxos proxy __virtual__() called...
2019-11-07 20:13:12,564 [/usr/lib/python2.7/dist-packages/salt/proxy/rest_sample.pyc:33  ][DEBUG   ][29508] rest_sample proxy __virtual__() called...
2019-11-07 20:13:12,564 [/usr/lib/python2.7/dist-packages/salt/proxy/ssh_sample.pyc :33  ][INFO    ][29508] ssh_sample proxy __virtual__() called...
2019-11-07 20:13:12,565 [/usr/lib/python2.7/dist-packages/salt/proxy/dummy.pyc      :68  ][DEBUG   ][29508] dummy proxy init() called...
2019-11-07 20:13:12,565 [salt.loader                                                :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:12,566 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:12,566 [salt.config                                                :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:12,566 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:14,124 [salt.loaded.int.grains.core                                :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:14,125 [salt.loaded.int.grains.core                                :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:14,125 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:14,126 [salt.loaded.int.grains.extra                               :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:14,130 [salt.loader                                                :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:14,130 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:14,131 [salt.config                                                :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:14,131 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:15,645 [salt.loaded.int.grains.core                                :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:16,178 [salt.loaded.int.grains.core                                :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:16,179 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:16,180 [salt.loaded.int.grains.extra                               :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:16,213 [salt.utils.schedule                                        :94  ][DEBUG   ][29508] Initializing new Schedule
2019-11-07 20:13:16,219 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded timezone.get_offset
2019-11-07 20:13:16,221 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded cmd.run
2019-11-07 20:13:16,222 [salt.loader.localhost.int.module.cmdmod                    :397 ][INFO    ][29508] Executing command [u'date', u'+%z'] in directory '/root'
2019-11-07 20:13:16,759 [salt.loader.localhost.int.module.cmdmod                    :843 ][DEBUG   ][29508] stdout: +0000
2019-11-07 20:13:16,759 [salt.loader.localhost.int.module.cmdmod                    :1202][DEBUG   ][29508] output: +0000
2019-11-07 20:13:16,765 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded config.merge
2019-11-07 20:13:16,766 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:16,766 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:16,766 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-11-07T20:13:16.766915', u'complete': True, u'schedule': {}}
2019-11-07 20:13:16,767 [salt.utils.schedule                                        :271 ][DEBUG   ][29508] Persisting schedule
2019-11-07 20:13:16,767 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:16,768 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded mine.update
2019-11-07 20:13:16,768 [salt.utils.schedule                                        :376 ][INFO    ][29508] Added new job __mine_interval to scheduler
2019-11-07 20:13:16,769 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:16,769 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:16,769 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_schedule_add_complete; data = {u'_stamp': '2019-11-07T20:13:16.769763', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-11-07 20:13:16,770 [salt.utils.schedule                                        :271 ][DEBUG   ][29508] Persisting schedule
2019-11-07 20:13:16,776 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:16,776 [salt.loaded.int.metaproxy.proxy                            :200 ][INFO    ][29508] Added mine.update to scheduler
2019-11-07 20:13:16,777 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:16,777 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:16,777 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-11-07T20:13:16.777585', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-11-07 20:13:16,777 [salt.utils.schedule                                        :271 ][DEBUG   ][29508] Persisting schedule
2019-11-07 20:13:17,005 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:17,006 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:17,006 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:17,008 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-11-07T20:13:17.008387', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-11-07 20:13:17,009 [salt.utils.schedule                                        :271 ][DEBUG   ][29508] Persisting schedule
2019-11-07 20:13:17,059 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:17,060 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:17,061 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:17,062 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {u'_stamp': '2019-11-07T20:13:17.062169', u'complete': True, u'schedule': {u'__mine_interval': {u'function': u'mine.update', u'run_on_start': True, u'enabled': True, u'return_job': False, u'jid_include': True, u'maxrunning': 2, u'minutes': 60}}}
2019-11-07 20:13:17,063 [salt.utils.schedule                                        :271 ][DEBUG   ][29508] Persisting schedule
2019-11-07 20:13:17,104 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:17,108 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded saltutil.sync_grains
2019-11-07 20:13:17,121 [salt.transport.zeromq                                      :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:17,121 [salt.crypt                                                 :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:17,122 [salt.transport.zeromq                                      :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:17,122 [salt.transport.zeromq                                      :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:17,123 [salt.utils.extmods                                         :90  ][INFO    ][29508] Syncing grains for environment 'base'
2019-11-07 20:13:17,123 [salt.utils.extmods                                         :94  ][INFO    ][29508] Loading cache from salt://_grains, for base)
2019-11-07 20:13:17,123 [salt.fileclient                                            :234 ][INFO    ][29508] Caching directory '_grains/' for environment 'base'
2019-11-07 20:13:17,134 [salt.fileclient                                            :1093][DEBUG   ][29508] In saltenv 'base', looking at rel_path '_grains/test_grain.py' to resolve 'salt://_grains/test_grain.py'
2019-11-07 20:13:17,134 [salt.fileclient                                            :1101][DEBUG   ][29508] In saltenv 'base', ** considering ** path '/var/cache/salt/proxy/dummy_proxy/files/base/_grains/test_grain.py' to resolve 'salt://_grains/test_grain.py'
2019-11-07 20:13:17,135 [salt.utils.extmods                                         :109 ][DEBUG   ][29508] Local cache dir: '/var/cache/salt/proxy/dummy_proxy/files/base/_grains'
2019-11-07 20:13:17,136 [salt.utils.extmods                                         :119 ][INFO    ][29508] Copying '/var/cache/salt/proxy/dummy_proxy/files/base/_grains/test_grain.py' to '/var/cache/salt/proxy/extmods/dummy_proxy/grains/test_grain.py'
2019-11-07 20:13:17,137 [salt.transport.zeromq                                      :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:17,138 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded event.fire
2019-11-07 20:13:17,139 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:17,139 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:17,140 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = module_refresh; data = {u'_stamp': '2019-11-07T20:13:17.140572'}
2019-11-07 20:13:17,141 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:17,141 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:17,141 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:17,142 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = pillar_refresh; data = {u'_stamp': '2019-11-07T20:13:17.142660'}
2019-11-07 20:13:17,143 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:17,169 [salt.minion                                                :2323][INFO    ][29508] ProxyMinion is starting as user 'root'
2019-11-07 20:13:17,169 [salt.minion                                                :2685][DEBUG   ][29508] Minion 'dummy_proxy' trying to tune in
2019-11-07 20:13:17,169 [salt.transport.zeromq                                      :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:17,170 [salt.crypt                                                 :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:17,170 [salt.transport.zeromq                                      :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:17,170 [salt.transport.zeromq                                      :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:17,177 [salt.transport.zeromq                                      :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:17,178 [salt.transport.zeromq                                      :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:17,178 [salt.crypt                                                 :464 ][DEBUG   ][29508] Initializing new AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:17,179 [salt.transport.zeromq                                      :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:17,179 [salt.transport.zeromq                                      :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:17,184 [salt.transport.zeromq                                      :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:17,185 [salt.minion                                                :2695][INFO    ][29508] Minion is ready to receive requests!
2019-11-07 20:13:17,188 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag 'module_refresh'
2019-11-07 20:13:17,188 [salt.minion                                                :2161][DEBUG   ][29508] Refreshing modules. Notify=False
2019-11-07 20:13:17,188 [salt.loader                                                :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:17,188 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:17,189 [salt.config                                                :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:17,189 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:18,695 [salt.loaded.int.grains.core                                :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:18,696 [salt.loaded.int.grains.core                                :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:18,697 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:18,697 [salt.loaded.int.grains.extra                               :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:18,725 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag 'pillar_refresh'
2019-11-07 20:13:18,725 [salt.minion                                                :2190][DEBUG   ][29508] Refreshing pillar
2019-11-07 20:13:18,725 [salt.transport.zeromq                                      :138 ][DEBUG   ][29508] Initializing new AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:18,726 [salt.crypt                                                 :472 ][DEBUG   ][29508] Re-using AsyncAuth for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506')
2019-11-07 20:13:18,726 [salt.transport.zeromq                                      :209 ][DEBUG   ][29508] Connecting the Minion to the Master URI (for the return server): tcp://127.0.0.1:4506
2019-11-07 20:13:18,726 [salt.transport.zeromq                                      :1189][DEBUG   ][29508] Trying to connect to: tcp://127.0.0.1:4506
2019-11-07 20:13:18,727 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-11-07 20:13:18,727 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_schedule_add_complete'
2019-11-07 20:13:18,728 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-11-07 20:13:18,728 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-11-07 20:13:18,728 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2019-11-07 20:13:18,728 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag 'module_refresh'
2019-11-07 20:13:18,728 [salt.minion                                                :2161][DEBUG   ][29508] Refreshing modules. Notify=False
2019-11-07 20:13:18,728 [salt.loader                                                :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:18,728 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:18,729 [salt.config                                                :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:18,729 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:20,245 [salt.loaded.int.grains.core                                :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:20,245 [salt.loaded.int.grains.core                                :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:20,246 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:20,246 [salt.loaded.int.grains.extra                               :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:20,273 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag 'pillar_refresh'
2019-11-07 20:13:20,273 [salt.minion                                                :2190][DEBUG   ][29508] Refreshing pillar
2019-11-07 20:13:20,273 [salt.transport.zeromq                                      :153 ][DEBUG   ][29508] Re-using AsyncZeroMQReqChannel for (u'/etc/salt/pki/proxy', 'dummy_proxy', u'tcp://127.0.0.1:4506', u'aes')
2019-11-07 20:13:20,275 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded config.merge
2019-11-07 20:13:20,275 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded mine.update
2019-11-07 20:13:20,276 [salt.utils.schedule                                        :1619][DEBUG   ][29508] schedule: Job __mine_interval was scheduled with jid_include, adding to cache (jid_include defaults to True)
2019-11-07 20:13:20,276 [salt.utils.schedule                                        :1622][DEBUG   ][29508] schedule: Job __mine_interval was scheduled with a max number of 2
2019-11-07 20:13:20,276 [salt.utils.schedule                                        :1639][INFO    ][29508] Running scheduled job: __mine_interval
2019-11-07 20:13:20,280 [salt.utils.process                                         :860 ][DEBUG   ][29508] Subprocess SignalHandlingMultiprocessingProcess-1:1-Schedule-__mine_interval added
2019-11-07 20:13:20,336 [salt.utils.schedule                                        :689 ][DEBUG   ][29591] schedule.handle_func: adding this job to the jobcache with data {u'fun_args': [], u'jid': u'20191107201320336259', u'schedule': u'__mine_interval', u'pid': 29591, u'fun': u'mine.update', u'id': 'dummy_proxy'}
2019-11-07 20:13:20,339 [salt.utils.lazy                                            :104 ][DEBUG   ][29591] LazyLoaded mine.update
2019-11-07 20:13:20,339 [salt.crypt                                                 :200 ][DEBUG   ][29508] salt.crypt.get_rsa_key: Loading private key
2019-11-07 20:13:20,340 [salt.crypt                                                 :802 ][DEBUG   ][29508] Loaded minion key: /etc/salt/pki/proxy/minion.pem
2019-11-07 20:13:20,341 [salt.utils.lazy                                            :104 ][DEBUG   ][29591] LazyLoaded config.merge
2019-11-07 20:13:20,342 [salt.utils.schedule                                        :836 ][DEBUG   ][29591] schedule.handle_func: Removing /var/cache/salt/proxy/dummy_proxy/proc/20191107201320336259
2019-11-07 20:13:20,343 [salt.transport.zeromq                                      :229 ][DEBUG   ][29508] This is not the last AsyncZeroMQReqChannel instance. Not closing yet.
2019-11-07 20:13:20,344 [salt.minion                                                :2161][DEBUG   ][29508] Refreshing modules. Notify=False
2019-11-07 20:13:20,344 [salt.loader                                                :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:20,344 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:20,345 [salt.config                                                :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:20,345 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:21,907 [salt.loaded.int.grains.core                                :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:21,907 [salt.loaded.int.grains.core                                :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:21,908 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:21,908 [salt.loaded.int.grains.extra                               :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:21,937 [salt.minion                                                :2180][DEBUG   ][29508] Refreshing matchers.
2019-11-07 20:13:21,938 [salt.minion                                                :2173][DEBUG   ][29508] Refreshing beacons.
2019-11-07 20:13:21,939 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:21,940 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:21,941 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_pillar_refresh_complete; data = {u'_stamp': '2019-11-07T20:13:21.941251', u'complete': True}
2019-11-07 20:13:21,941 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageSubscriber instance
2019-11-07 20:13:21,941 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:21,942 [salt.crypt                                                 :200 ][DEBUG   ][29508] salt.crypt.get_rsa_key: Loading private key
2019-11-07 20:13:21,943 [salt.crypt                                                 :802 ][DEBUG   ][29508] Loaded minion key: /etc/salt/pki/proxy/minion.pem
2019-11-07 20:13:21,946 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded config.merge
2019-11-07 20:13:21,946 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded mine.update
2019-11-07 20:13:21,947 [salt.utils.process                                         :869 ][DEBUG   ][29508] Subprocess SignalHandlingMultiprocessingProcess-1:1-Schedule-__mine_interval cleaned up
2019-11-07 20:13:21,947 [salt.transport.zeromq                                      :233 ][DEBUG   ][29508] Closing AsyncZeroMQReqChannel instance
2019-11-07 20:13:21,948 [salt.minion                                                :2161][DEBUG   ][29508] Refreshing modules. Notify=False
2019-11-07 20:13:21,948 [salt.loader                                                :747 ][DEBUG   ][29508] Grains refresh requested. Refreshing grains.
2019-11-07 20:13:21,949 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy
2019-11-07 20:13:21,949 [salt.config                                                :2329][DEBUG   ][29508] Including configuration from '/etc/salt/proxy.d/dummy_proxy/_schedule.conf'
2019-11-07 20:13:21,949 [salt.config                                                :2185][DEBUG   ][29508] Reading configuration from /etc/salt/proxy.d/dummy_proxy/_schedule.conf
2019-11-07 20:13:23,463 [salt.loaded.int.grains.core                                :1063][INFO    ][29508] Although 'dmidecode' was found in path, the current user cannot execute it. Grains output might not be accurate.
2019-11-07 20:13:23,463 [salt.loaded.int.grains.core                                :2106][DEBUG   ][29508] Unable to derive osmajorrelease from osrelease_info '(u'proxy',)'. The osmajorrelease grain will not be set.
2019-11-07 20:13:23,464 [salt.loaded.ext.grains.test_grain                          :10  ][DEBUG   ][29508] test_grain is running
2019-11-07 20:13:23,464 [salt.loaded.int.grains.extra                               :70  ][DEBUG   ][29508] Loading static grains from /etc/salt/proxy.d/dummy_proxy/grains
2019-11-07 20:13:23,495 [salt.minion                                                :2180][DEBUG   ][29508] Refreshing matchers.
2019-11-07 20:13:23,496 [salt.minion                                                :2173][DEBUG   ][29508] Refreshing beacons.
2019-11-07 20:13:23,498 [salt.utils.event                                           :322 ][DEBUG   ][29508] SaltEvent PUB socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pub.ipc
2019-11-07 20:13:23,498 [salt.utils.event                                           :323 ][DEBUG   ][29508] SaltEvent PULL socket URI: /var/run/salt/proxy/minion_event_7ec73a3b0f_pull.ipc
2019-11-07 20:13:23,499 [salt.utils.event                                           :737 ][DEBUG   ][29508] Sending event: tag = /salt/minion/minion_pillar_refresh_complete; data = {u'_stamp': '2019-11-07T20:13:23.499846', u'complete': True}
2019-11-07 20:13:23,500 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageSubscriber instance
2019-11-07 20:13:23,500 [salt.transport.ipc                                         :364 ][DEBUG   ][29508] Closing IPCMessageClient instance
2019-11-07 20:13:23,502 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded config.merge
2019-11-07 20:13:23,502 [salt.utils.lazy                                            :104 ][DEBUG   ][29508] LazyLoaded mine.update
2019-11-07 20:13:23,503 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_pillar_refresh_complete'
2019-11-07 20:13:23,503 [salt.minion                                                :2360][DEBUG   ][29508] Minion of 'localhost' is handling event tag '/salt/minion/minion_pillar_refresh_complete'

@cmcmarrow cmcmarrow mentioned this issue Nov 7, 2019
Closed
@jtraub91
Copy link
Contributor Author

@cmcmarrow I see there you have an open PR for the erroneous dual pillar refresh, but can you confirm that my above comment regarding proxy minions has been noted? Seems to be a separate issue. Shall I raise another github issue for it?

@cmcmarrow
Copy link
Contributor

#46713
This PR is waiting to be merged and will be taking my PR place.

@cmcmarrow cmcmarrow added the fixed-pls-verify fix is linked, bug author to confirm fix label Nov 22, 2019
@cmcmarrow
Copy link
Contributor

A fix is waiting to be merged.

@cmcmarrow
Copy link
Contributor

cmcmarrow commented Nov 22, 2019 •
edited
Loading

@jtraub91
I agree that 8 times is a lot for a proxy minion. With that being said the problem right now is only being reported on startup. So there is not a huge performance hit. As parts of salt are loading refreshing the grains are necessary because some grains look at other grains etc.. But I don’t believe we need to update the grains 8 times.

@cmcmarrow
Copy link
Contributor

Raise another GitHub issue would be great @jtraub91. So for the slow reply.

@cmcmarrow cmcmarrow reopened this Dec 5, 2019
@sagetherage
Copy link
Contributor

@jtraub91 have you opened another ticket? Wanting to be sure that isn't lost. Thank you!

@jtraub91 jtraub91 mentioned this issue Dec 16, 2019
Closed
@jtraub91
Copy link
Contributor Author

@sagetherage Just did so here #55658

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@cmcmarrow cmcmarrow

Labels
Bug broken, incorrect, or confusing behavior Confirmed Salt engineer has confirmed bug/feature - often including a MCVE fixed-pls-verify fix is linked, bug author to confirm fix Grains v2019.2.3 unsupported version
Projects
None yet
Milestone
Approved
Development

No branches or pull requests
4 participants
@jtraub91 @sagetherage @KChandrashekhar @cmcmarrow