[BUG] Minion sending duplicate events #62959

supfors · 2022-10-26T10:32:21Z

Description
When running event.send in a state executed from the master to a minion, the minion sends duplicate events to the bus. This happens most of the times, but not always.

It does not happen when:

Running event.send from the master using salt myminion event.send test123
Running event.send from the minion using salt-call event.send test123
Running salt-call state.apply test123 from the minion

It looks like the behaviour reported in #53506 but the other way around. It also causes the behaviour reported in #62638

Setup
/srv/salt/test123.sls:

test123:
  event.send

salt myminion state.apply test123

salt-run state.event test123

test123	{"id": "myminion", "cmd": "_minion_event", "pretag": null, "data": {}, "tag": "test123", "_stamp": "2022-10-26T10:05:08.209961"}
test123	{"id": "myminion", "cmd": "_minion_event", "pretag": null, "data": {}, "tag": "test123", "_stamp": "2022-10-26T10:05:17.211189"}

Expected behavior
I expect events to always be sent once.

Versions Report

master:
Salt Version:
          Salt: 3005.1
 
Dependency Versions:
          cffi: 1.14.6
      cherrypy: unknown
      dateutil: 2.8.2
     docker-py: 5.0.3
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.1.0
       libgit2: 1.5.0
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: 2.21
      pycrypto: Not Installed
  pycryptodome: 3.9.8
        pygit2: 1.10.1
        Python: 3.9.14 (main, Oct  3 2022, 21:22:21)
  python-gnupg: 0.4.8
        PyYAML: 5.4.1
         PyZMQ: 23.2.0
         smmap: Not Installed
       timelib: 0.2.4
       Tornado: 4.5.3
           ZMQ: 4.3.4
 
System Versions:
          dist: ubuntu 22.04 jammy
        locale: utf-8
       machine: x86_64
       release: 5.15.0-52-generic
        system: Linux
       version: Ubuntu 22.04 jammy


minion:
Salt Version:
          Salt: 3005.1
 
Dependency Versions:
          cffi: 1.14.6
      cherrypy: 18.6.1
      dateutil: 2.8.1
     docker-py: Not Installed
         gitdb: Not Installed
     gitpython: Not Installed
        Jinja2: 3.1.0
       libgit2: Not Installed
      M2Crypto: Not Installed
          Mako: Not Installed
       msgpack: 1.0.2
  msgpack-pure: Not Installed
  mysql-python: Not Installed
     pycparser: 2.21
      pycrypto: Not Installed
  pycryptodome: 3.9.8
        pygit2: Not Installed
        Python: 3.9.14 (main, Oct  3 2022, 21:22:21)
  python-gnupg: 0.4.8
        PyYAML: 5.4.1
         PyZMQ: 23.2.0
         smmap: Not Installed
       timelib: 0.2.4
       Tornado: 4.5.3
           ZMQ: 4.3.4
 
System Versions:
          dist: ubuntu 22.04 jammy
        locale: ascii
       machine: x86_64
       release: 5.15.0-52-generic
        system: Linux
       version: Ubuntu 22.04 jammy

Additional context
I've tested this on Ubuntu20 (both classic and onedir install methods) and ubuntu22.
I did not see this behaviour in previous salt versions (3004.x).

The text was updated successfully, but these errors were encountered:

OrangeDog · 2022-10-26T11:30:51Z

The events are nine seconds apart, which seems like a lot.
Do you have debug/trace logs from the minion that would show the timings for when it ran the state?

supfors · 2022-10-26T14:03:20Z

I've ran another test, here's the trace:

Click


root@master:/srv/salt# salt myminion state.apply test123
root@master:~# salt-run state.event test123
test123	{"id": "myminion", "cmd": "_minion_event", "pretag": null, "data": {}, "tag": "test123", "_stamp": "2022-10-26T13:56:44.524180"}
test123	{"id": "myminion", "cmd": "_minion_event", "pretag": null, "data": {}, "tag": "test123", "_stamp": "2022-10-26T13:56:51.533665"}


/var/log/salt/minion:
2022-10-26 13:56:09,256 [salt.minion      :2642][INFO    ][14] Minion is starting as user 'root'
2022-10-26 13:56:09,256 [salt.minion      :3084][DEBUG   ][14] Minion 'myminion' trying to tune in
2022-10-26 13:56:09,257 [salt.utils.event :315 ][DEBUG   ][14] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pub.ipc
2022-10-26 13:56:09,257 [salt.utils.event :316 ][DEBUG   ][14] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:09,257 [salt.transport.ipc:32  ][TRACE   ][14] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:09,257 [salt.utils.event :821 ][DEBUG   ][14] Sending event: tag = __master_req_channel_payload; data = {'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': 'Minion myminion started at Wed Oct 26 13:56:09 2022', 'tag': 'minion_start', '_stamp': '2022-10-26T13:56:09.257624'}
2022-10-26 13:56:09,257 [salt.transport.ipc:373 ][DEBUG   ][14] Closing IPCMessageClient instance
2022-10-26 13:56:09,258 [salt.utils.event :315 ][DEBUG   ][14] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pub.ipc
2022-10-26 13:56:09,258 [salt.utils.event :316 ][DEBUG   ][14] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:09,259 [salt.transport.ipc:32  ][TRACE   ][14] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:09,259 [salt.utils.event :821 ][DEBUG   ][14] Sending event: tag = __master_req_channel_payload; data = {'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': 'Minion myminion started at Wed Oct 26 13:56:09 2022', 'tag': 'salt/minion/myminion/start', '_stamp': '2022-10-26T13:56:09.259370'}
2022-10-26 13:56:09,259 [salt.transport.ipc:373 ][DEBUG   ][14] Closing IPCMessageClient instance
2022-10-26 13:56:09,259 [salt.minion      :3094][INFO    ][14] Minion is ready to receive requests!
2022-10-26 13:56:09,262 [salt.transport.ipc:32  ][TRACE   ][14] IPCServer: Handling connection to address: <socket.socket fd=39, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_ac43295fd5_pull.ipc>
2022-10-26 13:56:09,262 [salt.transport.ipc:32  ][TRACE   ][14] IPCServer: Handling connection to address: <socket.socket fd=40, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_ac43295fd5_pull.ipc>
2022-10-26 13:56:09,263 [salt.transport.ipc:32  ][TRACE   ][14] Client disconnected from IPC /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:09,263 [salt.transport.ipc:32  ][TRACE   ][14] Client disconnected from IPC /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:09,263 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2022-10-26 13:56:09,264 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '/salt/minion/minion_schedule_add_complete'
2022-10-26 13:56:09,264 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2022-10-26 13:56:09,264 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '/salt/minion/minion_schedule_delete_complete'
2022-10-26 13:56:09,264 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '__master_req_channel_payload'
2022-10-26 13:56:09,264 [salt.minion      :890 ][DEBUG   ][14] Minion return retry timer set to 7 seconds (randomized)
2022-10-26 13:56:09,264 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': 'Minion myminion started at Wed Oct 26 13:56:09 2022', 'tag': 'minion_start', '_stamp': '2022-10-26T13:56:09.257624'}
2022-10-26 13:56:09,265 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '__master_req_channel_payload'
2022-10-26 13:56:09,265 [salt.minion      :890 ][DEBUG   ][14] Minion return retry timer set to 9 seconds (randomized)
2022-10-26 13:56:09,265 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': 'Minion myminion started at Wed Oct 26 13:56:09 2022', 'tag': 'salt/minion/myminion/start', '_stamp': '2022-10-26T13:56:09.259370'}
2022-10-26 13:56:09,266 [tornado.general  :567 ][WARNING ][14] Got events for closed stream <zmq.eventloop.zmqstream.ZMQStream object at 0x7f724f5b04c0>
2022-10-26 13:56:10,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:10,264 [salt.utils.schedule:1721][DEBUG   ][14] schedule: Job __mine_interval was scheduled with jid_include, adding to cache (jid_include defaults to True)
2022-10-26 13:56:10,265 [salt.utils.schedule:1727][DEBUG   ][14] schedule: Job __mine_interval was scheduled with a max number of 2
2022-10-26 13:56:10,265 [salt.utils.schedule:1751][INFO    ][14] Running scheduled job: __mine_interval with jid 20221026135610265500
2022-10-26 13:56:10,270 [salt.utils.process:1144][DEBUG   ][14] Subprocess Schedule(name=__mine_interval, jid=20221026135610265500) added
2022-10-26 13:56:10,291 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][64] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2022-10-26 13:56:10,292 [tiamatpip.configure:94  ][DEBUG   ][64] TiamatPipPathFinder.find_spec: First time trying to load log4mongo
2022-10-26 13:56:10,294 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][64] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2022-10-26 13:56:10,294 [tiamatpip.configure:94  ][DEBUG   ][64] TiamatPipPathFinder.find_spec: First time trying to load raven
2022-10-26 13:56:10,295 [salt.loader.lazy :32  ][TRACE   ][64] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2022-10-26 13:56:10,351 [salt.loader.lazy :960 ][DEBUG   ][64] The functions from module 'mine' are being loaded by dir() on the loaded module
2022-10-26 13:56:10,351 [salt.utils.lazy  :99  ][DEBUG   ][64] LazyLoaded mine.update
2022-10-26 13:56:10,351 [salt.utils.schedule:782 ][DEBUG   ][64] schedule.handle_func: adding this job to the jobcache with data {'id': 'myminion', 'fun': 'mine.update', 'fun_args': [], 'schedule': '__mine_interval', 'jid': '20221026135610265500', 'pid': 64}
2022-10-26 13:56:10,352 [salt.loader.lazy :960 ][DEBUG   ][64] The functions from module 'config' are being loaded by dir() on the loaded module
2022-10-26 13:56:10,352 [salt.utils.lazy  :99  ][DEBUG   ][64] LazyLoaded config.merge
2022-10-26 13:56:10,352 [salt.utils.schedule:924 ][DEBUG   ][64] schedule.handle_func: Removing /var/cache/salt/minion/proc/20221026135610265500
2022-10-26 13:56:11,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:11,264 [salt.utils.process:1155][DEBUG   ][14] Subprocess Schedule(name=__mine_interval, jid=20221026135610265500) cleaned up
2022-10-26 13:56:12,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:13,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:14,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:15,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:16,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:16,266 [salt.channel.client:32  ][TRACE   ][14] Failed to send msg SaltReqTimeoutError('Message timed out')
2022-10-26 13:56:16,267 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': 'Minion myminion started at Wed Oct 26 13:56:09 2022', 'tag': 'minion_start', '_stamp': '2022-10-26T13:56:09.257624', 'nonce': '500e79f39b1441d5842b37674d574b85'}
2022-10-26 13:56:17,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:18,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:19,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:20,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:21,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:22,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:23,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:24,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:25,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:26,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:27,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:28,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:29,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:30,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:31,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:32,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:33,116 [salt.channel.client:32  ][TRACE   ][14] Decoding payload: {'enc': 'aes', 'load': b"\xf9\xf1\x98\xf9{d\x82\xab\xdc\xf7\xb3%'yC\x0f)@5fz\xbd\x19\xd1N\x0e\x91\xda\xc8gp\xbc\xc8};\x91\x95-\xbd\x1d\xa7\xbb\x12\x86\xe8\xc2Y\xa9\x06\x82<\t\x88\x88h;\x10\xee\x889\x85d\xefNY\xf2\t\xdc\xc8\xb5\xe9\x0f\xaeV{kb\x9f\xaf\xdb\xf1{n\xcfe\xeb'\xdd\xb5\xa8\x00:\xd0<+\x90\xb4-\xbc8\x19\xc9\x06\xc5\xfcm\xf4H\x17\x14T,k\x8d/\xbbn\xe4\xe9\xc8\xb4\xae\xe1m\x92\xd6D\x16\xfd:c\x1b6\x07\xa7P\x05+\xcb\x95P\x89\xeb\x04\xfb[\x1f\xf2\x9a\xa4E\xdcN\xb84\xf6\xd5c8\xbf\x9d\xac\xc7\xf0*\x1bQ\xd5\x0bh\xccu|\xf2\xb3\xf52y1\x90yK\xc1\xf1\xa3\x0b\xca\xed\xf3|\xdf\xc8B\x80\xe3_u}&\x1a\xf5\xaa6N\xbd\x18\xfbB", 'sig': b"\x82*PX\xd1\xff>\x8eq\xcf*\xdc\xd9nrK\xdd\xca\xb0\xc3\x9648Y\\uh\xf7\xd0\xe4\xcd\xa9l\xb6\xf4\x99\xf0|\xb7\x94\xdd:\xa6\xd0n\xd8\xbb\x91\xe1\xe9\xe4&w\x82v\xb1\x90K\xd5?\xe93\xc3+A\x84\xe9{d\xb2C\xe2\x01\xf1\xf9j\x05b\xd2U?\x93\xfb\x14>to\xb8\xa4\xd7\x15\xec\x835\x18d`\xfe\x85{-\xa0\xf0\xe3w\xc9\xb4\xfe\t\xa7\x81V\xff\xfa_\xe5\xee\xd5\xb3\xb0\xae<\xcbu$\x18\x82\xad\x84+\xbc.\\Dq\xfb\xd3\x1a\xa4\xe8\xf0\xd5\x9a'z\xab;\x87\xee\x15\x0c\xb3E\x98\xc4\x7fN\xc9\xe3\x1f0\xe0``\xf0\xaf\\\n\xbc6\xf5*x\xfdms\x8d\xd4Q_\x93\xff\x05\xf3\xc7\xd2\x1d.\xe7\xf3\x86\xe0N\xc0\xf2|\x04\xaeB\xae\xcc=\tj\xc9\xcdm\xba5\x12\xd3\x9a\xb5\xcd\x8b\x9e\x96\x94\x045\x18\x19\tC\xa4xo+\x9c\x0c\xf3\x9a\xe5\x11\xc4\x7fPh\r\x08\x14\xfa\xa6@\x04\x11\t\x83\x9e2\x03\xb2\xd2w\xe9p"}
2022-10-26 13:56:33,116 [salt.channel.client:427 ][DEBUG   ][14] PubChannel received: {'enc': 'aes', 'load': {'fun': 'state.apply', 'arg': ['test123'], 'tgt': 'myminion', 'jid': '20221026135633098860', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'glob', 'user': 'sudo_root'}, 'sig': b"\x82*PX\xd1\xff>\x8eq\xcf*\xdc\xd9nrK\xdd\xca\xb0\xc3\x9648Y\\uh\xf7\xd0\xe4\xcd\xa9l\xb6\xf4\x99\xf0|\xb7\x94\xdd:\xa6\xd0n\xd8\xbb\x91\xe1\xe9\xe4&w\x82v\xb1\x90K\xd5?\xe93\xc3+A\x84\xe9{d\xb2C\xe2\x01\xf1\xf9j\x05b\xd2U?\x93\xfb\x14>to\xb8\xa4\xd7\x15\xec\x835\x18d`\xfe\x85{-\xa0\xf0\xe3w\xc9\xb4\xfe\t\xa7\x81V\xff\xfa_\xe5\xee\xd5\xb3\xb0\xae<\xcbu$\x18\x82\xad\x84+\xbc.\\Dq\xfb\xd3\x1a\xa4\xe8\xf0\xd5\x9a'z\xab;\x87\xee\x15\x0c\xb3E\x98\xc4\x7fN\xc9\xe3\x1f0\xe0``\xf0\xaf\\\n\xbc6\xf5*x\xfdms\x8d\xd4Q_\x93\xff\x05\xf3\xc7\xd2\x1d.\xe7\xf3\x86\xe0N\xc0\xf2|\x04\xaeB\xae\xcc=\tj\xc9\xcdm\xba5\x12\xd3\x9a\xb5\xcd\x8b\x9e\x96\x94\x045\x18\x19\tC\xa4xo+\x9c\x0c\xf3\x9a\xe5\x11\xc4\x7fPh\r\x08\x14\xfa\xa6@\x04\x11\t\x83\x9e2\x03\xb2\xd2w\xe9p"}
2022-10-26 13:56:33,117 [salt.loader.lazy :960 ][DEBUG   ][14] The functions from module 'glob_match' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,118 [salt.utils.lazy  :99  ][DEBUG   ][14] LazyLoaded glob_match.match
2022-10-26 13:56:33,118 [salt.minion      :1709][INFO    ][14] User sudo_root Executing command state.apply with jid 20221026135633098860
2022-10-26 13:56:33,118 [salt.minion      :1717][DEBUG   ][14] Command details {'fun': 'state.apply', 'arg': ['test123'], 'tgt': 'myminion', 'jid': '20221026135633098860', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'glob', 'user': 'sudo_root'}
2022-10-26 13:56:33,118 [salt.minion      :32  ][TRACE   ][14] Started JIDs: []
2022-10-26 13:56:33,120 [salt.utils.process:1144][DEBUG   ][14] Subprocess ProcessPayload(jid=20221026135633098860) added
2022-10-26 13:56:33,131 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][75] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2022-10-26 13:56:33,131 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load log4mongo
2022-10-26 13:56:33,132 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][75] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2022-10-26 13:56:33,132 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load raven
2022-10-26 13:56:33,133 [salt.loader.lazy :32  ][TRACE   ][75] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2022-10-26 13:56:33,204 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'jinja' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,204 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded jinja.render
2022-10-26 13:56:33,205 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'yaml' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,205 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded yaml.render
2022-10-26 13:56:33,207 [salt.minion      :1913][INFO    ][75] Starting a new job 20221026135633098860 with PID 75
2022-10-26 13:56:33,208 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'direct_call' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,208 [salt.loader.lazy :32  ][TRACE   ][75] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
2022-10-26 13:56:33,208 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'splay' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,209 [salt.utils.path  :32  ][TRACE   ][75] 'sudo' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin']'
2022-10-26 13:56:33,209 [salt.utils.path  :32  ][TRACE   ][75] 'transactional-update' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin']'
2022-10-26 13:56:33,209 [salt.loader.lazy :32  ][TRACE   ][75] Error loading executor.transactional_update: transactional_update executor requires a transactional system
2022-10-26 13:56:33,210 [salt.utils.lazy  :102 ][DEBUG   ][75] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
2022-10-26 13:56:33,213 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'state' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,213 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded state.apply
2022-10-26 13:56:33,213 [salt.minion      :32  ][TRACE   ][75] Executors list ['direct_call']
2022-10-26 13:56:33,216 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load immutables
2022-10-26 13:56:33,217 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load singledispatch
2022-10-26 13:56:33,218 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load singledispatch_helpers
2022-10-26 13:56:33,218 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load backports_abc
2022-10-26 13:56:33,219 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load backports
2022-10-26 13:56:33,220 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load saltwinshell
2022-10-26 13:56:33,221 [tiamatpip.configure:94  ][DEBUG   ][75] TiamatPipPathFinder.find_spec: First time trying to load esky
2022-10-26 13:56:33,222 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'saltutil' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,222 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded saltutil.is_running
2022-10-26 13:56:33,223 [salt.loader.lazy :859 ][DEBUG   ][75] Override  __grains__: <module 'salt.loaded.int.module.grains' from '/opt/saltstack/salt/run/salt/modules/grains.py'>
2022-10-26 13:56:33,223 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'grains' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,224 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded grains.get
2022-10-26 13:56:33,226 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'config' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,227 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded config.get
2022-10-26 13:56:33,232 [salt.crypt       :509 ][DEBUG   ][75] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://192.168.122.22:4506')
2022-10-26 13:56:33,233 [salt.channel.client:32  ][TRACE   ][75] ReqChannel send crypt load={'cmd': '_master_opts'}
2022-10-26 13:56:33,238 [salt.state       :763 ][DEBUG   ][75] Gathering pillar data for state run
2022-10-26 13:56:33,238 [salt.pillar      :71  ][DEBUG   ][75] Determining pillar cache
2022-10-26 13:56:33,238 [salt.crypt       :509 ][DEBUG   ][75] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://192.168.122.22:4506')
2022-10-26 13:56:33,238 [salt.pillar      :32  ][TRACE   ][75] ext_pillar_extra_data = {}
2022-10-26 13:56:33,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:33,326 [salt.crypt       :211 ][DEBUG   ][75] salt.crypt.get_rsa_key: Loading private key
2022-10-26 13:56:33,326 [salt.crypt       :903 ][DEBUG   ][75] Loaded minion key: /etc/salt/pki/minion/minion.pem
2022-10-26 13:56:33,328 [salt.crypt       :258 ][DEBUG   ][75] salt.crypt.verify_signature: Loading public key
2022-10-26 13:56:33,328 [salt.crypt       :219 ][DEBUG   ][75] salt.crypt.get_rsa_pub_key: Loading public key
2022-10-26 13:56:33,329 [salt.crypt       :260 ][DEBUG   ][75] salt.crypt.verify_signature: Verifying signature
2022-10-26 13:56:33,330 [salt.channel.client:313 ][DEBUG   ][75] Closing AsyncReqChannel instance
2022-10-26 13:56:33,330 [salt.state       :778 ][DEBUG   ][75] Finished gathering pillar data for state run
2022-10-26 13:56:33,330 [salt.state       :1194][INFO    ][75] Loading fresh modules for state activity
2022-10-26 13:56:33,364 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'jinja' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,364 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded jinja.render
2022-10-26 13:56:33,364 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'yaml' are being loaded by dir() on the loaded module
2022-10-26 13:56:33,365 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded yaml.render
2022-10-26 13:56:33,366 [salt.channel.client:32  ][TRACE   ][75] ReqChannel send crypt load={'saltenv': 'base', 'prefix': '', 'cmd': '_file_list'}
2022-10-26 13:56:34,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:35,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:36,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:37,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:38,216 [salt.channel.client:32  ][TRACE   ][14] Decoding payload: {'enc': 'aes', 'load': b"#T\x80\xc5\xa5\xc4Z\xac\x87\x8d\xb6\n\n\x1e\x87\x99&\x0153\xe6 \xf8\x8f'\x93\xec\xb9\xb2QM\xe0\x0e\x84\xa1+\x19\xdac\xd6)\xa2\x03\xf0\xff%4\xb4\xabf\x9a\xb9\xc5\x05f\xf3\x97\xc6\x80J\xdc\xdf\x83\xcd'\xed\xcaz\\\x92z\xdf\xc6\xef\x9f\x0b\xfe\xa9\x1c\xf1g\xf1N\xc4\x8c\xf7}\x114\xfe?\nE\xe7d\xdd\xc2\t\xd3\x9b}k\x06\x0cD\x8e\xbfk\x17\x0e\x1e\xdb\x0c\xed\xba\x1d\x1e_1\x7f\xcb0[\xc0\x12t9\xfcz\xb1\xd83\xdb\xc6\xba\xc7\x08\xbb\xd3\xa1x\x1d\x17\xa9geu\xf9\xdf\xd2V{W\xe3\x82S\xf2\xf7N\\\x17&\xbe.&\x1c\xf4\xfb\xfbr5\xe9\xee\x15\x06\xb8.C\xe0\x9d\xd8\xfce\x11\xd0 &t\xe3\xe1(\x1a\x9a\x1a\xfe\xf8\x01\xd1\xe0\xc3\x8b{\xcb\xce\xb6\x87E\xf1\xa5\x1c\x14\xfb\xd7h\xd8\xa3C\x18\xb3\xff\xf6\xc7\xca<", 'sig': b'\x7f\x16\xdb\x9f\x02K\x1a\x0c\xa1\x87\x03\xad\x8bh/\x8d\xb7P\xb6\x04(h\xda\x83\x14:\xff\x9b\x9f\x90\x03.YC{1\x08\xc0M\xd8\xf2\xcf]1\xac\xa8\xbb\xac#\xf1\xd0\xfa\xb5\x9e\x99"\xf4lL\xe48\xb8%(T\x1b\x92\xcb\x98+\xa6\xf0\xbe\xa0\x9fq\xf7\xa54l!i:]\x94Xk\x1a]\xb6GE\xfbX"o\x9b\xb8Uk{>\\U3\xf0\x9a\xc6Ff\xb7vUJ:\xd1\x80\x10\x054\xff\xc9\xa1Y\xd5\x95\xff6\xea\xbd(9\xd3K"\xa0\xee\x1b\xf8\x05a\xfd\x03\xe7\x83-\x05\xcb\xaa\xfc\x90\xbe\xbf\xe5\n\x0bh`(\x10\xff9_w\xce?\x811\xa5{\xcbd\nf/\x89\xb9\xb9\xa2h\xccD\x18\xe4\xe2D\x98\x0c4z\x83\x00J\xd0\xc9\xf8\r\xc1\xaf:\xbd\xd3\xa5\xff\xb2Sh|P\xbb\\5\x98\x9a=\xc2\xcc1<\xc9\xa1\xa5\x9e\x08\xdc\xdfw\xd4\x01\xa8D\xdd=\xda\x05\x1f\xd6\'\x84I&(\x92\xcd#z8\xd9\xefg\xc0\xf4\x9d\x9f_b'}
2022-10-26 13:56:38,216 [salt.channel.client:427 ][DEBUG   ][14] PubChannel received: {'enc': 'aes', 'load': {'fun': 'saltutil.find_job', 'arg': ['20221026135633098860'], 'tgt': ['myminion'], 'jid': '20221026135638202357', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'list', 'user': 'sudo_root'}, 'sig': b'\x7f\x16\xdb\x9f\x02K\x1a\x0c\xa1\x87\x03\xad\x8bh/\x8d\xb7P\xb6\x04(h\xda\x83\x14:\xff\x9b\x9f\x90\x03.YC{1\x08\xc0M\xd8\xf2\xcf]1\xac\xa8\xbb\xac#\xf1\xd0\xfa\xb5\x9e\x99"\xf4lL\xe48\xb8%(T\x1b\x92\xcb\x98+\xa6\xf0\xbe\xa0\x9fq\xf7\xa54l!i:]\x94Xk\x1a]\xb6GE\xfbX"o\x9b\xb8Uk{>\\U3\xf0\x9a\xc6Ff\xb7vUJ:\xd1\x80\x10\x054\xff\xc9\xa1Y\xd5\x95\xff6\xea\xbd(9\xd3K"\xa0\xee\x1b\xf8\x05a\xfd\x03\xe7\x83-\x05\xcb\xaa\xfc\x90\xbe\xbf\xe5\n\x0bh`(\x10\xff9_w\xce?\x811\xa5{\xcbd\nf/\x89\xb9\xb9\xa2h\xccD\x18\xe4\xe2D\x98\x0c4z\x83\x00J\xd0\xc9\xf8\r\xc1\xaf:\xbd\xd3\xa5\xff\xb2Sh|P\xbb\\5\x98\x9a=\xc2\xcc1<\xc9\xa1\xa5\x9e\x08\xdc\xdfw\xd4\x01\xa8D\xdd=\xda\x05\x1f\xd6\'\x84I&(\x92\xcd#z8\xd9\xefg\xc0\xf4\x9d\x9f_b'}
2022-10-26 13:56:38,217 [salt.loader.lazy :960 ][DEBUG   ][14] The functions from module 'list_match' are being loaded by dir() on the loaded module
2022-10-26 13:56:38,217 [salt.utils.lazy  :99  ][DEBUG   ][14] LazyLoaded list_match.match
2022-10-26 13:56:38,217 [salt.minion      :1709][INFO    ][14] User sudo_root Executing command saltutil.find_job with jid 20221026135638202357
2022-10-26 13:56:38,217 [salt.minion      :1717][DEBUG   ][14] Command details {'fun': 'saltutil.find_job', 'arg': ['20221026135633098860'], 'tgt': ['myminion'], 'jid': '20221026135638202357', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'list', 'user': 'sudo_root'}
2022-10-26 13:56:38,218 [salt.minion      :32  ][TRACE   ][14] Started JIDs: ['20221026135633098860']
2022-10-26 13:56:38,220 [salt.utils.process:1144][DEBUG   ][14] Subprocess ProcessPayload(jid=20221026135638202357) added
2022-10-26 13:56:38,232 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][83] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2022-10-26 13:56:38,233 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load log4mongo
2022-10-26 13:56:38,235 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][83] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2022-10-26 13:56:38,235 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load raven
2022-10-26 13:56:38,236 [salt.loader.lazy :32  ][TRACE   ][83] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2022-10-26 13:56:38,262 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:38,308 [salt.loader.lazy :960 ][DEBUG   ][83] The functions from module 'jinja' are being loaded by dir() on the loaded module
2022-10-26 13:56:38,308 [salt.utils.lazy  :99  ][DEBUG   ][83] LazyLoaded jinja.render
2022-10-26 13:56:38,309 [salt.loader.lazy :960 ][DEBUG   ][83] The functions from module 'yaml' are being loaded by dir() on the loaded module
2022-10-26 13:56:38,309 [salt.utils.lazy  :99  ][DEBUG   ][83] LazyLoaded yaml.render
2022-10-26 13:56:38,312 [salt.minion      :1913][INFO    ][83] Starting a new job 20221026135638202357 with PID 83
2022-10-26 13:56:38,312 [salt.loader.lazy :960 ][DEBUG   ][83] The functions from module 'direct_call' are being loaded by dir() on the loaded module
2022-10-26 13:56:38,313 [salt.loader.lazy :32  ][TRACE   ][83] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
2022-10-26 13:56:38,313 [salt.loader.lazy :960 ][DEBUG   ][83] The functions from module 'splay' are being loaded by dir() on the loaded module
2022-10-26 13:56:38,314 [salt.utils.path  :32  ][TRACE   ][83] 'sudo' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin']'
2022-10-26 13:56:38,314 [salt.utils.path  :32  ][TRACE   ][83] 'transactional-update' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin']'
2022-10-26 13:56:38,314 [salt.loader.lazy :32  ][TRACE   ][83] Error loading executor.transactional_update: transactional_update executor requires a transactional system
2022-10-26 13:56:38,314 [salt.utils.lazy  :102 ][DEBUG   ][83] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
2022-10-26 13:56:38,319 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load immutables
2022-10-26 13:56:38,321 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load singledispatch
2022-10-26 13:56:38,322 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load singledispatch_helpers
2022-10-26 13:56:38,322 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load backports_abc
2022-10-26 13:56:38,323 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load backports
2022-10-26 13:56:38,323 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load saltwinshell
2022-10-26 13:56:38,326 [tiamatpip.configure:94  ][DEBUG   ][83] TiamatPipPathFinder.find_spec: First time trying to load esky
2022-10-26 13:56:38,326 [salt.loader.lazy :960 ][DEBUG   ][83] The functions from module 'saltutil' are being loaded by dir() on the loaded module
2022-10-26 13:56:38,327 [salt.utils.lazy  :99  ][DEBUG   ][83] LazyLoaded saltutil.find_job
2022-10-26 13:56:38,327 [salt.minion      :32  ][TRACE   ][83] Executors list ['direct_call']
2022-10-26 13:56:38,329 [salt.minion      :2192][INFO    ][83] Returning information for job: 20221026135638202357
2022-10-26 13:56:38,329 [salt.minion      :32  ][TRACE   ][83] Return data: {'success': True, 'return': {'pid': 75, 'fun': 'state.apply', 'arg': ['test123'], 'tgt': 'myminion', 'jid': '20221026135633098860', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'glob', 'user': 'sudo_root'}, 'retcode': 0, 'jid': '20221026135638202357', 'fun': 'saltutil.find_job', 'fun_args': ['20221026135633098860'], 'master_id': 'localhost_master'}
2022-10-26 13:56:38,331 [salt.utils.event :315 ][DEBUG   ][83] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pub.ipc
2022-10-26 13:56:38,331 [salt.utils.event :316 ][DEBUG   ][83] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:38,332 [salt.transport.ipc:32  ][TRACE   ][83] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:38,332 [salt.transport.ipc:32  ][TRACE   ][14] IPCServer: Handling connection to address: <socket.socket fd=43, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_ac43295fd5_pull.ipc>
2022-10-26 13:56:38,332 [salt.utils.event :821 ][DEBUG   ][83] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'myminion', 'success': True, 'return': {'pid': 75, 'fun': 'state.apply', 'arg': ['test123'], 'tgt': 'myminion', 'jid': '20221026135633098860', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'glob', 'user': 'sudo_root'}, 'retcode': 0, 'jid': '20221026135638202357', 'fun': 'saltutil.find_job', 'fun_args': ['20221026135633098860'], 'master_id': 'localhost_master', '_stamp': '2022-10-26T13:56:38.332871'}
2022-10-26 13:56:38,333 [salt.transport.ipc:373 ][DEBUG   ][83] Closing IPCMessageClient instance
2022-10-26 13:56:38,333 [salt.minion      :32  ][TRACE   ][83] ret_val = True
2022-10-26 13:56:38,333 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '__master_req_channel_payload'
2022-10-26 13:56:38,333 [salt.minion      :2061][DEBUG   ][83] minion return: {'success': True, 'return': {'pid': 75, 'fun': 'state.apply', 'arg': ['test123'], 'tgt': 'myminion', 'jid': '20221026135633098860', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'glob', 'user': 'sudo_root'}, 'retcode': 0, 'jid': '20221026135638202357', 'fun': 'saltutil.find_job', 'fun_args': ['20221026135633098860'], 'master_id': 'localhost_master'}
2022-10-26 13:56:38,333 [salt.minion      :890 ][DEBUG   ][14] Minion return retry timer set to 9 seconds (randomized)
2022-10-26 13:56:38,334 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'cmd': '_return', 'id': 'myminion', 'success': True, 'return': {'pid': 75, 'fun': 'state.apply', 'arg': ['test123'], 'tgt': 'myminion', 'jid': '20221026135633098860', 'ret': '', 'master_id': 'localhost_master', 'tgt_type': 'glob', 'user': 'sudo_root'}, 'retcode': 0, 'jid': '20221026135638202357', 'fun': 'saltutil.find_job', 'fun_args': ['20221026135633098860'], 'master_id': 'localhost_master', '_stamp': '2022-10-26T13:56:38.332871'}
2022-10-26 13:56:38,336 [salt.transport.ipc:32  ][TRACE   ][14] Client disconnected from IPC /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:39,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:39,263 [salt.utils.process:1155][DEBUG   ][14] Subprocess ProcessPayload(jid=20221026135638202357) cleaned up
2022-10-26 13:56:40,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:41,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:42,262 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:43,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:44,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:44,491 [salt.channel.client:32  ][TRACE   ][75] ReqChannel send crypt load={'path': 'test123.sls', 'saltenv': 'base', 'cmd': '_file_hash'}
2022-10-26 13:56:44,495 [salt.channel.client:32  ][TRACE   ][75] ReqChannel send crypt load={'path': 'test123.sls', 'saltenv': 'base', 'cmd': '_file_find'}
2022-10-26 13:56:44,498 [salt.fileclient  :1204][DEBUG   ][75] In saltenv 'base', looking at rel_path 'test123.sls' to resolve 'salt://test123.sls'
2022-10-26 13:56:44,499 [salt.fileclient  :1213][DEBUG   ][75] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/test123.sls' to resolve 'salt://test123.sls'
2022-10-26 13:56:44,499 [salt.fileclient  :1234][DEBUG   ][75] Fetching file from saltenv 'base', ** attempting ** 'salt://test123.sls'
2022-10-26 13:56:44,499 [salt.fileclient  :1263][DEBUG   ][75] No dest file found
2022-10-26 13:56:44,499 [salt.channel.client:32  ][TRACE   ][75] ReqChannel send crypt load={'path': 'test123.sls', 'saltenv': 'base', 'cmd': '_serve_file', 'loc': 0}
2022-10-26 13:56:44,505 [salt.channel.client:32  ][TRACE   ][75] ReqChannel send crypt load={'path': 'test123.sls', 'saltenv': 'base', 'cmd': '_serve_file', 'loc': 22, 'nonce': 'ff87ca1067aa4aed817b599dee009274'}
2022-10-26 13:56:44,508 [salt.fileclient  :1350][INFO    ][75] Fetching file from saltenv 'base', ** done ** 'test123.sls'
2022-10-26 13:56:44,508 [salt.template    :53  ][DEBUG   ][75] compile template: /var/cache/salt/minion/files/base/test123.sls
2022-10-26 13:56:44,508 [salt.utils.jinja :92  ][DEBUG   ][75] Jinja search path: ['/var/cache/salt/minion/files/base']
2022-10-26 13:56:44,514 [salt.crypt       :509 ][DEBUG   ][75] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'myminion', 'tcp://192.168.122.22:4506')
2022-10-26 13:56:44,517 [salt.template    :23  ][PROFILE ][75] Time (in seconds) to render '/var/cache/salt/minion/files/base/test123.sls' using 'jinja' renderer: 0.008275032043457031
2022-10-26 13:56:44,517 [salt.template    :116 ][DEBUG   ][75] Rendered data from file: /var/cache/salt/minion/files/base/test123.sls:
test123:
  event.send

2022-10-26 13:56:44,517 [salt.template    :23  ][PROFILE ][75] Time (in seconds) to render '/var/cache/salt/minion/files/base/test123.sls' using 'yaml' renderer: 0.00016069412231445312
2022-10-26 13:56:44,518 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'config' are being loaded by dir() on the loaded module
2022-10-26 13:56:44,518 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded config.option
2022-10-26 13:56:44,518 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'event' are being loaded by dir() on the loaded module
2022-10-26 13:56:44,518 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded event.send
2022-10-26 13:56:44,518 [salt.state       :2159][INFO    ][75] Running state [test123] at time 13:56:44.518851
2022-10-26 13:56:44,519 [salt.state       :2190][INFO    ][75] Executing state event.send for [test123]
2022-10-26 13:56:44,519 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'event' are being loaded by dir() on the loaded module
2022-10-26 13:56:44,519 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded event.send
2022-10-26 13:56:44,520 [salt.utils.event :315 ][DEBUG   ][75] MinionEvent PUB socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pub.ipc
2022-10-26 13:56:44,520 [salt.utils.event :316 ][DEBUG   ][75] MinionEvent PULL socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,521 [salt.transport.ipc:32  ][TRACE   ][75] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,521 [salt.transport.ipc:32  ][TRACE   ][14] IPCServer: Handling connection to address: <socket.socket fd=38, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_ac43295fd5_pull.ipc>
2022-10-26 13:56:44,521 [salt.utils.event :821 ][DEBUG   ][75] Sending event: tag = fire_master; data = {'data': {}, 'tag': 'test123', 'events': None, 'pretag': None, '_stamp': '2022-10-26T13:56:44.521344'}
2022-10-26 13:56:44,521 [salt.transport.ipc:373 ][DEBUG   ][75] Closing IPCMessageClient instance
2022-10-26 13:56:44,521 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag 'fire_master'
2022-10-26 13:56:44,521 [salt.state       :319 ][INFO    ][75] {'tag': 'test123', 'data': None}
2022-10-26 13:56:44,522 [salt.minion      :2728][DEBUG   ][14] Forwarding master event tag=test123
2022-10-26 13:56:44,522 [salt.state       :2345][INFO    ][75] Completed state [test123] at time 13:56:44.522044 (duration_in_ms=3.194)
2022-10-26 13:56:44,522 [salt.state       :3401][DEBUG   ][75] File /var/cache/salt/minion/accumulator/140128929571936 does not exist, no need to cleanup
2022-10-26 13:56:44,522 [salt.channel.client:313 ][DEBUG   ][75] Closing AsyncReqChannel instance
2022-10-26 13:56:44,522 [salt.utils.event :315 ][DEBUG   ][14] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pub.ipc
2022-10-26 13:56:44,522 [salt.utils.event :316 ][DEBUG   ][14] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,523 [salt.loader.lazy :960 ][DEBUG   ][75] The functions from module 'state' are being loaded by dir() on the loaded module
2022-10-26 13:56:44,523 [salt.transport.ipc:32  ][TRACE   ][14] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,523 [salt.utils.lazy  :99  ][DEBUG   ][75] LazyLoaded state.check_result
2022-10-26 13:56:44,523 [salt.minion      :2192][INFO    ][75] Returning information for job: 20221026135633098860
2022-10-26 13:56:44,523 [salt.utils.event :769 ][DEBUG   ][14] Sending event: tag = __master_req_channel_payload; data = {'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': {}, 'tag': 'test123', '_stamp': '2022-10-26T13:56:44.523574'}
2022-10-26 13:56:44,523 [salt.minion      :32  ][TRACE   ][75] Return data: {'success': True, 'return': {'event_|-test123_|-test123_|-send': {'name': 'test123', 'changes': {'tag': 'test123', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'test123', '__run_num__': 0, 'start_time': '13:56:44.518850', 'duration': 3.194, '__id__': 'test123'}}, 'retcode': 0, 'jid': '20221026135633098860', 'fun': 'state.apply', 'fun_args': ['test123'], 'master_id': 'localhost_master'}
2022-10-26 13:56:44,524 [salt.transport.ipc:32  ][TRACE   ][14] IPCServer: Handling connection to address: <socket.socket fd=50, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_ac43295fd5_pull.ipc>
2022-10-26 13:56:44,524 [salt.utils.event :315 ][DEBUG   ][75] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pub.ipc
2022-10-26 13:56:44,524 [salt.utils.event :316 ][DEBUG   ][75] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,524 [salt.transport.ipc:32  ][TRACE   ][14] Client disconnected from IPC /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,524 [salt.transport.ipc:373 ][DEBUG   ][14] Closing IPCMessageClient instance
2022-10-26 13:56:44,524 [salt.transport.ipc:32  ][TRACE   ][75] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,524 [salt.transport.ipc:32  ][TRACE   ][14] Client disconnected from IPC /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,524 [salt.transport.ipc:32  ][TRACE   ][14] IPCServer: Handling connection to address: <socket.socket fd=38, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_ac43295fd5_pull.ipc>
2022-10-26 13:56:44,525 [salt.utils.event :821 ][DEBUG   ][75] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'myminion', 'success': True, 'return': {'event_|-test123_|-test123_|-send': {'name': 'test123', 'changes': {'tag': 'test123', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'test123', '__run_num__': 0, 'start_time': '13:56:44.518850', 'duration': 3.194, '__id__': 'test123'}}, 'retcode': 0, 'jid': '20221026135633098860', 'fun': 'state.apply', 'fun_args': ['test123'], 'master_id': 'localhost_master', 'out': 'highstate', '_stamp': '2022-10-26T13:56:44.524985'}
2022-10-26 13:56:44,525 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '__master_req_channel_payload'
2022-10-26 13:56:44,525 [salt.minion      :890 ][DEBUG   ][14] Minion return retry timer set to 7 seconds (randomized)
2022-10-26 13:56:44,525 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': {}, 'tag': 'test123', '_stamp': '2022-10-26T13:56:44.523574'}
2022-10-26 13:56:44,525 [salt.transport.ipc:373 ][DEBUG   ][75] Closing IPCMessageClient instance
2022-10-26 13:56:44,525 [salt.minion      :32  ][TRACE   ][75] ret_val = True
2022-10-26 13:56:44,525 [salt.minion      :2061][DEBUG   ][75] minion return: {'success': True, 'return': {'event_|-test123_|-test123_|-send': {'name': 'test123', 'changes': {'tag': 'test123', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'test123', '__run_num__': 0, 'start_time': '13:56:44.518850', 'duration': 3.194, '__id__': 'test123'}}, 'retcode': 0, 'jid': '20221026135633098860', 'fun': 'state.apply', 'fun_args': ['test123'], 'master_id': 'localhost_master'}
2022-10-26 13:56:44,526 [salt.transport.ipc:32  ][TRACE   ][14] Client disconnected from IPC /var/run/salt/minion/minion_event_ac43295fd5_pull.ipc
2022-10-26 13:56:44,526 [salt.minion      :2690][DEBUG   ][14] Minion of 'salt' is handling event tag '__master_req_channel_payload'
2022-10-26 13:56:44,526 [salt.minion      :890 ][DEBUG   ][14] Minion return retry timer set to 9 seconds (randomized)
2022-10-26 13:56:44,527 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'cmd': '_return', 'id': 'myminion', 'success': True, 'return': {'event_|-test123_|-test123_|-send': {'name': 'test123', 'changes': {'tag': 'test123', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'test123', '__run_num__': 0, 'start_time': '13:56:44.518850', 'duration': 3.194, '__id__': 'test123'}}, 'retcode': 0, 'jid': '20221026135633098860', 'fun': 'state.apply', 'fun_args': ['test123'], 'master_id': 'localhost_master', 'out': 'highstate', '_stamp': '2022-10-26T13:56:44.524985'}
2022-10-26 13:56:45,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:45,264 [salt.utils.process:1155][DEBUG   ][14] Subprocess ProcessPayload(jid=20221026135633098860) cleaned up
2022-10-26 13:56:46,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:47,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:48,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:49,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:50,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:51,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:51,527 [salt.channel.client:32  ][TRACE   ][14] Failed to send msg SaltReqTimeoutError('Message timed out')
2022-10-26 13:56:51,527 [salt.channel.client:32  ][TRACE   ][14] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"\x1d\xb6!\xe9\x16l\x81f\xcd\xc2\x95&eF\xc5N1!\xc5\x14:\x90\x1b\xb7\x01\xb5\xd6F\xe7\xd0=\xd7\x12\x10\xc2g\x99\xc9\x0b\x1c\xfc~\x19\xbb\xbc\xa43v\xccQ\xd7\xedh\xe3pz~1\xa3r\xd6\xae\xa3P$\xaa}\x04\x99WbB\xf0\x8c\x7f\x05\x8b\xec\xed\xbb`\x10\xa0~@a'\xc6V\x0e\xf5\x14a@#M\xac\x1d\xa2\xd8\x19\xa84m\xef\x7f\x89\xfdy\x1e\x12S\xb1\x7fD\x8b\xec\x11\x0e\xc6xp\xbb=\x04\x84\xfd\xe1av\xac\xd5\x90z*\xe8G\xa9\x8b<aIiqe:\x0f\xde\x81\xd3\xd5Q\x02\xc6\xb6\x13\x88v!\xf5\x10\x10]\xbb]%\xa0\x84\x16-\x14\xaeDU\xe6\x9a3\x88M\xa9\x91\xf7\x0e\xe7\x87\x17p\xa5\x8a^e\xe6d\xb0\xf8\r\x8e*\x16\xa5\xae\xab\xf6t,\tSJ\xd1\xc5\xb6\x00%\x90\x1c\xf0\x8d\x17\x8a,Q\xf4L\xea\xfd\xe1\xd6\x13\x0cIV\x90\xa1\x12\xf9S.tbX\xb3\xd5e\xc6\xe4~\xa7\x10\xfdhoQ\xdd\x8f\x07\x84", 'data': {}, 'tag': 'test123', '_stamp': '2022-10-26T13:56:44.523574', 'nonce': '796cd80004b24980b5e79f6b04305601'}
2022-10-26 13:56:52,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:53,264 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:54,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====
2022-10-26 13:56:55,263 [salt.utils.schedule:32  ][TRACE   ][14] ==== evaluating schedule now None =====

OrangeDog · 2022-10-26T14:20:26Z

It appears the the event is re-sent after a timeout.

"_stamp": "2022-10-26T13:56:44.524180"
"_stamp": "2022-10-26T13:56:51.533665"

13:56:44,527 [salt.channel.client:32 ][TRACE ][14] ReqChannel send crypt
13:56:51,527 [salt.channel.client:32 ][TRACE ][14] Failed to send msg SaltReqTimeoutError('Message timed out')
13:56:51,527 [salt.channel.client:32 ][TRACE ][14] ReqChannel send crypt

This may be related to #62881.

supfors · 2022-10-27T10:20:41Z

It seems so yes. I do want to note that I've ran these tests on fresh machines with 0 load.

twangboy · 2023-04-28T22:26:29Z

Is the minion configured with multiple masters?

s0undt3ch · 2023-04-29T07:07:50Z

Could you please try with 3006.0?

I've created a test case mimicking your steps and I even repeat the process 3 times before giving up and so far I haven't received the same even twice in my test runs.

supfors · 2023-05-03T12:43:20Z

Just tested this on 2 fresh Ubuntu 22 VM's with salt 3006, one being master, the other having only the minion installed.
I still see the same behaviour, although it happens less frequent.

Trace from both master and minion is attached below. I've ran the tests described here: #62638.

We're not using multiple masters.

Minion

2023-05-03 08:04:26,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:27,587 [salt.channel.client:32  ][TRACE   ][1085] Decoding payload: {'enc': 'aes', 'load': b'\x07`e\xba\x86\xd01:\xbfy\xf4\x93\xef5\xb8\x1f\x8aM\xb0G\xad\xa7\x7f\x884\x9a\xcd&\xc7\xaen[\xe9\xcd"\xce.\xf3\xcc^\xa7\xc6\xde\xb4\xe0\xa7\x93\xef\x82\xaf\xe3\xa9\xf8\x8bf@!\xff\xad\xcd\xedj\xe9<\x80\x03,\x01\x00\xcd9\x82E(\xf7\xb5\xe3,\x02\xfat\xd2\x01\xfe\x0b\x8d\x18\xe8\x18\xe2\xaa\xb0.\x03D\xe3\xaa-(q\xab\xc5\x14\xd5\xc3&\xf0\x1d\x16\xa3h\xbe,4\x88wd\xcb{\xefb\xd9\xecZ\x99\xbb_\xfa3\x8e\xbf\xa7\x19ZOuI\xc3Z\xc0n\xfa\xedj\xbf\x8c\x1fF\xb0(\xd8A~v\x91\xbaj\x11b\xb6Xs\xb7(\xa2\x05;4\xe5\xb0\xc1\x94\xbaz\x1c\x9f\\\x8b$4\xb4\x9e4\xdd\xbd\xe7\xe3)\xd2f<\xaf', 'sig': b"~\x83v\xde{\xca?x\x04\xa0J7\x83\xb0;\xda\x8a,\xdaf\xccH\x10f\\\x10.\xa3%\xf4\xac\xdc]\x9ae|C\xa8\xa0\x9c\xf6\xe8_\xba\xab\x11)V\n\xfe\x056\x97\x84-\xf1.Z\xbb\xdeE\x9b\xbd\x13\\U\xfc\xb2\xda\x8d\x0c\x01\xa5\xa97\x8e\xa8Y\x03'<'\x1aP\x03\xa9\xbf\xc4\xf8K\xd9\xc6\xea\x95\x10w\x8bw<\xee\r)\xa6\xf7 \xa7\x92+\x16\xe3`\xdep\xf3\x8d\x95wT\x9e-g[BX\xbd\xa1\x8d\x80\x81\x91n\xf5\x97<\xad\xe3!\xd3R\x86F\xf9\x05\xd2\xbdk=<\ta\x00cH\x9a\x1c\xdb\x8c\x88)\x9a\xfe\xf5V/S\xe7e\x1d\xb2\xb6=\x899\x8c!#0\x8eZ\xad\x14\x9e\xa9\x16p\xea?\x82\xc3>\xeab\xac[n$\xe1^\xe6\xa8\xc5\x83\x9fnZ\xe3\x95g\xbb[\x18\xd9^\xdd\xae\xe1\x8c\xcc\xfb\xdc\x03\x04\xc6OT\xd4\x94.\xa9\xd5\x8a\xb6\xd9\xa8\x958\xe2\x81\xd0\xc47\t\xd4N\xceY\xe9]\x1e\xcf\xf2\xa5\x0b\xfc\xb4\x90"}
2023-05-03 08:04:27,587 [salt.channel.client:427 ][DEBUG   ][1085] PubChannel received: {'enc': 'aes', 'load': {'fun': 'state.apply', 'arg': ['debug.send'], 'tgt': 'salt3006-minion', 'jid': '20230503080427580663', 'ret': '', 'tgt_type': 'glob', 'user': 'root'}, 'sig': b"~\x83v\xde{\xca?x\x04\xa0J7\x83\xb0;\xda\x8a,\xdaf\xccH\x10f\\\x10.\xa3%\xf4\xac\xdc]\x9ae|C\xa8\xa0\x9c\xf6\xe8_\xba\xab\x11)V\n\xfe\x056\x97\x84-\xf1.Z\xbb\xdeE\x9b\xbd\x13\\U\xfc\xb2\xda\x8d\x0c\x01\xa5\xa97\x8e\xa8Y\x03'<'\x1aP\x03\xa9\xbf\xc4\xf8K\xd9\xc6\xea\x95\x10w\x8bw<\xee\r)\xa6\xf7 \xa7\x92+\x16\xe3`\xdep\xf3\x8d\x95wT\x9e-g[BX\xbd\xa1\x8d\x80\x81\x91n\xf5\x97<\xad\xe3!\xd3R\x86F\xf9\x05\xd2\xbdk=<\ta\x00cH\x9a\x1c\xdb\x8c\x88)\x9a\xfe\xf5V/S\xe7e\x1d\xb2\xb6=\x899\x8c!#0\x8eZ\xad\x14\x9e\xa9\x16p\xea?\x82\xc3>\xeab\xac[n$\xe1^\xe6\xa8\xc5\x83\x9fnZ\xe3\x95g\xbb[\x18\xd9^\xdd\xae\xe1\x8c\xcc\xfb\xdc\x03\x04\xc6OT\xd4\x94.\xa9\xd5\x8a\xb6\xd9\xa8\x958\xe2\x81\xd0\xc47\t\xd4N\xceY\xe9]\x1e\xcf\xf2\xa5\x0b\xfc\xb4\x90"}
2023-05-03 08:04:27,587 [salt.minion      :1709][INFO    ][1085] User root Executing command state.apply with jid 20230503080427580663
2023-05-03 08:04:27,587 [salt.minion      :1717][DEBUG   ][1085] Command details {'fun': 'state.apply', 'arg': ['debug.send'], 'tgt': 'salt3006-minion', 'jid': '20230503080427580663', 'ret': '', 'tgt_type': 'glob', 'user': 'root'}
2023-05-03 08:04:27,587 [salt.minion      :32  ][TRACE   ][1085] Started JIDs: ['20230503080255120055', '20230503080255466007', '20230503080300275635', '20230503080332872623', '20230503080340091382', '20230503080403907043', '20230503080411144313']
2023-05-03 08:04:27,589 [salt.utils.process:1145][DEBUG   ][1085] Subprocess ProcessPayload(jid=20230503080427580663) added
2023-05-03 08:04:27,596 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][1313] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2023-05-03 08:04:27,598 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][1313] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2023-05-03 08:04:27,598 [salt.loader.lazy :32  ][TRACE   ][1313] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2023-05-03 08:04:27,621 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,621 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded jinja.render
2023-05-03 08:04:27,622 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,622 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded yaml.render
2023-05-03 08:04:27,623 [salt.minion      :1913][INFO    ][1313] Starting a new job 20230503080427580663 with PID 1313
2023-05-03 08:04:27,623 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'direct_call' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,624 [salt.loader.lazy :32  ][TRACE   ][1313] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
2023-05-03 08:04:27,624 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'splay' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,625 [salt.utils.path  :32  ][TRACE   ][1313] 'transactional-update' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:27,625 [salt.loader.lazy :32  ][TRACE   ][1313] Error loading executor.transactional_update: transactional_update executor requires a transactional system
2023-05-03 08:04:27,625 [salt.utils.lazy  :102 ][DEBUG   ][1313] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
2023-05-03 08:04:27,627 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'state' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,628 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded state.apply
2023-05-03 08:04:27,628 [salt.minion      :32  ][TRACE   ][1313] Executors list ['direct_call']
2023-05-03 08:04:27,629 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'config' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,629 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded config.option
2023-05-03 08:04:27,635 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'saltutil' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,635 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded saltutil.is_running
2023-05-03 08:04:27,636 [salt.loader.lazy :863 ][DEBUG   ][1313] Override  __grains__: <module 'salt.loaded.int.module.grains' from '/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/grains.py'>
2023-05-03 08:04:27,636 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'grains' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,636 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded grains.get
2023-05-03 08:04:27,641 [salt.crypt       :506 ][DEBUG   ][1313] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:27,641 [salt.channel.client:32  ][TRACE   ][1313] ReqChannel send crypt load={'cmd': '_master_opts'}
2023-05-03 08:04:27,661 [salt.state       :767 ][DEBUG   ][1313] Gathering pillar data for state run
2023-05-03 08:04:27,662 [salt.pillar      :71  ][DEBUG   ][1313] Determining pillar cache
2023-05-03 08:04:27,662 [salt.crypt       :506 ][DEBUG   ][1313] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:27,662 [salt.pillar      :32  ][TRACE   ][1313] ext_pillar_extra_data = {}
2023-05-03 08:04:27,688 [salt.crypt       :208 ][DEBUG   ][1313] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:27,688 [salt.crypt       :900 ][DEBUG   ][1313] Loaded minion key: /etc/salt/pki/minion/minion.pem
2023-05-03 08:04:27,691 [salt.crypt       :255 ][DEBUG   ][1313] salt.crypt.verify_signature: Loading public key
2023-05-03 08:04:27,691 [salt.crypt       :216 ][DEBUG   ][1313] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:27,692 [salt.crypt       :257 ][DEBUG   ][1313] salt.crypt.verify_signature: Verifying signature
2023-05-03 08:04:27,692 [salt.channel.client:313 ][DEBUG   ][1313] Closing AsyncReqChannel instance
2023-05-03 08:04:27,693 [salt.state       :782 ][DEBUG   ][1313] Finished gathering pillar data for state run
2023-05-03 08:04:27,693 [salt.state       :1267][INFO    ][1313] Loading fresh modules for state activity
2023-05-03 08:04:27,712 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,712 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded jinja.render
2023-05-03 08:04:27,712 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,713 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded yaml.render
2023-05-03 08:04:27,713 [salt.channel.client:32  ][TRACE   ][1313] ReqChannel send crypt load={'saltenv': 'base', 'prefix': '', 'cmd': '_file_list'}
2023-05-03 08:04:27,719 [salt.channel.client:32  ][TRACE   ][1313] ReqChannel send crypt load={'path': 'debug/send.sls', 'saltenv': 'base', 'cmd': '_file_hash'}
2023-05-03 08:04:27,721 [salt.channel.client:32  ][TRACE   ][1313] ReqChannel send crypt load={'path': 'debug/send.sls', 'saltenv': 'base', 'cmd': '_file_find'}
2023-05-03 08:04:27,723 [salt.fileclient  :1198][DEBUG   ][1313] In saltenv 'base', looking at rel_path 'debug/send.sls' to resolve 'salt://debug/send.sls'
2023-05-03 08:04:27,724 [salt.fileclient  :1207][DEBUG   ][1313] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/debug/send.sls' to resolve 'salt://debug/send.sls'
2023-05-03 08:04:27,724 [salt.template    :53  ][DEBUG   ][1313] compile template: /var/cache/salt/minion/files/base/debug/send.sls
2023-05-03 08:04:27,724 [salt.utils.jinja :93  ][DEBUG   ][1313] Jinja search path: ['/var/cache/salt/minion/files/base']
2023-05-03 08:04:27,728 [salt.crypt       :506 ][DEBUG   ][1313] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:27,730 [salt.channel.client:313 ][DEBUG   ][1313] Closing AsyncReqChannel instance
2023-05-03 08:04:27,730 [salt.template    :23  ][PROFILE ][1313] Time (in seconds) to render '/var/cache/salt/minion/files/base/debug/send.sls' using 'jinja' renderer: 0.006380319595336914
2023-05-03 08:04:27,730 [salt.template    :116 ][DEBUG   ][1313] Rendered data from file: /var/cache/salt/minion/files/base/debug/send.sls:
debug/test:
  event.send

2023-05-03 08:04:27,731 [salt.template    :23  ][PROFILE ][1313] Time (in seconds) to render '/var/cache/salt/minion/files/base/debug/send.sls' using 'yaml' renderer: 0.000392913818359375
2023-05-03 08:04:27,731 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'config' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,731 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded config.option
2023-05-03 08:04:27,732 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'event' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,732 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded event.send
2023-05-03 08:04:27,732 [salt.state       :2257][INFO    ][1313] Running state [debug/test] at time 08:04:27.732371
2023-05-03 08:04:27,732 [salt.state       :2288][INFO    ][1313] Executing state event.send for [debug/test]
2023-05-03 08:04:27,733 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'event' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,733 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded event.send
2023-05-03 08:04:27,733 [salt.utils.event :315 ][DEBUG   ][1313] MinionEvent PUB socket URI: /var/run/salt/minion/minion_event_6432538fe7_pub.ipc
2023-05-03 08:04:27,733 [salt.utils.event :316 ][DEBUG   ][1313] MinionEvent PULL socket URI: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,734 [salt.transport.ipc:32  ][TRACE   ][1313] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,734 [salt.transport.ipc:32  ][TRACE   ][1085] IPCServer: Handling connection to address: <socket.socket fd=45, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_6432538fe7_pull.ipc>
2023-05-03 08:04:27,735 [salt.utils.event :823 ][DEBUG   ][1313] Sending event: tag = fire_master; data = {'data': {}, 'tag': 'debug/test', 'events': None, 'pretag': None, '_stamp': '2023-05-03T08:04:27.735004'}
2023-05-03 08:04:27,735 [salt.minion      :2692][DEBUG   ][1085] Minion of '192.168.122.254' is handling event tag 'fire_master'
2023-05-03 08:04:27,735 [salt.minion      :2730][DEBUG   ][1085] Forwarding master event tag=debug/test
2023-05-03 08:04:27,736 [salt.utils.event :315 ][DEBUG   ][1085] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_6432538fe7_pub.ipc
2023-05-03 08:04:27,736 [salt.utils.event :316 ][DEBUG   ][1085] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,736 [salt.transport.ipc:373 ][DEBUG   ][1313] Closing IPCMessageClient instance
2023-05-03 08:04:27,736 [salt.state       :323 ][INFO    ][1313] {'tag': 'debug/test', 'data': None}
2023-05-03 08:04:27,736 [salt.state       :2458][INFO    ][1313] Completed state [debug/test] at time 08:04:27.736872 (duration_in_ms=4.5)
2023-05-03 08:04:27,736 [salt.state       :3528][DEBUG   ][1313] File /var/cache/salt/minion/accumulator/140195380737456 does not exist, no need to cleanup
2023-05-03 08:04:27,737 [salt.channel.client:313 ][DEBUG   ][1313] Closing AsyncReqChannel instance
2023-05-03 08:04:27,737 [salt.transport.ipc:32  ][TRACE   ][1085] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,737 [salt.loader.lazy :964 ][DEBUG   ][1313] The functions from module 'state' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,737 [salt.utils.lazy  :99  ][DEBUG   ][1313] LazyLoaded state.check_result
2023-05-03 08:04:27,738 [salt.utils.event :771 ][DEBUG   ][1085] Sending event: tag = __master_req_channel_payload; data = {'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"V1\xf5u\x15<+=\xc3\x8e\xdc\xc0\xd8\xb9\xf2\x81\x14\x07\xfe\xd2\xdb\xe4\x90\xf1\x0e.\x05\xf5\xf4\x0c\x04\x0c1>\xb7\xbctt\x02G\xcd\xc1\x8c\xf8a\xaf\xf0H\xce\xe6\x8a\x8d4\x9f'\xacf\xd1!\xf9o\n\xb4\xdc;\x14\x1d\x8f\x7fp\xc8\xf30?\xf2\x87-\\8.o\x84n\xf8\x04f7\x00\x1dF\x81c,] \xd5M(\x96\xa19>\xe8\x87\x93<\xe7\xa6\x84\x8d\xaac\xb3\xfap\xf1\xa6\xbc\xac\x99\x15\xe4\xd9u\xbb\xff\xe2\xd0\xa3$b[\xde(9r\x99\xf1\xdd#(\xa8*-1\xdb\xd0M9\x8e\xfb\xb4\xfc\x93\xff;C\n\xd2}\xdbAs\x0f\x06\xd9\x05\xb3%\x94\xcf4M8\x11\xb6=^\x1a7\xd2\xb7\xac\xf2\xe1\xf6<\xd95\x85\xba\xcc\xc9\xdfb\xe2\xe4\x15\xd4o(\x9e\x9c@BI\xb4\x95\x04y m/N?\xfa\xdd.}\xe4m?=\xb1_\x8e\xa6\xac?/\x02<8\xe0$\xeeI\x01O\xf9\x87P\xabd\x86\xb0\xa6C\xbbj\xcfG-\xda\xc2\xff", 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:27.738025'}
2023-05-03 08:04:27,738 [salt.minion      :2192][INFO    ][1313] Returning information for job: 20230503080427580663
2023-05-03 08:04:27,738 [salt.minion      :32  ][TRACE   ][1313] Return data: {'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send']}
2023-05-03 08:04:27,738 [salt.transport.ipc:32  ][TRACE   ][1085] IPCServer: Handling connection to address: <socket.socket fd=61, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_6432538fe7_pull.ipc>
2023-05-03 08:04:27,738 [salt.utils.event :315 ][DEBUG   ][1313] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_6432538fe7_pub.ipc
2023-05-03 08:04:27,738 [salt.utils.event :316 ][DEBUG   ][1313] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,738 [salt.transport.ipc:32  ][TRACE   ][1085] Client disconnected from IPC /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,738 [salt.transport.ipc:373 ][DEBUG   ][1085] Closing IPCMessageClient instance
2023-05-03 08:04:27,738 [salt.transport.ipc:32  ][TRACE   ][1313] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,739 [salt.transport.ipc:32  ][TRACE   ][1085] IPCServer: Handling connection to address: <socket.socket fd=45, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_6432538fe7_pull.ipc>
2023-05-03 08:04:27,739 [salt.utils.event :823 ][DEBUG   ][1313] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send'], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.739111'}
2023-05-03 08:04:27,739 [salt.transport.ipc:32  ][TRACE   ][1085] Client disconnected from IPC /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,739 [salt.minion      :2692][DEBUG   ][1085] Minion of '192.168.122.254' is handling event tag '__master_req_channel_payload'
2023-05-03 08:04:27,739 [salt.transport.ipc:373 ][DEBUG   ][1313] Closing IPCMessageClient instance
2023-05-03 08:04:27,739 [salt.minion      :890 ][DEBUG   ][1085] Minion return retry timer set to 9 seconds (randomized)
2023-05-03 08:04:27,739 [salt.minion      :32  ][TRACE   ][1313] ret_val = True
2023-05-03 08:04:27,739 [salt.channel.client:32  ][TRACE   ][1085] ReqChannel send crypt load={'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"V1\xf5u\x15<+=\xc3\x8e\xdc\xc0\xd8\xb9\xf2\x81\x14\x07\xfe\xd2\xdb\xe4\x90\xf1\x0e.\x05\xf5\xf4\x0c\x04\x0c1>\xb7\xbctt\x02G\xcd\xc1\x8c\xf8a\xaf\xf0H\xce\xe6\x8a\x8d4\x9f'\xacf\xd1!\xf9o\n\xb4\xdc;\x14\x1d\x8f\x7fp\xc8\xf30?\xf2\x87-\\8.o\x84n\xf8\x04f7\x00\x1dF\x81c,] \xd5M(\x96\xa19>\xe8\x87\x93<\xe7\xa6\x84\x8d\xaac\xb3\xfap\xf1\xa6\xbc\xac\x99\x15\xe4\xd9u\xbb\xff\xe2\xd0\xa3$b[\xde(9r\x99\xf1\xdd#(\xa8*-1\xdb\xd0M9\x8e\xfb\xb4\xfc\x93\xff;C\n\xd2}\xdbAs\x0f\x06\xd9\x05\xb3%\x94\xcf4M8\x11\xb6=^\x1a7\xd2\xb7\xac\xf2\xe1\xf6<\xd95\x85\xba\xcc\xc9\xdfb\xe2\xe4\x15\xd4o(\x9e\x9c@BI\xb4\x95\x04y m/N?\xfa\xdd.}\xe4m?=\xb1_\x8e\xa6\xac?/\x02<8\xe0$\xeeI\x01O\xf9\x87P\xabd\x86\xb0\xa6C\xbbj\xcfG-\xda\xc2\xff", 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:27.738025'}
2023-05-03 08:04:27,739 [salt.minion      :2061][DEBUG   ][1313] minion return: {'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send']}
2023-05-03 08:04:27,740 [salt.transport.ipc:32  ][TRACE   ][1085] Client disconnected from IPC /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,741 [salt.minion      :2692][DEBUG   ][1085] Minion of '192.168.122.254' is handling event tag '__master_req_channel_payload'
2023-05-03 08:04:27,741 [salt.minion      :890 ][DEBUG   ][1085] Minion return retry timer set to 8 seconds (randomized)
2023-05-03 08:04:27,741 [salt.channel.client:32  ][TRACE   ][1085] ReqChannel send crypt load={'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send'], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.739111'}
2023-05-03 08:04:27,785 [salt.channel.client:32  ][TRACE   ][1085] Decoding payload: {'enc': 'aes', 'load': b"\xf2\xe2{\xab\x15e\x00\x07\x86\xb4L\xb7\xd4\xc3\x0b2\xbf\x89\xba\x7f$\xad\x8aI\x1aa}eH\xb4{\xe9qf\n\x06\xda\xcfB\xb0\xc4i~E\x00\x8b\x05\xf5\x8a:\xdb\xebB\x1bz\x9d\xa5\xfd\xc4\x9b%k\xa7}%d\x1a\xe9\xd0C\xbf\xd4\x83\x99~\xce \x8eH\xb5\xff6\xb6\xd1@B\r(\x18\xb2Jy\xae\xff{\x0exd\xfe9E\xb0N\xbbK|EU\x95D\xfee\xf7\xd6\xba\xc3\xa7\xa1\x15\xa5Z)\xbduUC\x0b\xc9m\xac\x92oo\xae\xa5t\xf3\xabv\xd5G\x9a:q\x7f\xc4\xeb\x91Un\xcb\xd0Z\x81^\xd6\x04$dV?\x94{\xbc:\xf8\x9e\xe7/Fc>\x05\xde\xe8K\x0f\xd6\t\x07=\x9a\x81\xe2)\xcd\x8e\xadC\x97\xbd\x13h\x02\x83\x9e\xe1\xf8\xdfC\x10dA\x1a\xd7\x07&^ \xb9\x83~\xca=\xbd\x97\x99\xf6\xf5\x07\xafI(\xa7\xd9&^\x13'\x04\x13\xe7=e\xf9\x9f\x83\xd5\xd2->\xb2\n_1\x11\xd5\xf1\xdf\xfbs\xd20\x05`\x81", 'sig': b"\x17\xa4\xa6\x1d\x80n1Hf\xd4\x96\xd1\xbe|\x94\x8bwr\x1f\xf8\xbc\x99\xb6\xaf'\xf9\n\x02\x1a\xc3\\w:\xdb\x10\x83\x16\x956h\x8e\x80\xf4\xabj\xddm\xf0\xa8bt\x81\x84\xac\xc4\xa5\xe5a\xfc[\x83\x17\x0c\xf4\x03\xde\x07\x9bW|1\xaaRB\xee\xc6.5\xfc]_\x19\xff,\x989l\xf2\xe85\x986\xc6\xf5M\xd9\xd67\xad\x1bZL\xb4b\x04\xa8\x00\xfdA\xea\x838\xec\xa7L\xc3\x02\x90\x8b\xe2\xf5\xe8\x014H\t?s+J\xb0\xfb\x8a\x90IPb\xc0\x97$\xba\x1as\xc6|X\x1a\xc9p~\xcb\t\xa6\xb4\xa6\n\xf7`4\x07\x92D\xac\x9a\xfcN\\\xae(!\xc5\xbak\x9e\xf3\xc7^\xf8\x1eyb\xf8\xfd\xc4\x90p\xfem|b\xda\xb5\x99\x96~6NO\x04\xc1\xed\xeb\x8f\xbf\x95\xf1\x82JY\xba\x86\x1b\xf3\xd7\x8e\xc7!K\x82zH\x81S\n\xbe:\xe3\x0bd\xdef\xda\xb0}\x04\x9f\xe0g\xc9\xc2\t\x7fz\xbc\x16\x822\xad\\6\x16\x95Km\xd3\x1f"}
2023-05-03 08:04:27,786 [salt.channel.client:427 ][DEBUG   ][1085] PubChannel received: {'enc': 'aes', 'load': {'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'tgt': 'salt3006-minion', 'jid': '20230503080427775179', 'ret': '', 'tgt_type': 'glob', 'user': 'salt'}, 'sig': b"\x17\xa4\xa6\x1d\x80n1Hf\xd4\x96\xd1\xbe|\x94\x8bwr\x1f\xf8\xbc\x99\xb6\xaf'\xf9\n\x02\x1a\xc3\\w:\xdb\x10\x83\x16\x956h\x8e\x80\xf4\xabj\xddm\xf0\xa8bt\x81\x84\xac\xc4\xa5\xe5a\xfc[\x83\x17\x0c\xf4\x03\xde\x07\x9bW|1\xaaRB\xee\xc6.5\xfc]_\x19\xff,\x989l\xf2\xe85\x986\xc6\xf5M\xd9\xd67\xad\x1bZL\xb4b\x04\xa8\x00\xfdA\xea\x838\xec\xa7L\xc3\x02\x90\x8b\xe2\xf5\xe8\x014H\t?s+J\xb0\xfb\x8a\x90IPb\xc0\x97$\xba\x1as\xc6|X\x1a\xc9p~\xcb\t\xa6\xb4\xa6\n\xf7`4\x07\x92D\xac\x9a\xfcN\\\xae(!\xc5\xbak\x9e\xf3\xc7^\xf8\x1eyb\xf8\xfd\xc4\x90p\xfem|b\xda\xb5\x99\x96~6NO\x04\xc1\xed\xeb\x8f\xbf\x95\xf1\x82JY\xba\x86\x1b\xf3\xd7\x8e\xc7!K\x82zH\x81S\n\xbe:\xe3\x0bd\xdef\xda\xb0}\x04\x9f\xe0g\xc9\xc2\t\x7fz\xbc\x16\x822\xad\\6\x16\x95Km\xd3\x1f"}
2023-05-03 08:04:27,786 [salt.minion      :1709][INFO    ][1085] User salt Executing command state.apply with jid 20230503080427775179
2023-05-03 08:04:27,786 [salt.minion      :1717][DEBUG   ][1085] Command details {'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'tgt': 'salt3006-minion', 'jid': '20230503080427775179', 'ret': '', 'tgt_type': 'glob', 'user': 'salt'}
2023-05-03 08:04:27,786 [salt.minion      :32  ][TRACE   ][1085] Started JIDs: ['20230503080255120055', '20230503080255466007', '20230503080300275635', '20230503080332872623', '20230503080340091382', '20230503080403907043', '20230503080411144313', '20230503080427580663']
2023-05-03 08:04:27,788 [salt.utils.process:1145][DEBUG   ][1085] Subprocess ProcessPayload(jid=20230503080427775179) added
2023-05-03 08:04:27,799 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][1329] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2023-05-03 08:04:27,801 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][1329] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2023-05-03 08:04:27,802 [salt.loader.lazy :32  ][TRACE   ][1329] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2023-05-03 08:04:27,832 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,832 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded jinja.render
2023-05-03 08:04:27,833 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,833 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded yaml.render
2023-05-03 08:04:27,835 [salt.minion      :1913][INFO    ][1329] Starting a new job 20230503080427775179 with PID 1329
2023-05-03 08:04:27,835 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'direct_call' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,836 [salt.loader.lazy :32  ][TRACE   ][1329] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
2023-05-03 08:04:27,836 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'splay' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,837 [salt.utils.path  :32  ][TRACE   ][1329] 'transactional-update' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:27,837 [salt.loader.lazy :32  ][TRACE   ][1329] Error loading executor.transactional_update: transactional_update executor requires a transactional system
2023-05-03 08:04:27,837 [salt.utils.lazy  :102 ][DEBUG   ][1329] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
2023-05-03 08:04:27,839 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'state' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,840 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded state.apply
2023-05-03 08:04:27,840 [salt.minion      :32  ][TRACE   ][1329] Executors list ['direct_call']
2023-05-03 08:04:27,846 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'saltutil' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,846 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded saltutil.is_running
2023-05-03 08:04:27,847 [salt.loader.lazy :863 ][DEBUG   ][1329] Override  __grains__: <module 'salt.loaded.int.module.grains' from '/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/grains.py'>
2023-05-03 08:04:27,847 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'grains' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,847 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded grains.get
2023-05-03 08:04:27,848 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'config' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,848 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded config.get
2023-05-03 08:04:27,852 [salt.crypt       :506 ][DEBUG   ][1329] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:27,853 [salt.channel.client:32  ][TRACE   ][1329] ReqChannel send crypt load={'cmd': '_master_opts'}
2023-05-03 08:04:27,869 [salt.state       :767 ][DEBUG   ][1329] Gathering pillar data for state run
2023-05-03 08:04:27,869 [salt.pillar      :71  ][DEBUG   ][1329] Determining pillar cache
2023-05-03 08:04:27,869 [salt.crypt       :506 ][DEBUG   ][1329] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:27,869 [salt.pillar      :32  ][TRACE   ][1329] ext_pillar_extra_data = {}
2023-05-03 08:04:27,897 [salt.crypt       :208 ][DEBUG   ][1329] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:27,897 [salt.crypt       :900 ][DEBUG   ][1329] Loaded minion key: /etc/salt/pki/minion/minion.pem
2023-05-03 08:04:27,899 [salt.crypt       :255 ][DEBUG   ][1329] salt.crypt.verify_signature: Loading public key
2023-05-03 08:04:27,899 [salt.crypt       :216 ][DEBUG   ][1329] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:27,899 [salt.crypt       :257 ][DEBUG   ][1329] salt.crypt.verify_signature: Verifying signature
2023-05-03 08:04:27,900 [salt.channel.client:313 ][DEBUG   ][1329] Closing AsyncReqChannel instance
2023-05-03 08:04:27,900 [salt.state       :782 ][DEBUG   ][1329] Finished gathering pillar data for state run
2023-05-03 08:04:27,900 [salt.state       :1267][INFO    ][1329] Loading fresh modules for state activity
2023-05-03 08:04:27,911 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:27,911 [salt.utils.process:1156][DEBUG   ][1085] Subprocess ProcessPayload(jid=20230503080427580663) cleaned up
2023-05-03 08:04:27,919 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,919 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded jinja.render
2023-05-03 08:04:27,920 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,920 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded yaml.render
2023-05-03 08:04:27,923 [salt.channel.client:32  ][TRACE   ][1329] ReqChannel send crypt load={'saltenv': 'base', 'prefix': '', 'cmd': '_file_list'}
2023-05-03 08:04:27,926 [salt.channel.client:32  ][TRACE   ][1329] ReqChannel send crypt load={'path': 'debug/action.sls', 'saltenv': 'base', 'cmd': '_file_hash'}
2023-05-03 08:04:27,929 [salt.channel.client:32  ][TRACE   ][1329] ReqChannel send crypt load={'path': 'debug/action.sls', 'saltenv': 'base', 'cmd': '_file_find'}
2023-05-03 08:04:27,931 [salt.fileclient  :1198][DEBUG   ][1329] In saltenv 'base', looking at rel_path 'debug/action.sls' to resolve 'salt://debug/action.sls'
2023-05-03 08:04:27,931 [salt.fileclient  :1207][DEBUG   ][1329] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/debug/action.sls' to resolve 'salt://debug/action.sls'
2023-05-03 08:04:27,932 [salt.template    :53  ][DEBUG   ][1329] compile template: /var/cache/salt/minion/files/base/debug/action.sls
2023-05-03 08:04:27,932 [salt.utils.jinja :93  ][DEBUG   ][1329] Jinja search path: ['/var/cache/salt/minion/files/base']
2023-05-03 08:04:27,936 [salt.crypt       :506 ][DEBUG   ][1329] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:27,939 [salt.channel.client:313 ][DEBUG   ][1329] Closing AsyncReqChannel instance
2023-05-03 08:04:27,939 [salt.template    :23  ][PROFILE ][1329] Time (in seconds) to render '/var/cache/salt/minion/files/base/debug/action.sls' using 'jinja' renderer: 0.007100582122802734
2023-05-03 08:04:27,939 [salt.template    :116 ][DEBUG   ][1329] Rendered data from file: /var/cache/salt/minion/files/base/debug/action.sls:
/tmp/test.txt:
  file.append:
    - text: |
        salt3006-minion -- Wednesday May 03 2023 08:04:27

2023-05-03 08:04:27,939 [salt.template    :23  ][PROFILE ][1329] Time (in seconds) to render '/var/cache/salt/minion/files/base/debug/action.sls' using 'yaml' renderer: 0.00049591064453125
2023-05-03 08:04:27,940 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'config' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,940 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded config.option
2023-05-03 08:04:27,941 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'file' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,941 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded file.append
2023-05-03 08:04:27,941 [salt.state       :2257][INFO    ][1329] Running state [/tmp/test.txt] at time 08:04:27.941704
2023-05-03 08:04:27,941 [salt.state       :2288][INFO    ][1329] Executing state file.append for [/tmp/test.txt]
2023-05-03 08:04:27,944 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'file' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,945 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded file.search
2023-05-03 08:04:27,945 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'files' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,945 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded files.is_text
2023-05-03 08:04:27,946 [salt.state       :323 ][INFO    ][1329] File changed:
---

+++

@@ -1,3 +1,4 @@

 salt3006-minion -- Wednesday May 03 2023 08:02:55
 salt3006-minion -- Wednesday May 03 2023 08:03:40
 salt3006-minion -- Wednesday May 03 2023 08:04:11
+salt3006-minion -- Wednesday May 03 2023 08:04:27
2023-05-03 08:04:27,946 [salt.state       :2458][INFO    ][1329] Completed state [/tmp/test.txt] at time 08:04:27.946783 (duration_in_ms=5.078)
2023-05-03 08:04:27,946 [salt.state       :3528][DEBUG   ][1329] File /var/cache/salt/minion/accumulator/140195375809296 does not exist, no need to cleanup
2023-05-03 08:04:27,946 [salt.channel.client:313 ][DEBUG   ][1329] Closing AsyncReqChannel instance
2023-05-03 08:04:27,947 [salt.loader.lazy :964 ][DEBUG   ][1329] The functions from module 'state' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,947 [salt.utils.lazy  :99  ][DEBUG   ][1329] LazyLoaded state.check_result
2023-05-03 08:04:27,948 [salt.minion      :2192][INFO    ][1329] Returning information for job: 20230503080427775179
2023-05-03 08:04:27,948 [salt.minion      :32  ][TRACE   ][1329] Return data: {'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -1,3 +1,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:02:55\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n+salt3006-minion -- Wednesday May 03 2023 08:04:27'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:27.941705', 'duration': 5.078, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080427775179', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}]}
2023-05-03 08:04:27,948 [salt.utils.event :315 ][DEBUG   ][1329] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_6432538fe7_pub.ipc
2023-05-03 08:04:27,948 [salt.utils.event :316 ][DEBUG   ][1329] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,948 [salt.transport.ipc:32  ][TRACE   ][1329] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:27,949 [salt.transport.ipc:32  ][TRACE   ][1085] IPCServer: Handling connection to address: <socket.socket fd=52, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_6432538fe7_pull.ipc>
2023-05-03 08:04:27,949 [salt.utils.event :823 ][DEBUG   ][1329] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -1,3 +1,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:02:55\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n+salt3006-minion -- Wednesday May 03 2023 08:04:27'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:27.941705', 'duration': 5.078, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080427775179', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.949691'}
2023-05-03 08:04:27,950 [salt.minion      :2692][DEBUG   ][1085] Minion of '192.168.122.254' is handling event tag '__master_req_channel_payload'
2023-05-03 08:04:27,950 [salt.minion      :890 ][DEBUG   ][1085] Minion return retry timer set to 9 seconds (randomized)
2023-05-03 08:04:27,950 [salt.transport.ipc:373 ][DEBUG   ][1329] Closing IPCMessageClient instance
2023-05-03 08:04:27,950 [salt.channel.client:32  ][TRACE   ][1085] ReqChannel send crypt load={'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -1,3 +1,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:02:55\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n+salt3006-minion -- Wednesday May 03 2023 08:04:27'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:27.941705', 'duration': 5.078, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080427775179', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.949691'}
2023-05-03 08:04:27,950 [salt.minion      :32  ][TRACE   ][1329] ret_val = True
2023-05-03 08:04:27,950 [salt.minion      :2061][DEBUG   ][1329] minion return: {'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -1,3 +1,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:02:55\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n+salt3006-minion -- Wednesday May 03 2023 08:04:27'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:27.941705', 'duration': 5.078, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080427775179', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}]}
2023-05-03 08:04:27,951 [salt.transport.ipc:32  ][TRACE   ][1085] Client disconnected from IPC /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:28,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:28,912 [salt.utils.process:1156][DEBUG   ][1085] Subprocess ProcessPayload(jid=20230503080427775179) cleaned up
2023-05-03 08:04:29,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:30,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:31,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:32,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:33,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:34,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:35,911 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:36,741 [salt.channel.client:32  ][TRACE   ][1085] Failed to send msg SaltReqTimeoutError('Message timed out')
2023-05-03 08:04:36,742 [salt.channel.client:32  ][TRACE   ][1085] ReqChannel send crypt load={'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'tok': b"V1\xf5u\x15<+=\xc3\x8e\xdc\xc0\xd8\xb9\xf2\x81\x14\x07\xfe\xd2\xdb\xe4\x90\xf1\x0e.\x05\xf5\xf4\x0c\x04\x0c1>\xb7\xbctt\x02G\xcd\xc1\x8c\xf8a\xaf\xf0H\xce\xe6\x8a\x8d4\x9f'\xacf\xd1!\xf9o\n\xb4\xdc;\x14\x1d\x8f\x7fp\xc8\xf30?\xf2\x87-\\8.o\x84n\xf8\x04f7\x00\x1dF\x81c,] \xd5M(\x96\xa19>\xe8\x87\x93<\xe7\xa6\x84\x8d\xaac\xb3\xfap\xf1\xa6\xbc\xac\x99\x15\xe4\xd9u\xbb\xff\xe2\xd0\xa3$b[\xde(9r\x99\xf1\xdd#(\xa8*-1\xdb\xd0M9\x8e\xfb\xb4\xfc\x93\xff;C\n\xd2}\xdbAs\x0f\x06\xd9\x05\xb3%\x94\xcf4M8\x11\xb6=^\x1a7\xd2\xb7\xac\xf2\xe1\xf6<\xd95\x85\xba\xcc\xc9\xdfb\xe2\xe4\x15\xd4o(\x9e\x9c@BI\xb4\x95\x04y m/N?\xfa\xdd.}\xe4m?=\xb1_\x8e\xa6\xac?/\x02<8\xe0$\xeeI\x01O\xf9\x87P\xabd\x86\xb0\xa6C\xbbj\xcfG-\xda\xc2\xff", 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:27.738025', 'nonce': '5d100dc94039412a94693d8a131b5a56'}
2023-05-03 08:04:36,793 [salt.channel.client:32  ][TRACE   ][1085] Decoding payload: {'enc': 'aes', 'load': b"\xf1\xf5\xd4\xe1H;]1\xad]ok-\x94\x93\x98\xb2\xad\xd5\xf1b\xe3\xeb\x1b'>\xd7\xec0&|H\xcb\xe4\xb337\xc2\xa9\x10\xf0p>~\xd4\xcf\x83\x07tF2\xd8\x1e\xe7;*z!\xf4Q\x9b>T\x1b0XX\xbcP\x83\xaec\x8a\x1bTq\x95\x83\xc8\xdeE\xb1\xdd=H\xa4Agm\xc5\x80:,\\\x1e\x95zFl\xce\xf3F\xc1\xac%=\xc8\xb0cz\x93h\xd8\xfd\xb3\x98\x15\xcb\xf9:\xc4\xbfgw\xcb\x8c\xb8\xb2y\xcd.9\x7f*\x9d>\xce\x16=\x08\xa7 \xb2\xe9=O\xcdB\x92\xf3\x08F\xf3{\xc2d\xbb\xbcP\x0f \xacf\xf7yW\xc0\x17\xb10\xf9\xe2@\x8e?T\xe3%\x94s^\x8ed{\xfbC\x93\x93\x85\x84\n\x01#C\xba\x04\xd9\xb5\x8b+\xab\xfb\xd2\x1b\x85\xd1\xf8\xe5\xa6\xc8B\x8d=\xb6\xceg\x89V\x98\x88\xf1\xf3\xf0\xe8\xe7l{\xcf\xc0\xad\xa7\x9bC\x08;\x8f}\xd7l\x15\x877\x9aL\x9c\x98\xf2\x03\x980V\x1d\xd5U\xc3\xa6", 'sig': b'O# \xad\xf0>i+?{\xf2^\xb9\xd0\x06\x05\xe2\xac\xce<\xc9\x82\xbf\xbeY\x16\x1cA\xf6\xcc~7\xfd`\xe9\x9c\xfb@\x87\xad\xc8\xabf\xb6\xfcg6\x95\xcfk\x8d\x05\x0b\xd0\n-\xa9\xa6<\x8a\xa7[y\n\xfc\xbb\x9b\xc0b\xbc\x82u\xac\xe7(\x04U+\x90\xfe\xa5~u\xc9f\xfci\xb0i\xddP\x08\x8c\xee\x0e\x06Q\xe5 \x06\x1e\x8b\xad\x03\xee\xcd\x94\xa7\xee\t1\xc7\x9a\xa8L\xa9\xdf\xacu\x03:\xb0r\xdf\xa8\x19Y\x9d\x14\x040\x15\xea\xa3\xa7\xd2\xf2>;\x1d^\xee\xf9&\xd2\x04j\xae\xe3%\xa9\xfb\x14\xd14fB\x03V\xcb\x99c\xb4\x82\x0c\xdd\xd6$0\xbf\x86\x9dY\xf9\xb2n&\x91,-z\x00\xef\xe7\xc1d\x1b\x10\x92U\xb1{\xe1\n\xa4\xfb\xa6\x1d\xffU&$\x87\n\x8c\xbe\xa8S5umh\xd9\xf3\xd3\x00P\xe5\xab\xd2\xfc0\xb6\xe1\xc5K\xd5\xf1\x8d\xe3r\x99xm\xcf\x83\x13\xd6\x9bc\x1a$\x1b\xaf\xf19\x86\xb3\r\xa1\xa3\x7f\xb0\x86\x8d\xc5'}
2023-05-03 08:04:36,793 [salt.channel.client:427 ][DEBUG   ][1085] PubChannel received: {'enc': 'aes', 'load': {'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'tgt': 'salt3006-minion', 'jid': '20230503080436786612', 'ret': '', 'tgt_type': 'glob', 'user': 'salt'}, 'sig': b'O# \xad\xf0>i+?{\xf2^\xb9\xd0\x06\x05\xe2\xac\xce<\xc9\x82\xbf\xbeY\x16\x1cA\xf6\xcc~7\xfd`\xe9\x9c\xfb@\x87\xad\xc8\xabf\xb6\xfcg6\x95\xcfk\x8d\x05\x0b\xd0\n-\xa9\xa6<\x8a\xa7[y\n\xfc\xbb\x9b\xc0b\xbc\x82u\xac\xe7(\x04U+\x90\xfe\xa5~u\xc9f\xfci\xb0i\xddP\x08\x8c\xee\x0e\x06Q\xe5 \x06\x1e\x8b\xad\x03\xee\xcd\x94\xa7\xee\t1\xc7\x9a\xa8L\xa9\xdf\xacu\x03:\xb0r\xdf\xa8\x19Y\x9d\x14\x040\x15\xea\xa3\xa7\xd2\xf2>;\x1d^\xee\xf9&\xd2\x04j\xae\xe3%\xa9\xfb\x14\xd14fB\x03V\xcb\x99c\xb4\x82\x0c\xdd\xd6$0\xbf\x86\x9dY\xf9\xb2n&\x91,-z\x00\xef\xe7\xc1d\x1b\x10\x92U\xb1{\xe1\n\xa4\xfb\xa6\x1d\xffU&$\x87\n\x8c\xbe\xa8S5umh\xd9\xf3\xd3\x00P\xe5\xab\xd2\xfc0\xb6\xe1\xc5K\xd5\xf1\x8d\xe3r\x99xm\xcf\x83\x13\xd6\x9bc\x1a$\x1b\xaf\xf19\x86\xb3\r\xa1\xa3\x7f\xb0\x86\x8d\xc5'}
2023-05-03 08:04:36,793 [salt.minion      :1709][INFO    ][1085] User salt Executing command state.apply with jid 20230503080436786612
2023-05-03 08:04:36,793 [salt.minion      :1717][DEBUG   ][1085] Command details {'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'tgt': 'salt3006-minion', 'jid': '20230503080436786612', 'ret': '', 'tgt_type': 'glob', 'user': 'salt'}
2023-05-03 08:04:36,793 [salt.minion      :32  ][TRACE   ][1085] Started JIDs: ['20230503080255120055', '20230503080255466007', '20230503080300275635', '20230503080332872623', '20230503080340091382', '20230503080403907043', '20230503080411144313', '20230503080427580663', '20230503080427775179']
2023-05-03 08:04:36,795 [salt.utils.process:1145][DEBUG   ][1085] Subprocess ProcessPayload(jid=20230503080436786612) added
2023-05-03 08:04:36,802 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][1341] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2023-05-03 08:04:36,803 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][1341] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2023-05-03 08:04:36,803 [salt.loader.lazy :32  ][TRACE   ][1341] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2023-05-03 08:04:36,823 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,823 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded jinja.render
2023-05-03 08:04:36,824 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,824 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded yaml.render
2023-05-03 08:04:36,825 [salt.minion      :1913][INFO    ][1341] Starting a new job 20230503080436786612 with PID 1341
2023-05-03 08:04:36,825 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'direct_call' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,825 [salt.loader.lazy :32  ][TRACE   ][1341] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
2023-05-03 08:04:36,826 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'splay' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,826 [salt.utils.path  :32  ][TRACE   ][1341] 'transactional-update' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:36,826 [salt.loader.lazy :32  ][TRACE   ][1341] Error loading executor.transactional_update: transactional_update executor requires a transactional system
2023-05-03 08:04:36,826 [salt.utils.lazy  :102 ][DEBUG   ][1341] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
2023-05-03 08:04:36,829 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'state' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,829 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded state.apply
2023-05-03 08:04:36,829 [salt.minion      :32  ][TRACE   ][1341] Executors list ['direct_call']
2023-05-03 08:04:36,835 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'saltutil' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,835 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded saltutil.is_running
2023-05-03 08:04:36,835 [salt.loader.lazy :863 ][DEBUG   ][1341] Override  __grains__: <module 'salt.loaded.int.module.grains' from '/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/grains.py'>
2023-05-03 08:04:36,836 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'grains' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,836 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded grains.get
2023-05-03 08:04:36,837 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'config' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,837 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded config.get
2023-05-03 08:04:36,840 [salt.crypt       :506 ][DEBUG   ][1341] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:36,841 [salt.channel.client:32  ][TRACE   ][1341] ReqChannel send crypt load={'cmd': '_master_opts'}
2023-05-03 08:04:36,857 [salt.state       :767 ][DEBUG   ][1341] Gathering pillar data for state run
2023-05-03 08:04:36,857 [salt.pillar      :71  ][DEBUG   ][1341] Determining pillar cache
2023-05-03 08:04:36,858 [salt.crypt       :506 ][DEBUG   ][1341] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:36,858 [salt.pillar      :32  ][TRACE   ][1341] ext_pillar_extra_data = {}
2023-05-03 08:04:36,902 [salt.crypt       :208 ][DEBUG   ][1341] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:36,902 [salt.crypt       :900 ][DEBUG   ][1341] Loaded minion key: /etc/salt/pki/minion/minion.pem
2023-05-03 08:04:36,903 [salt.crypt       :255 ][DEBUG   ][1341] salt.crypt.verify_signature: Loading public key
2023-05-03 08:04:36,903 [salt.crypt       :216 ][DEBUG   ][1341] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:36,904 [salt.crypt       :257 ][DEBUG   ][1341] salt.crypt.verify_signature: Verifying signature
2023-05-03 08:04:36,905 [salt.channel.client:313 ][DEBUG   ][1341] Closing AsyncReqChannel instance
2023-05-03 08:04:36,905 [salt.state       :782 ][DEBUG   ][1341] Finished gathering pillar data for state run
2023-05-03 08:04:36,905 [salt.state       :1267][INFO    ][1341] Loading fresh modules for state activity
2023-05-03 08:04:36,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:36,923 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,923 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded jinja.render
2023-05-03 08:04:36,924 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,924 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded yaml.render
2023-05-03 08:04:36,926 [salt.channel.client:32  ][TRACE   ][1341] ReqChannel send crypt load={'saltenv': 'base', 'prefix': '', 'cmd': '_file_list'}
2023-05-03 08:04:36,929 [salt.channel.client:32  ][TRACE   ][1341] ReqChannel send crypt load={'path': 'debug/action.sls', 'saltenv': 'base', 'cmd': '_file_hash'}
2023-05-03 08:04:36,931 [salt.channel.client:32  ][TRACE   ][1341] ReqChannel send crypt load={'path': 'debug/action.sls', 'saltenv': 'base', 'cmd': '_file_find'}
2023-05-03 08:04:36,933 [salt.fileclient  :1198][DEBUG   ][1341] In saltenv 'base', looking at rel_path 'debug/action.sls' to resolve 'salt://debug/action.sls'
2023-05-03 08:04:36,933 [salt.fileclient  :1207][DEBUG   ][1341] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/debug/action.sls' to resolve 'salt://debug/action.sls'
2023-05-03 08:04:36,933 [salt.template    :53  ][DEBUG   ][1341] compile template: /var/cache/salt/minion/files/base/debug/action.sls
2023-05-03 08:04:36,934 [salt.utils.jinja :93  ][DEBUG   ][1341] Jinja search path: ['/var/cache/salt/minion/files/base']
2023-05-03 08:04:36,938 [salt.crypt       :506 ][DEBUG   ][1341] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'salt3006-minion', 'tcp://192.168.122.254:4506')
2023-05-03 08:04:36,940 [salt.channel.client:313 ][DEBUG   ][1341] Closing AsyncReqChannel instance
2023-05-03 08:04:36,941 [salt.template    :23  ][PROFILE ][1341] Time (in seconds) to render '/var/cache/salt/minion/files/base/debug/action.sls' using 'jinja' renderer: 0.007099151611328125
2023-05-03 08:04:36,941 [salt.template    :116 ][DEBUG   ][1341] Rendered data from file: /var/cache/salt/minion/files/base/debug/action.sls:
/tmp/test.txt:
  file.append:
    - text: |
        salt3006-minion -- Wednesday May 03 2023 08:04:36

2023-05-03 08:04:36,941 [salt.template    :23  ][PROFILE ][1341] Time (in seconds) to render '/var/cache/salt/minion/files/base/debug/action.sls' using 'yaml' renderer: 0.00046706199645996094
2023-05-03 08:04:36,942 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'config' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,942 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded config.option
2023-05-03 08:04:36,943 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'file' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,943 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded file.append
2023-05-03 08:04:36,943 [salt.state       :2257][INFO    ][1341] Running state [/tmp/test.txt] at time 08:04:36.943357
2023-05-03 08:04:36,943 [salt.state       :2288][INFO    ][1341] Executing state file.append for [/tmp/test.txt]
2023-05-03 08:04:36,946 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'file' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,946 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded file.search
2023-05-03 08:04:36,947 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'files' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,947 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded files.is_text
2023-05-03 08:04:36,948 [salt.state       :323 ][INFO    ][1341] File changed:
---

+++

@@ -2,3 +2,4 @@

 salt3006-minion -- Wednesday May 03 2023 08:03:40
 salt3006-minion -- Wednesday May 03 2023 08:04:11
 salt3006-minion -- Wednesday May 03 2023 08:04:27
+salt3006-minion -- Wednesday May 03 2023 08:04:36
2023-05-03 08:04:36,948 [salt.state       :2458][INFO    ][1341] Completed state [/tmp/test.txt] at time 08:04:36.948530 (duration_in_ms=5.174)
2023-05-03 08:04:36,948 [salt.state       :3528][DEBUG   ][1341] File /var/cache/salt/minion/accumulator/140195380753984 does not exist, no need to cleanup
2023-05-03 08:04:36,948 [salt.channel.client:313 ][DEBUG   ][1341] Closing AsyncReqChannel instance
2023-05-03 08:04:36,949 [salt.loader.lazy :964 ][DEBUG   ][1341] The functions from module 'state' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,949 [salt.utils.lazy  :99  ][DEBUG   ][1341] LazyLoaded state.check_result
2023-05-03 08:04:36,949 [salt.minion      :2192][INFO    ][1341] Returning information for job: 20230503080436786612
2023-05-03 08:04:36,949 [salt.minion      :32  ][TRACE   ][1341] Return data: {'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -2,3 +2,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n salt3006-minion -- Wednesday May 03 2023 08:04:27\n+salt3006-minion -- Wednesday May 03 2023 08:04:36'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:36.943356', 'duration': 5.174, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080436786612', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}]}
2023-05-03 08:04:36,950 [salt.utils.event :315 ][DEBUG   ][1341] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_6432538fe7_pub.ipc
2023-05-03 08:04:36,950 [salt.utils.event :316 ][DEBUG   ][1341] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:36,950 [salt.transport.ipc:32  ][TRACE   ][1341] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:36,950 [salt.transport.ipc:32  ][TRACE   ][1085] IPCServer: Handling connection to address: <socket.socket fd=55, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_6432538fe7_pull.ipc>
2023-05-03 08:04:36,951 [salt.utils.event :823 ][DEBUG   ][1341] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -2,3 +2,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n salt3006-minion -- Wednesday May 03 2023 08:04:27\n+salt3006-minion -- Wednesday May 03 2023 08:04:36'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:36.943356', 'duration': 5.174, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080436786612', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:36.951411'}
2023-05-03 08:04:36,952 [salt.minion      :2692][DEBUG   ][1085] Minion of '192.168.122.254' is handling event tag '__master_req_channel_payload'
2023-05-03 08:04:36,952 [salt.minion      :890 ][DEBUG   ][1085] Minion return retry timer set to 9 seconds (randomized)
2023-05-03 08:04:36,952 [salt.channel.client:32  ][TRACE   ][1085] ReqChannel send crypt load={'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -2,3 +2,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n salt3006-minion -- Wednesday May 03 2023 08:04:27\n+salt3006-minion -- Wednesday May 03 2023 08:04:36'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:36.943356', 'duration': 5.174, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080436786612', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:36.951411'}
2023-05-03 08:04:36,953 [salt.transport.ipc:373 ][DEBUG   ][1341] Closing IPCMessageClient instance
2023-05-03 08:04:36,953 [salt.minion      :32  ][TRACE   ][1341] ret_val = True
2023-05-03 08:04:36,953 [salt.transport.ipc:32  ][TRACE   ][1085] Client disconnected from IPC /var/run/salt/minion/minion_event_6432538fe7_pull.ipc
2023-05-03 08:04:36,953 [salt.minion      :2061][DEBUG   ][1341] minion return: {'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -2,3 +2,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n salt3006-minion -- Wednesday May 03 2023 08:04:27\n+salt3006-minion -- Wednesday May 03 2023 08:04:36'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:36.943356', 'duration': 5.174, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080436786612', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}]}
2023-05-03 08:04:37,912 [salt.utils.schedule:32  ][TRACE   ][1085] ==== evaluating schedule now None =====
2023-05-03 08:04:37,912 [salt.utils.process:1156][DEBUG   ][1085] Subprocess ProcessPayload(jid=20230503080436786612) cleaned up

Master


2023-05-03 08:04:27,529 [salt.loaded.int.log_handlers.fluent_mod:32  ][TRACE   ][2830] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
2023-05-03 08:04:27,530 [salt.loaded.int.log_handlers.logstash_mod:32  ][TRACE   ][2830] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
2023-05-03 08:04:27,530 [salt.loader.lazy :32  ][TRACE   ][2830] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
2023-05-03 08:04:27,531 [salt.utils.parsers:222 ][DEBUG   ][2830] Configuration file path: /etc/salt/master
2023-05-03 08:04:27,531 [salt.config      :2013][DEBUG   ][2830] Reading configuration from /etc/salt/master
2023-05-03 08:04:27,566 [salt.config      :2135][DEBUG   ][2830] Missing configuration file: /root/.saltrc
2023-05-03 08:04:27,567 [salt.utils.event :315 ][DEBUG   ][2830] MasterEvent PUB socket URI: /var/run/salt/master/master_event_pub.ipc
2023-05-03 08:04:27,567 [salt.utils.event :316 ][DEBUG   ][2830] MasterEvent PULL socket URI: /var/run/salt/master/master_event_pull.ipc
2023-05-03 08:04:27,578 [salt.transport.ipc:32  ][TRACE   ][2830] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pub.ipc
2023-05-03 08:04:27,579 [salt.transport.ipc:32  ][TRACE   ][1847] IPCServer: Handling connection to address:
2023-05-03 08:04:27,579 [salt.channel.client:32  ][TRACE   ][2830] ReqChannel send clear load={'cmd': 'publish', 'tgt': 'salt3006-minion', 'fun': 'state.apply', 'arg': ['debug.send'], 'key': 'mn9AzrE4cDfhFKD7JrtId65naoxtulVnTqIiCjubmANLRDmlUvD61NV4DaJ4hJCxJXiWG1WOGI0=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'show_timeout': True, 'show_jid': False, 'delimiter': ':'}, 'user': 'root'}
2023-05-03 08:04:27,580 [salt.master      :32  ][TRACE   ][1856] Clear payload received with command publish
2023-05-03 08:04:27,580 [salt.utils.event :823 ][DEBUG   ][1856] Sending event: tag = 20230503080427580663; data = {'minions': ['salt3006-minion'], '_stamp': '2023-05-03T08:04:27.580904'}
2023-05-03 08:04:27,581 [salt.utils.event :823 ][DEBUG   ][1856] Sending event: tag = salt/job/20230503080427580663/new; data = {'jid': '20230503080427580663', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'root', 'fun': 'state.apply', 'arg': ['debug.send'], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:27.581613'}
2023-05-03 08:04:27,582 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'minions': ['salt3006-minion'], '_stamp': '2023-05-03T08:04:27.580904'}, 'tag': '20230503080427580663'}
2023-05-03 08:04:27,582 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag 20230503080427580663
2023-05-03 08:04:27,582 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,582 [salt.loaded.int.returner.local_cache:237 ][DEBUG   ][1856] Adding minions for job 20230503080427580663: ['salt3006-minion']
2023-05-03 08:04:27,582 [salt.master      :2511][INFO    ][1856] User root Published command state.apply with jid 20230503080427580663
2023-05-03 08:04:27,582 [salt.master      :2522][DEBUG   ][1856] Published command details {'fun': 'state.apply', 'arg': ['debug.send'], 'tgt': 'salt3006-minion', 'jid': '20230503080427580663', 'ret': '', 'tgt_type': 'glob', 'user': 'root'}
2023-05-03 08:04:27,582 [salt.channel.server:895 ][DEBUG   ][1856] Sending payload to publish daemon. jid=20230503080427580663 load={'fun': 'state.apply', 'arg': ['debug.se
2023-05-03 08:04:27,583 [salt.transport.zeromq:881 ][DEBUG   ][1856] Sent payload to publish daemon.
2023-05-03 08:04:27,583 [salt.channel.server:867 ][DEBUG   ][1846] Signing data packet
2023-05-03 08:04:27,583 [salt.crypt       :208 ][DEBUG   ][1846] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:27,583 [salt.crypt       :239 ][DEBUG   ][1846] salt.crypt.sign_message: Signing message.
2023-05-03 08:04:27,583 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'jid': '20230503080427580663', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'root', 'fun': 'state.apply', 'arg': ['debug.send'], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:27.581613'}, 'tag': 'salt/job/20230503080427580663/new'}
2023-05-03 08:04:27,584 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag salt/job/20230503080427580663/new
2023-05-03 08:04:27,584 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,585 [salt.transport.zeromq:32  ][TRACE   ][1846] Sending ZMQ-unfiltered data over publisher tcp://0.0.0.0:4505
2023-05-03 08:04:27,585 [salt.transport.zeromq:32  ][TRACE   ][1846] Unfiltered data has been sent
2023-05-03 08:04:27,585 [salt.channel.client:313 ][DEBUG   ][2830] Closing AsyncReqChannel instance
2023-05-03 08:04:27,586 [salt.client      :32  ][TRACE   ][2830] func get_cli_event_returns()
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'base64_encode' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'base64_decode' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'md5' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'sha1' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'sha256' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'sha512' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'hmac' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'hmac_compute' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'random_hash' as a jinja filter
2023-05-03 08:04:27,594 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'rand_str' as a jinja filter
2023-05-03 08:04:27,595 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'file_hashsum' as a jinja filter
2023-05-03 08:04:27,636 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'http_query' as a jinja filter
2023-05-03 08:04:27,638 [salt.utils.decorators.jinja:74  ][DEBUG   ][2830] Marking 'ifelse' as a jinja global
2023-05-03 08:04:27,639 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'strftime' as a jinja filter
2023-05-03 08:04:27,639 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'date_format' as a jinja filter
2023-05-03 08:04:27,641 [salt.utils.decorators.jinja:74  ][DEBUG   ][2830] Marking 'raise' as a jinja global
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:50  ][DEBUG   ][2830] Marking 'match' as a jinja test
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:50  ][DEBUG   ][2830] Marking 'equalto' as a jinja test
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'skip' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'sequence' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'to_bool' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'indent' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'tojson' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'quote' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'regex_escape' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'regex_search' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'regex_match' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'regex_replace' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'uuid' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'unique' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'min' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'max' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'avg' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'union' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'intersect' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'difference' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'symmetric_difference' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'method_call' as a jinja filter
2023-05-03 08:04:27,642 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'yaml_dquote' as a jinja filter
2023-05-03 08:04:27,643 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'yaml_squote' as a jinja filter
2023-05-03 08:04:27,643 [salt.utils.decorators.jinja:26  ][DEBUG   ][2830] Marking 'yaml_encode' as a jinja filter
2023-05-03 08:04:27,649 [salt.utils.json  :32  ][TRACE   ][2830] loaded json json lib
2023-05-03 08:04:27,650 [salt.loader.lazy :964 ][DEBUG   ][2830] The functions from module 'local_cache' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,650 [salt.utils.lazy  :99  ][DEBUG   ][2830] LazyLoaded local_cache.get_load
2023-05-03 08:04:27,650 [salt.loaded.int.returner.local_cache:307 ][DEBUG   ][2830] Reading minion list from /var/cache/salt/master/jobs/36/2a740d90e3131e6b99b6f1570fcb0bf2630db3ed6b3dac10cc97d99a900ca3/.minions.p
2023-05-03 08:04:27,650 [salt.client      :1181][DEBUG   ][2830] get_iter_returns for jid 20230503080427580663 sent to {'salt3006-minion'} will timeout at 08:04:32.650782
2023-05-03 08:04:27,650 [salt.utils.event :32  ][TRACE   ][2830] Get event. tag: salt/job/20230503080427580663
2023-05-03 08:04:27,651 [salt.utils.event :32  ][TRACE   ][2830] _get_event() waited 0 seconds and received nothing
2023-05-03 08:04:27,658 [salt.master      :32  ][TRACE   ][1858] AES payload received with command _master_opts
2023-05-03 08:04:27,659 [salt.master      :32  ][TRACE   ][1858] Master function call _master_opts took 0.00018477439880371094 seconds
2023-05-03 08:04:27,661 [salt.utils.event :32  ][TRACE   ][2830] Get event. tag: salt/job/20230503080427580663
2023-05-03 08:04:27,662 [salt.utils.event :32  ][TRACE   ][2830] get_event() received = {'data': {'jid': '20230503080427580663', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'root', 'fun': 'state.apply', 'arg': ['debug.send'], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:27.581613'}, 'tag': 'salt/job/20230503080427580663/new'}
2023-05-03 08:04:27,662 [salt.master      :32  ][TRACE   ][1854] AES payload received with command _pillar
2023-05-03 08:04:27,663 [salt.pillar      :71  ][DEBUG   ][1854] Determining pillar cache
2023-05-03 08:04:27,662 [salt.utils.event :32  ][TRACE   ][2830] Get event. tag: salt/job/20230503080427580663
2023-05-03 08:04:27,677 [salt.loader.lazy :964 ][DEBUG   ][1854] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,677 [salt.utils.lazy  :99  ][DEBUG   ][1854] LazyLoaded jinja.render
2023-05-03 08:04:27,678 [salt.loader.lazy :964 ][DEBUG   ][1854] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,678 [salt.utils.lazy  :99  ][DEBUG   ][1854] LazyLoaded yaml.render
2023-05-03 08:04:27,682 [salt.utils.event :823 ][DEBUG   ][1854] Sending event: tag = minion/refresh/salt3006-minion; data = {'Minion data cache refresh': 'salt3006-minion', '_stamp': '2023-05-03T08:04:27.682400'}
2023-05-03 08:04:27,683 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'Minion data cache refresh': 'salt3006-minion', '_stamp': '2023-05-03T08:04:27.682400'}, 'tag': 'minion/refresh/salt3006-minion'}
2023-05-03 08:04:27,683 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag minion/refresh/salt3006-minion
2023-05-03 08:04:27,683 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,683 [salt.utils.event :32  ][TRACE   ][2830] _get_event() waited 0 seconds and received nothing
2023-05-03 08:04:27,683 [salt.master      :32  ][TRACE   ][1854] Master function call _pillar took 0.020741939544677734 seconds
2023-05-03 08:04:27,683 [salt.crypt       :216 ][DEBUG   ][1854] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:27,684 [salt.crypt       :208 ][DEBUG   ][1854] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:27,684 [salt.crypt       :239 ][DEBUG   ][1854] salt.crypt.sign_message: Signing message.
2023-05-03 08:04:27,693 [salt.utils.event :32  ][TRACE   ][2830] Get event. tag: salt/job/20230503080427580663
2023-05-03 08:04:27,715 [salt.master      :32  ][TRACE   ][1855] AES payload received with command _file_list
2023-05-03 08:04:27,715 [salt.fileserver  :32  ][TRACE   ][1855] Lockfile /var/cache/salt/master/file_lists/roots/.base.w created
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: Processing /srv/salt/debug
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug is not a link
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug relative path is debug
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: Processing /srv/salt/debug/reactor.sls
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug/reactor.sls is not a link
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug/reactor.sls relative path is debug/reactor.sls
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: Processing /srv/salt/debug/send.sls
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug/send.sls is not a link
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug/send.sls relative path is debug/send.sls
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: Processing /srv/salt/debug/action.sls
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug/action.sls is not a link
2023-05-03 08:04:27,715 [salt.loaded.int.fileserver.roots:32  ][TRACE   ][1855] roots: /srv/salt/debug/action.sls relative path is debug/action.sls
2023-05-03 08:04:27,716 [salt.fileserver  :32  ][TRACE   ][1855] Lockfile /var/cache/salt/master/file_lists/roots/.base.w removed
2023-05-03 08:04:27,716 [salt.master      :32  ][TRACE   ][1855] Master function call _file_list took 0.0010569095611572266 seconds
2023-05-03 08:04:27,719 [salt.master      :32  ][TRACE   ][1857] AES payload received with command _file_hash
2023-05-03 08:04:27,719 [salt.master      :32  ][TRACE   ][1857] Master function call _file_hash took 0.00016045570373535156 seconds
2023-05-03 08:04:27,721 [salt.master      :32  ][TRACE   ][1856] AES payload received with command _file_find
2023-05-03 08:04:27,721 [salt.master      :32  ][TRACE   ][1856] Master function call _file_find took 0.00011396408081054688 seconds
2023-05-03 08:04:27,739 [salt.master      :32  ][TRACE   ][1858] AES payload received with command _minion_event
2023-05-03 08:04:27,740 [salt.crypt       :216 ][DEBUG   ][1858] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:27,740 [salt.utils.event :823 ][DEBUG   ][1858] Sending event: tag = debug/test; data = {'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:27.740912'}
2023-05-03 08:04:27,741 [salt.utils.event :32  ][TRACE   ][2830] _get_event() waited 0 seconds and received nothing
2023-05-03 08:04:27,742 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:27.740912'}, 'tag': 'debug/test'}
2023-05-03 08:04:27,742 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag debug/test
2023-05-03 08:04:27,742 [salt.utils.reactor:173 ][DEBUG   ][1850] Compiling reactions for tag debug/test
2023-05-03 08:04:27,742 [salt.master      :32  ][TRACE   ][1854] AES payload received with command _return
2023-05-03 08:04:27,742 [salt.loader.lazy :964 ][DEBUG   ][1854] The functions from module 'local_cache' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,743 [salt.utils.lazy  :99  ][DEBUG   ][1854] LazyLoaded local_cache.prep_jid
2023-05-03 08:04:27,743 [salt.utils.job   :86  ][INFO    ][1854] Got return from salt3006-minion for job 20230503080427580663
2023-05-03 08:04:27,743 [salt.utils.event :823 ][DEBUG   ][1854] Sending event: tag = salt/job/20230503080427580663/ret/salt3006-minion; data = {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send'], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.743285'}
2023-05-03 08:04:27,744 [salt.master      :32  ][TRACE   ][1854] Master function call _return took 0.001691579818725586 seconds
2023-05-03 08:04:27,741 [salt.master      :32  ][TRACE   ][1858] Master function call _minion_event took 0.0017104148864746094 seconds
2023-05-03 08:04:27,752 [salt.utils.event :32  ][TRACE   ][2830] Get event. tag: salt/job/20230503080427580663
2023-05-03 08:04:27,752 [salt.utils.event :32  ][TRACE   ][2830] get_event() received = {'data': {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send'], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.743285'}, 'tag': 'salt/job/20230503080427580663/ret/salt3006-minion'}
2023-05-03 08:04:27,752 [salt.client      :1221][DEBUG   ][2830] jid 20230503080427580663 return from salt3006-minion
2023-05-03 08:04:27,752 [salt.client      :1663][DEBUG   ][2830] return event: {'salt3006-minion': {'ret': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'out': 'highstate', 'retcode': 0, 'jid': '20230503080427580663'}}
2023-05-03 08:04:27,754 [salt.loader.lazy :964 ][DEBUG   ][2830] The functions from module 'highstate' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,754 [salt.utils.lazy  :99  ][DEBUG   ][2830] LazyLoaded highstate.output
2023-05-03 08:04:27,754 [salt.loader.lazy :964 ][DEBUG   ][1850] The functions from module 'roots' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,754 [salt.utils.lazy  :99  ][DEBUG   ][1850] LazyLoaded roots.envs
2023-05-03 08:04:27,755 [salt.loader.lazy :964 ][DEBUG   ][2830] The functions from module 'nested' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,755 [salt.utils.lazy  :99  ][DEBUG   ][2830] LazyLoaded nested.output
2023-05-03 08:04:27,755 [salt.output      :32  ][TRACE   ][2830] data = {'salt3006-minion': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': '4.5 ms', '__id__': 'debug/test'}}}
2023-05-03 08:04:27,756 [salt.utils.event :32  ][TRACE   ][2830] Get event. tag: salt/job/20230503080427580663
2023-05-03 08:04:27,765 [salt.loader.lazy :964 ][DEBUG   ][1850] The functions from module 's3fs' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,769 [salt.utils.lazy  :102 ][DEBUG   ][1850] Could not LazyLoad roots.init: 'roots.init' is not available.
2023-05-03 08:04:27,770 [salt.fileclient  :1198][DEBUG   ][1850] In saltenv 'base', looking at rel_path 'debug/reactor.sls' to resolve 'salt://debug/reactor.sls'
2023-05-03 08:04:27,770 [salt.fileclient  :1207][DEBUG   ][1850] In saltenv 'base', ** considering ** path '/var/cache/salt/master/files/base/debug/reactor.sls' to resolve 'salt://debug/reactor.sls'
2023-05-03 08:04:27,770 [salt.template    :53  ][DEBUG   ][1850] compile template: /var/cache/salt/master/files/base/debug/reactor.sls
2023-05-03 08:04:27,770 [salt.utils.jinja :93  ][DEBUG   ][1850] Jinja search path: ['/var/cache/salt/master/files/base']
2023-05-03 08:04:27,771 [salt.template    :23  ][PROFILE ][1850] Time (in seconds) to render '/var/cache/salt/master/files/base/debug/reactor.sls' using 'jinja' renderer: 0.0009057521820068359
2023-05-03 08:04:27,771 [salt.template    :116 ][DEBUG   ][1850] Rendered data from file: /var/cache/salt/master/files/base/debug/reactor.sls:
execute_state:
  local.state.apply:
    - tgt: salt3006-minion
    - args:
      - mods: debug.action
      - queue: True
      - pillar:
          minion:
            id: salt3006-minion
            moreinfo: 'abc'

2023-05-03 08:04:27,772 [salt.template    :23  ][PROFILE ][1850] Time (in seconds) to render '/var/cache/salt/master/files/base/debug/reactor.sls' using 'yaml' renderer: 0.0009772777557373047
2023-05-03 08:04:27,773 [salt.channel.client:32  ][TRACE   ][1850] ReqChannel send clear load={'cmd': 'publish', 'tgt': 'salt3006-minion', 'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': OrderedDict([('minion', OrderedDict([('id', 'salt3006-minion'), ('moreinfo', 'abc')]))])}], 'key': 'mn9AzrE4cDfhFKD7JrtId65naoxtulVnTqIiCjubmANLRDmlUvD61NV4DaJ4hJCxJXiWG1WOGI0=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'state': 'local', 'name': 'execute_state', '__sls__': '/var/cache/salt/master/files/base/debug/reactor.sls', '__id__': 'execute_state', 'order': 1}, 'user': 'salt'}
2023-05-03 08:04:27,774 [salt.master      :32  ][TRACE   ][1855] Clear payload received with command publish
2023-05-03 08:04:27,775 [salt.utils.event :823 ][DEBUG   ][1855] Sending event: tag = 20230503080427775179; data = {'minions': ['salt3006-minion'], '_stamp': '2023-05-03T08:04:27.775408'}
2023-05-03 08:04:27,776 [salt.utils.event :32  ][TRACE   ][2830] _get_event() waited 0 seconds and received nothing
2023-05-03 08:04:27,776 [salt.client      :1230][DEBUG   ][2830] jid 20230503080427580663 found all minions {'salt3006-minion'}
2023-05-03 08:04:27,776 [salt.transport.ipc:373 ][DEBUG   ][2830] Closing IPCMessageSubscriber instance
2023-05-03 08:04:27,780 [salt.utils.event :823 ][DEBUG   ][1855] Sending event: tag = salt/job/20230503080427775179/new; data = {'jid': '20230503080427775179', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'salt', 'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:27.780169'}
2023-05-03 08:04:27,781 [salt.loaded.int.returner.local_cache:237 ][DEBUG   ][1855] Adding minions for job 20230503080427775179: ['salt3006-minion']
2023-05-03 08:04:27,781 [salt.master      :2511][INFO    ][1855] User salt Published command state.apply with jid 20230503080427775179
2023-05-03 08:04:27,781 [salt.master      :2522][DEBUG   ][1855] Published command details {'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'tgt': 'salt3006-minion', 'jid': '20230503080427775179', 'ret': '', 'tgt_type': 'glob', 'user': 'salt'}
2023-05-03 08:04:27,781 [salt.channel.server:895 ][DEBUG   ][1855] Sending payload to publish daemon. jid=20230503080427775179 load={'fun': 'state.apply', 'arg': [{'__kwarg
2023-05-03 08:04:27,781 [salt.transport.zeromq:881 ][DEBUG   ][1855] Sent payload to publish daemon.
2023-05-03 08:04:27,782 [salt.channel.server:867 ][DEBUG   ][1846] Signing data packet
2023-05-03 08:04:27,782 [salt.crypt       :208 ][DEBUG   ][1846] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:27,782 [salt.crypt       :239 ][DEBUG   ][1846] salt.crypt.sign_message: Signing message.
2023-05-03 08:04:27,783 [salt.transport.zeromq:32  ][TRACE   ][1846] Sending ZMQ-unfiltered data over publisher tcp://0.0.0.0:4505
2023-05-03 08:04:27,784 [salt.channel.client:313 ][DEBUG   ][1850] Closing AsyncReqChannel instance
2023-05-03 08:04:27,784 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,784 [salt.transport.zeromq:32  ][TRACE   ][1846] Unfiltered data has been sent
2023-05-03 08:04:27,785 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'event_|-debug/test_|-debug/test_|-send': {'name': 'debug/test', 'changes': {'tag': 'debug/test', 'data': None}, 'result': True, 'comment': 'Event fired', '__sls__': 'debug.send', '__run_num__': 0, 'start_time': '08:04:27.732372', 'duration': 4.5, '__id__': 'debug/test'}}, 'retcode': 0, 'jid': '20230503080427580663', 'fun': 'state.apply', 'fun_args': ['debug.send'], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.743285'}, 'tag': 'salt/job/20230503080427580663/ret/salt3006-minion'}
2023-05-03 08:04:27,785 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag salt/job/20230503080427580663/ret/salt3006-minion
2023-05-03 08:04:27,785 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,786 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'minions': ['salt3006-minion'], '_stamp': '2023-05-03T08:04:27.775408'}, 'tag': '20230503080427775179'}
2023-05-03 08:04:27,786 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag 20230503080427775179
2023-05-03 08:04:27,786 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,786 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'jid': '20230503080427775179', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'salt', 'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:27.780169'}, 'tag': 'salt/job/20230503080427775179/new'}
2023-05-03 08:04:27,786 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag salt/job/20230503080427775179/new
2023-05-03 08:04:27,786 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,866 [salt.master      :32  ][TRACE   ][1857] AES payload received with command _master_opts
2023-05-03 08:04:27,866 [salt.master      :32  ][TRACE   ][1857] Master function call _master_opts took 0.0001971721649169922 seconds
2023-05-03 08:04:27,870 [salt.master      :32  ][TRACE   ][1856] AES payload received with command _pillar
2023-05-03 08:04:27,870 [salt.pillar      :71  ][DEBUG   ][1856] Determining pillar cache
2023-05-03 08:04:27,885 [salt.loader.lazy :964 ][DEBUG   ][1856] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,885 [salt.utils.lazy  :99  ][DEBUG   ][1856] LazyLoaded jinja.render
2023-05-03 08:04:27,885 [salt.loader.lazy :964 ][DEBUG   ][1856] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:27,885 [salt.utils.lazy  :99  ][DEBUG   ][1856] LazyLoaded yaml.render
2023-05-03 08:04:27,890 [salt.utils.event :823 ][DEBUG   ][1856] Sending event: tag = minion/refresh/salt3006-minion; data = {'Minion data cache refresh': 'salt3006-minion', '_stamp': '2023-05-03T08:04:27.890847'}
2023-05-03 08:04:27,891 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'Minion data cache refresh': 'salt3006-minion', '_stamp': '2023-05-03T08:04:27.890847'}, 'tag': 'minion/refresh/salt3006-minion'}
2023-05-03 08:04:27,891 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag minion/refresh/salt3006-minion
2023-05-03 08:04:27,891 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:27,892 [salt.master      :32  ][TRACE   ][1856] Master function call _pillar took 0.021938323974609375 seconds
2023-05-03 08:04:27,892 [salt.crypt       :216 ][DEBUG   ][1856] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:27,893 [salt.crypt       :208 ][DEBUG   ][1856] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:27,893 [salt.crypt       :239 ][DEBUG   ][1856] salt.crypt.sign_message: Signing message.
2023-05-03 08:04:27,923 [salt.master      :32  ][TRACE   ][1858] AES payload received with command _file_list
2023-05-03 08:04:27,923 [salt.fileserver  :145 ][DEBUG   ][1858] Returning file list from cache: age=0 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2023-05-03 08:04:27,923 [salt.master      :32  ][TRACE   ][1858] Master function call _file_list took 0.0002753734588623047 seconds
2023-05-03 08:04:27,926 [salt.master      :32  ][TRACE   ][1854] AES payload received with command _file_hash
2023-05-03 08:04:27,926 [salt.master      :32  ][TRACE   ][1854] Master function call _file_hash took 0.00024056434631347656 seconds
2023-05-03 08:04:27,929 [salt.master      :32  ][TRACE   ][1855] AES payload received with command _file_find
2023-05-03 08:04:27,929 [salt.master      :32  ][TRACE   ][1855] Master function call _file_find took 0.00012230873107910156 seconds
2023-05-03 08:04:27,950 [salt.master      :32  ][TRACE   ][1857] AES payload received with command _return
2023-05-03 08:04:27,951 [salt.utils.job   :86  ][INFO    ][1857] Got return from salt3006-minion for job 20230503080427775179
2023-05-03 08:04:27,951 [salt.utils.event :823 ][DEBUG   ][1857] Sending event: tag = salt/job/20230503080427775179/ret/salt3006-minion; data = {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -1,3 +1,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:02:55\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n+salt3006-minion -- Wednesday May 03 2023 08:04:27'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:27.941705', 'duration': 5.078, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080427775179', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.951436'}
2023-05-03 08:04:27,952 [salt.master      :32  ][TRACE   ][1857] Master function call _return took 0.0014846324920654297 seconds
2023-05-03 08:04:27,953 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -1,3 +1,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:02:55\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n+salt3006-minion -- Wednesday May 03 2023 08:04:27'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:27.941705', 'duration': 5.078, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080427775179', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:27.951436'}, 'tag': 'salt/job/20230503080427775179/ret/salt3006-minion'}
2023-05-03 08:04:27,953 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag salt/job/20230503080427775179/ret/salt3006-minion
2023-05-03 08:04:27,953 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:30,422 [salt.utils.process:32  ][TRACE   ][1852] Process manager iteration
2023-05-03 08:04:30,428 [salt.utils.process:32  ][TRACE   ][1793] Process manager iteration
2023-05-03 08:04:32,954 [salt.utils.event :32  ][TRACE   ][1850] _get_event() waited 5 seconds and received nothing
2023-05-03 08:04:32,955 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:36,743 [salt.master      :32  ][TRACE   ][1856] AES payload received with command _minion_event
2023-05-03 08:04:36,744 [salt.crypt       :216 ][DEBUG   ][1856] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:36,748 [salt.transport.ipc:32  ][TRACE   ][1856] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc
2023-05-03 08:04:36,749 [salt.transport.ipc:32  ][TRACE   ][1847] IPCServer: Handling connection to address: <socket.socket fd=45, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/master/master_event_pull.ipc>
2023-05-03 08:04:36,749 [salt.utils.event :823 ][DEBUG   ][1856] Sending event: tag = debug/test; data = {'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:36.749284'}
2023-05-03 08:04:36,750 [salt.master      :32  ][TRACE   ][1856] Master function call _minion_event took 0.006474018096923828 seconds
2023-05-03 08:04:36,751 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'id': 'salt3006-minion', 'cmd': '_minion_event', 'pretag': None, 'data': {}, 'tag': 'debug/test', '_stamp': '2023-05-03T08:04:36.749284'}, 'tag': 'debug/test'}
2023-05-03 08:04:36,751 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag debug/test
2023-05-03 08:04:36,751 [salt.utils.reactor:173 ][DEBUG   ][1850] Compiling reactions for tag debug/test
2023-05-03 08:04:36,768 [salt.loader.lazy :964 ][DEBUG   ][1850] The functions from module 'roots' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,769 [salt.utils.lazy  :99  ][DEBUG   ][1850] LazyLoaded roots.envs
2023-05-03 08:04:36,778 [salt.loader.lazy :964 ][DEBUG   ][1850] The functions from module 's3fs' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,781 [salt.utils.lazy  :102 ][DEBUG   ][1850] Could not LazyLoad roots.init: 'roots.init' is not available.
2023-05-03 08:04:36,782 [salt.fileclient  :1198][DEBUG   ][1850] In saltenv 'base', looking at rel_path 'debug/reactor.sls' to resolve 'salt://debug/reactor.sls'
2023-05-03 08:04:36,782 [salt.fileclient  :1207][DEBUG   ][1850] In saltenv 'base', ** considering ** path '/var/cache/salt/master/files/base/debug/reactor.sls' to resolve 'salt://debug/reactor.sls'
2023-05-03 08:04:36,782 [salt.template    :53  ][DEBUG   ][1850] compile template: /var/cache/salt/master/files/base/debug/reactor.sls
2023-05-03 08:04:36,782 [salt.utils.jinja :93  ][DEBUG   ][1850] Jinja search path: ['/var/cache/salt/master/files/base']
2023-05-03 08:04:36,783 [salt.template    :23  ][PROFILE ][1850] Time (in seconds) to render '/var/cache/salt/master/files/base/debug/reactor.sls' using 'jinja' renderer: 0.0007870197296142578
2023-05-03 08:04:36,783 [salt.template    :116 ][DEBUG   ][1850] Rendered data from file: /var/cache/salt/master/files/base/debug/reactor.sls:
execute_state:
  local.state.apply:
    - tgt: salt3006-minion
    - args:
      - mods: debug.action
      - queue: True
      - pillar:
          minion:
            id: salt3006-minion
            moreinfo: 'abc'

2023-05-03 08:04:36,784 [salt.template    :23  ][PROFILE ][1850] Time (in seconds) to render '/var/cache/salt/master/files/base/debug/reactor.sls' using 'yaml' renderer: 0.0008487701416015625
2023-05-03 08:04:36,784 [salt.channel.client:32  ][TRACE   ][1850] ReqChannel send clear load={'cmd': 'publish', 'tgt': 'salt3006-minion', 'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': OrderedDict([('minion', OrderedDict([('id', 'salt3006-minion'), ('moreinfo', 'abc')]))])}], 'key': 'mn9AzrE4cDfhFKD7JrtId65naoxtulVnTqIiCjubmANLRDmlUvD61NV4DaJ4hJCxJXiWG1WOGI0=', 'tgt_type': 'glob', 'ret': '', 'jid': '', 'kwargs': {'state': 'local', 'name': 'execute_state', '__sls__': '/var/cache/salt/master/files/base/debug/reactor.sls', '__id__': 'execute_state', 'order': 1}, 'user': 'salt'}
2023-05-03 08:04:36,785 [salt.master      :32  ][TRACE   ][1858] Clear payload received with command publish
2023-05-03 08:04:36,786 [salt.loader.lazy :964 ][DEBUG   ][1858] The functions from module 'local_cache' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,786 [salt.utils.lazy  :99  ][DEBUG   ][1858] LazyLoaded local_cache.prep_jid
2023-05-03 08:04:36,787 [salt.transport.ipc:32  ][TRACE   ][1858] IPCClient: Connecting to socket: /var/run/salt/master/master_event_pull.ipc
2023-05-03 08:04:36,787 [salt.transport.ipc:32  ][TRACE   ][1847] IPCServer: Handling connection to address: <socket.socket fd=46, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/master/master_event_pull.ipc>
2023-05-03 08:04:36,787 [salt.utils.event :823 ][DEBUG   ][1858] Sending event: tag = 20230503080436786612; data = {'minions': ['salt3006-minion'], '_stamp': '2023-05-03T08:04:36.787546'}
2023-05-03 08:04:36,788 [salt.utils.event :823 ][DEBUG   ][1858] Sending event: tag = salt/job/20230503080436786612/new; data = {'jid': '20230503080436786612', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'salt', 'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:36.788016'}
2023-05-03 08:04:36,788 [salt.loaded.int.returner.local_cache:237 ][DEBUG   ][1858] Adding minions for job 20230503080436786612: ['salt3006-minion']
2023-05-03 08:04:36,788 [salt.master      :2511][INFO    ][1858] User salt Published command state.apply with jid 20230503080436786612
2023-05-03 08:04:36,788 [salt.master      :2522][DEBUG   ][1858] Published command details {'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'tgt': 'salt3006-minion', 'jid': '20230503080436786612', 'ret': '', 'tgt_type': 'glob', 'user': 'salt'}
2023-05-03 08:04:36,788 [salt.channel.server:895 ][DEBUG   ][1858] Sending payload to publish daemon. jid=20230503080436786612 load={'fun': 'state.apply', 'arg': [{'__kwarg
2023-05-03 08:04:36,788 [salt.transport.zeromq:857 ][DEBUG   ][1858] Connecting to pub server: ipc:///var/run/salt/master/publish_pull.ipc
2023-05-03 08:04:36,788 [salt.transport.zeromq:881 ][DEBUG   ][1858] Sent payload to publish daemon.
2023-05-03 08:04:36,789 [salt.channel.server:867 ][DEBUG   ][1846] Signing data packet
2023-05-03 08:04:36,789 [salt.crypt       :208 ][DEBUG   ][1846] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:36,789 [salt.crypt       :239 ][DEBUG   ][1846] salt.crypt.sign_message: Signing message.
2023-05-03 08:04:36,790 [salt.transport.zeromq:32  ][TRACE   ][1846] Sending ZMQ-unfiltered data over publisher tcp://0.0.0.0:4505
2023-05-03 08:04:36,791 [salt.transport.zeromq:32  ][TRACE   ][1846] Unfiltered data has been sent
2023-05-03 08:04:36,791 [salt.channel.client:313 ][DEBUG   ][1850] Closing AsyncReqChannel instance
2023-05-03 08:04:36,791 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:36,792 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'minions': ['salt3006-minion'], '_stamp': '2023-05-03T08:04:36.787546'}, 'tag': '20230503080436786612'}
2023-05-03 08:04:36,792 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag 20230503080436786612
2023-05-03 08:04:36,792 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:36,792 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'jid': '20230503080436786612', 'tgt_type': 'glob', 'tgt': 'salt3006-minion', 'user': 'salt', 'fun': 'state.apply', 'arg': [{'__kwarg__': True, 'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'minions': ['salt3006-minion'], 'missing': [], '_stamp': '2023-05-03T08:04:36.788016'}, 'tag': 'salt/job/20230503080436786612/new'}
2023-05-03 08:04:36,792 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag salt/job/20230503080436786612/new
2023-05-03 08:04:36,792 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:36,854 [salt.master      :32  ][TRACE   ][1854] AES payload received with command _master_opts
2023-05-03 08:04:36,855 [salt.master      :32  ][TRACE   ][1854] Master function call _master_opts took 0.0002162456512451172 seconds
2023-05-03 08:04:36,858 [salt.master      :32  ][TRACE   ][1855] AES payload received with command _pillar
2023-05-03 08:04:36,858 [salt.pillar      :71  ][DEBUG   ][1855] Determining pillar cache
2023-05-03 08:04:36,875 [salt.loader.lazy :964 ][DEBUG   ][1855] The functions from module 'jinja' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,875 [salt.utils.lazy  :99  ][DEBUG   ][1855] LazyLoaded jinja.render
2023-05-03 08:04:36,876 [salt.loader.lazy :964 ][DEBUG   ][1855] The functions from module 'yaml' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,876 [salt.utils.lazy  :99  ][DEBUG   ][1855] LazyLoaded yaml.render
2023-05-03 08:04:36,891 [salt.loader.lazy :964 ][DEBUG   ][1855] The functions from module 's3fs' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,895 [salt.loader.lazy :964 ][DEBUG   ][1855] The functions from module 'localfs' are being loaded by dir() on the loaded module
2023-05-03 08:04:36,895 [salt.utils.lazy  :99  ][DEBUG   ][1855] LazyLoaded localfs.init_kwargs
2023-05-03 08:04:36,896 [salt.utils.event :823 ][DEBUG   ][1855] Sending event: tag = minion/refresh/salt3006-minion; data = {'Minion data cache refresh': 'salt3006-minion', '_stamp': '2023-05-03T08:04:36.896265'}
2023-05-03 08:04:36,897 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'Minion data cache refresh': 'salt3006-minion', '_stamp': '2023-05-03T08:04:36.896265'}, 'tag': 'minion/refresh/salt3006-minion'}
2023-05-03 08:04:36,897 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag minion/refresh/salt3006-minion
2023-05-03 08:04:36,897 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:36,897 [salt.master      :32  ][TRACE   ][1855] Master function call _pillar took 0.038455963134765625 seconds
2023-05-03 08:04:36,897 [salt.crypt       :216 ][DEBUG   ][1855] salt.crypt.get_rsa_pub_key: Loading public key
2023-05-03 08:04:36,898 [salt.crypt       :208 ][DEBUG   ][1855] salt.crypt.get_rsa_key: Loading private key
2023-05-03 08:04:36,898 [salt.crypt       :239 ][DEBUG   ][1855] salt.crypt.sign_message: Signing message.
2023-05-03 08:04:36,926 [salt.master      :32  ][TRACE   ][1857] AES payload received with command _file_list
2023-05-03 08:04:36,926 [salt.fileserver  :145 ][DEBUG   ][1857] Returning file list from cache: age=9 cache_time=20 /var/cache/salt/master/file_lists/roots/base.p
2023-05-03 08:04:36,926 [salt.master      :32  ][TRACE   ][1857] Master function call _file_list took 0.0003657341003417969 seconds
2023-05-03 08:04:36,928 [salt.master      :32  ][TRACE   ][1856] AES payload received with command _file_hash
2023-05-03 08:04:36,929 [salt.master      :32  ][TRACE   ][1856] Master function call _file_hash took 0.00016450881958007812 seconds
2023-05-03 08:04:36,931 [salt.master      :32  ][TRACE   ][1858] AES payload received with command _file_find
2023-05-03 08:04:36,931 [salt.master      :32  ][TRACE   ][1858] Master function call _file_find took 7.843971252441406e-05 seconds
2023-05-03 08:04:36,952 [salt.master      :32  ][TRACE   ][1854] AES payload received with command _return
2023-05-03 08:04:36,952 [salt.utils.job   :86  ][INFO    ][1854] Got return from salt3006-minion for job 20230503080436786612
2023-05-03 08:04:36,953 [salt.utils.event :823 ][DEBUG   ][1854] Sending event: tag = salt/job/20230503080436786612/ret/salt3006-minion; data = {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -2,3 +2,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n salt3006-minion -- Wednesday May 03 2023 08:04:27\n+salt3006-minion -- Wednesday May 03 2023 08:04:36'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:36.943356', 'duration': 5.174, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080436786612', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:36.953102'}
2023-05-03 08:04:36,953 [salt.utils.event :32  ][TRACE   ][1850] get_event() received = {'data': {'cmd': '_return', 'id': 'salt3006-minion', 'success': True, 'return': {'file_|-/tmp/test.txt_|-/tmp/test.txt_|-append': {'name': '/tmp/test.txt', 'changes': {'diff': '--- \n\n+++ \n\n@@ -2,3 +2,4 @@\n\n salt3006-minion -- Wednesday May 03 2023 08:03:40\n salt3006-minion -- Wednesday May 03 2023 08:04:11\n salt3006-minion -- Wednesday May 03 2023 08:04:27\n+salt3006-minion -- Wednesday May 03 2023 08:04:36'}, 'result': True, 'comment': 'Appended 1 lines', '__sls__': 'debug.action', '__run_num__': 0, 'start_time': '08:04:36.943356', 'duration': 5.174, '__id__': '/tmp/test.txt'}}, 'retcode': 0, 'jid': '20230503080436786612', 'fun': 'state.apply', 'fun_args': [{'mods': 'debug.action', 'queue': True, 'pillar': {'minion': {'id': 'salt3006-minion', 'moreinfo': 'abc'}}}], 'out': 'highstate', '_stamp': '2023-05-03T08:04:36.953102'}, 'tag': 'salt/job/20230503080436786612/ret/salt3006-minion'}
2023-05-03 08:04:36,954 [salt.utils.reactor:85  ][DEBUG   ][1850] Gathering reactors for tag salt/job/20230503080436786612/ret/salt3006-minion
2023-05-03 08:04:36,954 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:
2023-05-03 08:04:36,954 [salt.master      :32  ][TRACE   ][1854] Master function call _return took 0.0020537376403808594 seconds
2023-05-03 08:04:40,387 [salt.master      :481 ][DEBUG   ][1865] Performing fileserver updates for items with an update interval of 60
2023-05-03 08:04:40,387 [salt.master      :463 ][DEBUG   ][1865] Updating roots fileserver cache
2023-05-03 08:04:40,388 [salt.master      :486 ][DEBUG   ][1865] Completed fileserver updates for items with an update interval of 60, waiting 60 seconds
2023-05-03 08:04:40,424 [salt.utils.process:32  ][TRACE   ][1852] Process manager iteration
2023-05-03 08:04:40,438 [salt.utils.process:32  ][TRACE   ][1793] Process manager iteration
2023-05-03 08:04:41,148 [salt.master      :32  ][TRACE   ][1851] Running maintenance routines
2023-05-03 08:04:41,148 [salt.config      :2013][DEBUG   ][1851] Reading configuration from /etc/salt/master
2023-05-03 08:04:41,180 [salt.config      :3621][DEBUG   ][1851] Guessing ID. The id can be explicitly set in /etc/salt/minion
2023-05-03 08:04:41,183 [salt.config      :3647][DEBUG   ][1851] Found minion id from generate_minion_id(): salt3006-master
2023-05-03 08:04:41,183 [salt.loader      :1073][DEBUG   ][1851] Grains refresh requested. Refreshing grains.
2023-05-03 08:04:41,183 [salt.config      :2013][DEBUG   ][1851] Reading configuration from /etc/salt/master
2023-05-03 08:04:41,222 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'core' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,223 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'disks' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,223 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'extra' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,224 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'lvm' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,224 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'mdadm' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,225 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'minion_process' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,225 [salt.loader.lazy :32  ][TRACE   ][1851] Error loading grains.napalm: "napalm"" (/opt/saltstack/salt/lib/python3.10/site-packages/salt/grains/napalm.py) cannot be loaded: NAPALM is not installed: ``pip install napalm``
2023-05-03 08:04:41,225 [salt.loader.lazy :32  ][TRACE   ][1851] Error loading grains.nxos: No host specified and no UDS found at /tmp/nginx_local/nginx_1_be_nxapi.sock

2023-05-03 08:04:41,225 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'opts' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,226 [salt.loader.lazy :32  ][TRACE   ][1851] Error loading grains.pending_reboot: 'pending_reboot' grain only available on Windows
2023-05-03 08:04:41,226 [salt.loader.lazy :863 ][DEBUG   ][1851] Override  __utils__: <module 'salt.loaded.int.grains.zfs' from '/opt/saltstack/salt/lib/python3.10/site-packages/salt/grains/zfs.py'>
2023-05-03 08:04:41,226 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'zfs' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,226 [salt.loader      :32  ][TRACE   ][1851] Loading core.append_domain grain
2023-05-03 08:04:41,226 [salt.loader      :32  ][TRACE   ][1851] Loading core.cwd grain
2023-05-03 08:04:41,226 [salt.loader      :32  ][TRACE   ][1851] Loading core.default_gateway grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.dns grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.fqdns grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.get_machine_id grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.get_master grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.get_server_id grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.hostname grain
2023-05-03 08:04:41,229 [salt.loader      :32  ][TRACE   ][1851] Loading core.hwaddr_interfaces grain
2023-05-03 08:04:41,231 [salt.loader      :32  ][TRACE   ][1851] Loading core.id_ grain
2023-05-03 08:04:41,231 [salt.loader      :32  ][TRACE   ][1851] Loading core.ip4_interfaces grain
2023-05-03 08:04:41,231 [salt.loader      :32  ][TRACE   ][1851] Loading core.ip6_interfaces grain
2023-05-03 08:04:41,231 [salt.loader      :32  ][TRACE   ][1851] Loading core.ip_fqdn grain
2023-05-03 08:04:41,234 [salt.loader      :32  ][TRACE   ][1851] Loading core.ip_interfaces grain
2023-05-03 08:04:41,235 [salt.loader      :32  ][TRACE   ][1851] Loading core.kernelparams grain
2023-05-03 08:04:41,235 [salt.loader      :32  ][TRACE   ][1851] Loading core.locale_info grain
2023-05-03 08:04:41,235 [salt.loader      :32  ][TRACE   ][1851] Loading core.os_data grain
2023-05-03 08:04:41,237 [salt.loaded.int.grains.core:32  ][TRACE   ][1851] Adding systemd grains
2023-05-03 08:04:41,238 [salt.loaded.int.grains.core:32  ][TRACE   ][1851] Adding init grain
2023-05-03 08:04:41,238 [salt.loaded.int.grains.core:32  ][TRACE   ][1851] Getting lsb_release distro information
2023-05-03 08:04:41,239 [salt.loaded.int.grains.core:32  ][TRACE   ][1851] lsb_release python bindings not available
2023-05-03 08:04:41,239 [salt.loaded.int.grains.core:32  ][TRACE   ][1851] Attempting to parse /etc/lsb-release
2023-05-03 08:04:41,239 [salt.loaded.int.grains.core:32  ][TRACE   ][1851] Getting OS name, release, and codename from freedesktop_os_release
2023-05-03 08:04:41,240 [salt.utils.path  :32  ][TRACE   ][1851] 'virt-what' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:41,243 [salt.loader      :32  ][TRACE   ][1851] Loading core.path grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.pythonexecutable grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.pythonpath grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.pythonversion grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.saltpath grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.saltversion grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.saltversioninfo grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading core.zmqversion grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading disks.disks grain
2023-05-03 08:04:41,244 [salt.loaded.int.grains.disks:32  ][TRACE   ][1851] Device vda reports itself as an HDD
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading extra.config grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading extra.shell grain
2023-05-03 08:04:41,244 [salt.loader      :32  ][TRACE   ][1851] Loading extra.transactional grain
2023-05-03 08:04:41,245 [salt.utils.path  :32  ][TRACE   ][1851] 'transactional-update' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:41,245 [salt.loader      :32  ][TRACE   ][1851] Loading extra.uefi grain
2023-05-03 08:04:41,245 [salt.loader      :32  ][TRACE   ][1851] Loading lvm.lvm grain
2023-05-03 08:04:41,249 [salt.loader      :32  ][TRACE   ][1851] Loading mdadm.mdadm grain
2023-05-03 08:04:41,249 [salt.loader      :32  ][TRACE   ][1851] Loading minion_process.grains grain
2023-05-03 08:04:41,249 [salt.loader      :32  ][TRACE   ][1851] Loading opts.opts grain
2023-05-03 08:04:41,249 [salt.loader      :32  ][TRACE   ][1851] Loading zfs.zfs grain
2023-05-03 08:04:41,253 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'zfs' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,253 [salt.utils.lazy  :99  ][DEBUG   ][1851] LazyLoaded zfs.is_supported
2023-05-03 08:04:41,253 [salt.utils.path  :32  ][TRACE   ][1851] 'zfs-fuse' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:41,254 [salt.utils.path  :32  ][TRACE   ][1851] 'zpool' could not be found in the following search path: '['/usr/local/sbin', '/usr/local/bin', '/usr/sbin', '/usr/bin', '/sbin', '/bin', '/snap/bin']'
2023-05-03 08:04:41,269 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'local_cache' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,269 [salt.utils.lazy  :99  ][DEBUG   ][1851] LazyLoaded local_cache.clean_old_jobs
2023-05-03 08:04:41,275 [salt.loader.lazy :964 ][DEBUG   ][1851] The functions from module 'localfs' are being loaded by dir() on the loaded module
2023-05-03 08:04:41,275 [salt.utils.lazy  :99  ][DEBUG   ][1851] LazyLoaded localfs.list_tokens
2023-05-03 08:04:41,275 [salt.utils.schedule:32  ][TRACE   ][1851] ==== evaluating schedule now None =====
2023-05-03 08:04:41,275 [salt.utils.verify:426 ][DEBUG   ][1851] This salt-master instance has accepted 1 minion keys.
2023-05-03 08:04:41,960 [salt.utils.event :32  ][TRACE   ][1850] _get_event() waited 5 seconds and received nothing
2023-05-03 08:04:41,960 [salt.utils.event :32  ][TRACE   ][1850] Get event. tag:

Ch3LL · 2023-05-12T15:25:54Z

Thanks for the additional information. This has been set to be fixed in 3006.2.

Any chance you can create a Vagrant file or Dockerfile that will help me replicate this issue when I dive in? If not no worries, I'll see if I can't replicate it using a new Ubuntu 22 VM.

lkubb · 2023-05-22T06:04:35Z

I do see this issue regularly with the updated Vault integration (#62684) and expiry events turned on (https://github.com/lkubb/salt/blob/32f977335765c530c66417a78504fdfde3dbdabd/salt/modules/vault.py#L413-L420):

[TRACE   ] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b'\x06\x05\x90\x80\x02A6?\x91\xd7\xab\xcfx\xc2\xac\x9c\xbf0\xdf\xee3\xa2#\x04\x90E\xd7\xb7\xe0\xc9\xb2\\!h\x93\xd9\xaa\x1b\x1f\x1d+R|\xa4\xf1\x95DV.\xeeU\x97\x0b)\xde\x8bs\x89M\xd7\x848N\xc9\xa0\xfdn\xba\xcdv\xf4\xc96\xc6g\xfa\xf0\x06\r\xec\xeb\xb7\x8bK_\x8f^\xa5\xf7\x8c\x13\xce(\x83H\x9c\x03\xe5e\xe62\xadaD\xb6v\x18\xa5\xf5\x99\n\xbc\\4/\xd0/GB@\xb9\x97\xa4\xbd\xad<XE-$\xdf\xc6\xc0\xf2\x9b\x9e\xea)\xb6\x87q\xb0lx\xbf\x89\xecp\xa3\xcfQ\xa7\xcc\x93\xd0\x02\x08(\x83m\xa0\x85\xfc\x97\x19\x9c\xf1E\xb7\xdc\x96\xbf\x9f\xaa\x1ePX\xe8`\xfbz\x8et\xc7\xee\xacg\x81Fu\rIeq^_\xfe\xb2w\xfc\xef\xdb&\xb5*\xea9D\x01f\xb0\x96\xcfr~\x94\xc3%\xb8\xb5<rR\x06R4e\x19\x93XB\x0fY\xdc;\xe2nq\x93\xebt\xe9;\xa2\xe8\xbe\xeeC>r\x08\xe8G\x9b?\xd1', 'data': {}, 'tag': 'vault/cache/connection/clear', '_stamp': '2023-05-22T05:37:02.914165'}
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_434ac36d17_pull.ipc
[TRACE   ] IPCServer: Handling connection to address: <socket.socket fd=53, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_434ac36d17_pull.ipc>
[DEBUG   ] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'myminion', 'success': True, 'return': True, 'retcode': 0, 'jid': '20230522053702727283', 'fun': 'vault.clear_cache', 'fun_args': [], '_stamp': '2023-05-22T05:37:02.918932'}
[DEBUG   ] Minion of 'mymaster' is handling event tag '__master_req_channel_payload'
[DEBUG   ] Minion return retry timer set to 7 seconds (randomized)
[TRACE   ] ReqChannel send crypt load={'cmd': '_return', 'id': 'myminion', 'success': True, 'return': True, 'retcode': 0, 'jid': '20230522053702727283', 'fun': 'vault.clear_cache', 'fun_args': [], '_stamp': '2023-05-22T05:37:02.918932'}
[DEBUG   ] Closing IPCMessageClient instance
[TRACE   ] ret_val = True
[DEBUG   ] minion return: {'success': True, 'return': True, 'retcode': 0, 'jid': '20230522053702727283', 'fun': 'vault.clear_cache', 'fun_args': []}
[TRACE   ] Client disconnected from IPC /var/run/salt/minion/minion_event_434ac36d17_pull.ipc
[DEBUG   ] Subprocess ProcessPayload(jid=20230522053702727283) cleaned up
[TRACE   ] Process manager iteration
[TRACE   ] Failed to send msg SaltReqTimeoutError('Message timed out')
[TRACE   ] ReqChannel send crypt load={'id': 'myminion', 'cmd': '_minion_event', 'pretag': None, 'tok': b'\x06\x05\x90\x80\x02A6?\x91\xd7\xab\xcfx\xc2\xac\x9c\xbf0\xdf\xee3\xa2#\x04\x90E\xd7\xb7\xe0\xc9\xb2\\!h\x93\xd9\xaa\x1b\x1f\x1d+R|\xa4\xf1\x95DV.\xeeU\x97\x0b)\xde\x8bs\x89M\xd7\x848N\xc9\xa0\xfdn\xba\xcdv\xf4\xc96\xc6g\xfa\xf0\x06\r\xec\xeb\xb7\x8bK_\x8f^\xa5\xf7\x8c\x13\xce(\x83H\x9c\x03\xe5e\xe62\xadaD\xb6v\x18\xa5\xf5\x99\n\xbc\\4/\xd0/GB@\xb9\x97\xa4\xbd\xad<XE-$\xdf\xc6\xc0\xf2\x9b\x9e\xea)\xb6\x87q\xb0lx\xbf\x89\xecp\xa3\xcfQ\xa7\xcc\x93\xd0\x02\x08(\x83m\xa0\x85\xfc\x97\x19\x9c\xf1E\xb7\xdc\x96\xbf\x9f\xaa\x1ePX\xe8`\xfbz\x8et\xc7\xee\xacg\x81Fu\rIeq^_\xfe\xb2w\xfc\xef\xdb&\xb5*\xea9D\x01f\xb0\x96\xcfr~\x94\xc3%\xb8\xb5<rR\x06R4e\x19\x93XB\x0fY\xdc;\xe2nq\x93\xebt\xe9;\xa2\xe8\xbe\xeeC>r\x08\xe8G\x9b?\xd1', 'data': {}, 'tag': 'vault/cache/connection/clear', '_stamp': '2023-05-22T05:37:02.914165', 'nonce': 'c97f8b1510414c6285d780fe14ec39f0'}

In this case, the events are received exactly at 7 seconds apart, matching Minion return retry timer set to 7 seconds (randomized):

There will likely be a much easier way to reproduce this behavior, but for the record, this happens every time I run salt myminion vault.clear_cache from the master. It does not happen using salt-call vault.clear_cache on the minion.

This is on v3006.1 (all daemons).

Edit: I have a reactor for this event putting some strain on the master, but removing it still exhibits the same behavior.

gluf-technik · 2023-07-04T10:00:40Z

Hi,
just a short note: I got a lot of those messages from/for my minions running 3005:

2023-07-04 11:39:17,413 [salt.loaded.int.returner.local_cache:148 ][ERROR   ][996151] An extra return was detected from minion deb11-kvm-minion, please verify the minion, this could be a replay attack

Those already running v3006.1 (FreeBSD 13, Alpine 318) and the OpenBSD ones (7.2, 7.3) stuck on 3003.5 did not cause such errors. When I update a Debian 11/12 or Ubuntu 22.04 to Salt 3006.1 using the "latest" repos instead of the 3005 one the messages for those minions I've updated stop.

Oh, right, in case it somehow matters: The master is running 3006.1 on Debian 11.

vzhestkov · 2023-07-24T12:40:13Z

Not sure if it related or not, but I have 2 or 3 cases of An extra return was detected from minion {}, please verify the minion, this could be a replay attack if I try to run for i in {1..5}; do salt ${MINION_ID} grains.items > /dev/null & done. There was no such issue with 3004.

vzhestkov · 2023-07-31T13:04:28Z

I have tried to revert the following commits:

And now it seems works as before for me. But as it's not a fix by itself, it's better to ensure with @devkits how to fix the issue.

Ch3LL · 2023-08-22T18:20:10Z

I am able to replicate this on the head of 3006.x with the original submitter test case, but it looks to be fixed on the head of master. Can anyone confirm this as well?

Ch3LL · 2023-08-23T16:27:44Z

I'm going to go ahead and close this, but let me know if I need to re-open if anyone confirms that its not fixed on master.

OrangeDog · 2023-08-23T16:48:07Z

So it's not going to be fixed in 3006, despite that being an LTS release and this being a regression?

Ch3LL · 2023-08-23T17:04:08Z

I have not been able to successfully bisect the issue to determine which code to cherry pick. I can try a few more times and try to look at the git log around that code to see if we can't narrow it down as well.

Ch3LL · 2023-08-25T15:03:46Z

I still have not been able to narrow down the fix, so this will be included in 3007.0.

…sc#1213257) This reverts commits: saltstack/salt@a99ffb5 saltstack/salt@80ae518 saltstack/salt@3c7e1ec saltstack/salt@171926c From this PR: saltstack/salt#61468 See: saltstack/salt#62959 (comment)

…sc#1213257) * Revert usage of long running REQ channel (bsc#1213960, bsc#1213630, bsc#1213257) This reverts commits: saltstack/salt@a99ffb5 saltstack/salt@80ae518 saltstack/salt@3c7e1ec saltstack/salt@171926c From this PR: saltstack/salt#61468 See: saltstack/salt#62959 (comment) * Revert "Fix linter" This reverts commit d09d2d3. * Revert "add a regression test" This reverts commit b2c32be. * Fix failing tests after reverting commits

supfors added Bug broken, incorrect, or confusing behavior needs-triage labels Oct 26, 2022

OrangeDog added the info-needed waiting for more info label Oct 26, 2022

OrangeDog added Regression The issue is a bug that breaks functionality known to work in previous releases. Phosphorus v3005.0 Release code name and version and removed info-needed waiting for more info labels Oct 26, 2022

anilsil assigned Ch3LL Apr 18, 2023

anilsil added this to the Sulfur v3006.1 milestone Apr 18, 2023

anilsil modified the milestones: Sulfur v3006.1, Sulfur v3006.2 May 1, 2023

OrangeDog mentioned this issue May 3, 2023

salt.loaded.int.returner.local_cache:147 An extra return was detected from minion . #64205

Open

Ch3LL closed this as completed Aug 23, 2023

OrangeDog modified the milestones: Sulfur v3006.2, Chlorine v3007.0 Aug 23, 2023

meaksh mentioned this issue Aug 31, 2023

Revert usage of long running REQ channel (bsc#1213960, bsc#1213630, bsc#1213257) openSUSE/salt#600

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] Minion sending duplicate events #62959

[BUG] Minion sending duplicate events #62959

supfors commented Oct 26, 2022

OrangeDog commented Oct 26, 2022

supfors commented Oct 26, 2022

OrangeDog commented Oct 26, 2022

supfors commented Oct 27, 2022

twangboy commented Apr 28, 2023

s0undt3ch commented Apr 29, 2023

supfors commented May 3, 2023

Ch3LL commented May 12, 2023

lkubb commented May 22, 2023 •

edited

gluf-technik commented Jul 4, 2023

vzhestkov commented Jul 24, 2023

vzhestkov commented Jul 31, 2023

Ch3LL commented Aug 22, 2023

Ch3LL commented Aug 23, 2023

OrangeDog commented Aug 23, 2023

Ch3LL commented Aug 23, 2023

Ch3LL commented Aug 25, 2023

[BUG] Minion sending duplicate events #62959

[BUG] Minion sending duplicate events #62959

Comments

supfors commented Oct 26, 2022

OrangeDog commented Oct 26, 2022

supfors commented Oct 26, 2022

OrangeDog commented Oct 26, 2022

supfors commented Oct 27, 2022

twangboy commented Apr 28, 2023

s0undt3ch commented Apr 29, 2023

supfors commented May 3, 2023

Ch3LL commented May 12, 2023

lkubb commented May 22, 2023 • edited

gluf-technik commented Jul 4, 2023

vzhestkov commented Jul 24, 2023

vzhestkov commented Jul 31, 2023

Ch3LL commented Aug 22, 2023

Ch3LL commented Aug 23, 2023

OrangeDog commented Aug 23, 2023

Ch3LL commented Aug 23, 2023

Ch3LL commented Aug 25, 2023

lkubb commented May 22, 2023 •

edited