salt
salt copied to clipboard
saltstack
[BUG] Minion sends duplicate /start event (3006.1, 3006.4)
Description at least seen in Windows minion 3006.1 and 3006.4, and 3006.7, if the minion is set with a multimaster list with N masters, it sends duplicate N /start event when it starts, as per the numbers of masters in the list to the same master
For instance, the minion is set with two masters, both masters receives two /start events, which cause anomalies like reactor being triggered for each event
# MINION 3006.1 / 3006.4 (two start events in the minion log)
[DEBUG ] SaltEvent PUB socket URI: 4510
[DEBUG ] SaltEvent PULL socket URI: 4511
[DEBUG ] Sending event: tag = __master_req_channel_payload; data = {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'tok': b'\x19\x94rQG\xa1\xe2"\xc3(z\x90\xa6yV\xcfE\xf5+\x8e\x9e\xb1T\xf5N8+\xd5\xc9&d\xf8\xc0\x85\x8e*$.:L\xd2G\xc3U\n\xea\xd8\xad\xf2}S\xa9]]\xb5\x86\xebCM\xae\x86\xd40\xec\xbaX\x16\x812!\xe3>\xec\xcd\xceq\xd4\x95\xb4\xfbG!\x8f-\xa8]9#\xb7\x08\xcac\xae\xd7\xe6*.\xf5\xca\xa0\xd3\xeaO\xb4\x19\x1a7\xcc DB\x8d\xeaN\x00\x8b\x98C\xccc\xa3\xbc\xf4>\xe0\xad A@\x1fp\xab7\xd8\xfb\xc2\xd1\x1c\xbf\x9a\x03K\xc8&\xb5\'CtR\x14\xedX\xe7\x0fZ\xdar\x02\xe0bK<\xff$\x8b\xecEJ\x15\xc4\xb5\xd5h\x12|a=;\x98\xba\xb9\xf7\xed\xfal\xcf\x1e\xa1x%w\xea\xe0\xb2\xb6\xe5@\x93\x83\x90h_\xb0\x94\x9e{2\xe9""\x84\xc5S_,\xb5i\xb5j,\xe4\x04a\xbe\x9f\xfe4\xac\xff\xe8\x07-R\xdbX\xf7\xdc;\x92;\xd6\xe6\x0f#]\xddeuA\xceJh\xfd\xb1\x85\x04', 'data': 'Minion minion-win-1 started at Wed Apr 10 12:48:56 2024', 'tag': 'minion_start', '_stamp': '2024-04-10T12:48:56.674818'}
[DEBUG ] Closing IPCMessageClient instance
[DEBUG ] SaltEvent PUB socket URI: 4510
[DEBUG ] SaltEvent PULL socket URI: 4511
[DEBUG ] Sending event: tag = __master_req_channel_payload; data = {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'tok': b'\x19\x94rQG\xa1\xe2"\xc3(z\x90\xa6yV\xcfE\xf5+\x8e\x9e\xb1T\xf5N8+\xd5\xc9&d\xf8\xc0\x85\x8e*$.:L\xd2G\xc3U\n\xea\xd8\xad\xf2}S\xa9]]\xb5\x86\xebCM\xae\x86\xd40\xec\xbaX\x16\x812!\xe3>\xec\xcd\xceq\xd4\x95\xb4\xfbG!\x8f-\xa8]9#\xb7\x08\xcac\xae\xd7\xe6*.\xf5\xca\xa0\xd3\xeaO\xb4\x19\x1a7\xcc DB\x8d\xeaN\x00\x8b\x98C\xccc\xa3\xbc\xf4>\xe0\xad A@\x1fp\xab7\xd8\xfb\xc2\xd1\x1c\xbf\x9a\x03K\xc8&\xb5\'CtR\x14\xedX\xe7\x0fZ\xdar\x02\xe0bK<\xff$\x8b\xecEJ\x15\xc4\xb5\xd5h\x12|a=;\x98\xba\xb9\xf7\xed\xfal\xcf\x1e\xa1x%w\xea\xe0\xb2\xb6\xe5@\x93\x83\x90h_\xb0\x94\x9e{2\xe9""\x84\xc5S_,\xb5i\xb5j,\xe4\x04a\xbe\x9f\xfe4\xac\xff\xe8\x07-R\xdbX\xf7\xdc;\x92;\xd6\xe6\x0f#]\xddeuA\xceJh\xfd\xb1\x85\x04', 'data': 'Minion minion-win-1 started at Wed Apr 10 12:48:56 2024', 'tag': 'salt/minion/minion-win-1/start', '_stamp': '2024-04-10T12:48:56.674818'}
[DEBUG ] Closing IPCMessageClient instance
[INFO ] Minion is ready to receive requests!
# Master receives two events
[DEBUG ] Sending event: tag = salt/minion/minion-win-1/start; data = {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'data': 'Minion minion-win-1 started at Wed Apr 10 12:48:56 2024', 'tag': 'salt/minion/minion-win-1/start', '_stamp': '2024-04-10T12:48:56.901377'}
[DEBUG ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG ] Sending event: tag = salt/minion/minion-win-1/start; data = {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'data': 'Minion minion-win-1 started at Wed Apr 10 12:48:56 2024', 'tag': 'salt/minion/minion-win-1/start', '_stamp': '2024-04-10T12:48:56.979531'}
[saltwinqa@saltmaster-pip 3006.7]$ salt-run state.event pretty=true tagmatch='salt/minion/*/start'
salt/minion/minion-win-1/start {
"_stamp": "2024-04-10T12:48:56.901377",
"cmd": "_minion_event",
"data": "Minion minion-win-1 started at Wed Apr 10 12:48:56 2024",
"id": "minion-win-1",
"pretag": null,
"tag": "salt/minion/minion-win-1/start"
}
salt/minion/minion-win-1/start {
"_stamp": "2024-04-10T12:48:56.979531",
"cmd": "_minion_event",
"data": "Minion minion-win-1 started at Wed Apr 10 12:48:56 2024",
"id": "minion-win-1",
"pretag": null,
"tag": "salt/minion/minion-win-1/start"
}
Setup Windows minions 3006.1, 3006.4 The master version seems to be irrelevant. Does not happen with 3006.6 and 3006.7 minions
Please be as specific as possible and give set-up details.
- [ ] on-prem machine
- [ ] VM (Virtualbox, KVM, etc. please specify)
- [ ] VM running on a cloud service, please be explicit and add details
- [ ] container (Kubernetes, Docker, containerd, etc. please specify)
- [ ] or a combination, please be explicit
- [ ] jails if it is FreeBSD
- [ ] classic packaging
- [ ] onedir packaging
- [ ] used bootstrap to install
Steps to Reproduce the behavior (Include debug logs if possible and relevant)
Expected behavior A clear and concise description of what you expected to happen.
Screenshots If applicable, add screenshots to help explain your problem.
Versions Report
salt --versions-report
(Provided by running salt --versions-report. Please also mention any differences in master/minion versions.)PASTE HERE
Additional context Add any other context about the problem here.
spent quite a good time adventuring into the the minion and master communication code… just to verify the behavior but unable to find the cause, I added a bunch of INFO logging lines along the process in the minion and master just to see the minion creating a minion object for each master defined in the master list, but apparently sending only 1 start event in theory to each master. I guess it’s the master as received of the event which produces two events on the event bus ? (not sure if this is the right way of describing it) This morning completely removed and re installed the minion, started fresh, just to see the same. At least is replicable in my 3006.1 environment
PS C:\Users\adrian> salt-minion -l info
12:48:17,160 [salt.cli.daemons:281][INFO][3604] Setting up the Salt Minion "minion-win-1"
12:48:17,379 [salt.cli.daemons:83][INFO][3604] Starting up the Salt Minion
12:48:17,379 [salt.utils.event:1133][INFO][3604] Starting pull socket on 4511
12:48:17,379 [salt.minion1106][INFO][3604] >>>> ADRIAN connecting to master 1 - 172.21.0.10
12:48:17,379 [salt.minion1113][INFO[3604] >>>> ADRIAN _create_minion_object for 1 - 172.21.0.10
12:48:17,379 [salt.minion1074][INFO][3604] >>>> ADRIAN _create_minion_object
12:48:18,725 [salt.minion:1293][INFO][3604] Creating minion process manager
12:48:18,741 [salt.minion:1106][INFO][3604] >>>> ADRIAN connecting to master 2 - 172.21.0.11
12:48:18,741 [salt.minion:1113][INFO][3604] >>>> ADRIAN _create_minion_object for 2 - 172.21.0.11
12:48:18,741 [salt.minion:1074][INFO][3604] >>>> ADRIAN _create_minion_object
12:48:19,272 [salt.minion:1293][INFO][3604] Creating minion process manager
12:48:19,319 [salt.minion:1137][INFO][3604] >>>> ADRIAN running schedule before connect
12:48:19,460 [salt.minion:1137][INFO][3604] >>>> ADRIAN running schedule before connect
12:48:19,585 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = __master_connected; data = {'master': '172.21.0.10', '_stamp': '2024-04-11T12:48:19.585451'}
12:48:19,632 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = __master_connected; data = {'master': '172.21.0.11', '_stamp': '2024-04-11T12:48:19.632324'}
12:48:20,372 [salt.loader.172.21.0.10.int.module.cmdmod:438][INFO][3604] Executing command tzutil in directory 'C:\Users\adrian'
12:48:20,606 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {'complete': True, 'schedule': {'__mine_interval': {...
12:48:20,622 [salt.utils.schedule:::411][INFO][3604] Updating job settings for scheduled job: __mine_interval
12:48:20,622 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_add_complete; data = {'complete': True, 'schedule': {'__mine_interval': {'function': 'mine.update', ...
12:48:20,639 [salt.minion:1459][INFO][3604] Added mine.update to scheduler
12:48:20,639 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {'complete': True, 'schedule': {'__mine_interval': {'function': 'mine.update', ...
12:48:20,639 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {'complete': True, 'schedule': {'__mine_interval': {'function': 'mine.update', ...
12:48:20,653 [salt.minion:1142][INFO][3604] >>>> ADRIAN running _connect_minion count 0
12:48:20,653 [salt.minion:2655][INFO][3604] Minion is starting as user 'minion-win-1\adrian'
12:48:20,653 [salt.minion:3099][INFO][3604] >>>> ADRIAN 1 Minion 'minion-win-1' trying to tune in
12:48:20,653 [salt.minion:3108][INFO][3604] >>>> ADRIAN _fire_minion_start 1: connected True start False
12:48:20,653 [salt.minion:2416][INFO][3604] >>>> ADRIAN Firing start event to master 172.21.0.10
12:48:20,653 [salt.minion:1681][INFO][3604] >>>> ADRIAN _fire_master None 172.21.0.10 sync: True load: {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'tok': b'V\xdf...', 'data': 'Minion minion-win-1 started at Thu Apr 11 12:48:20 2024', 'tag': 'salt/minion/minion-win-1/start'}
12:48:20,653 [salt.minion:1605][INFO][3604] >>>>> ADRIAN send sync
12:48:20,653 [salt.minion:1617][INFO][3604] >>>>> ADRIAN event fire_event send sync
12:48:20,653 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = __master_req_channel_payload; data = {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'tok': b'V\xdf...', 'data': 'Minion minion-win-1 started at Thu Apr 11 12:48:20 2024', 'tag': 'salt/minion/minion-win-1/start', '_stamp': '2024-04-11T12:48:20.653302'}
12:48:20,684 [salt.minion:3110][INFO][3604] Minion is ready to receive requests!
12:48:21,309 [salt.utils.schedule:::411][INFO][3604] Updating job settings for scheduled job: __mine_interval
12:48:21,309 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_add_complete; data = ...
12:48:21,325 [salt.minion:1459][INFO][3604] Added mine.update to scheduler
12:48:21,325 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {'complete': True, 'schedule': {'__mine_interval': {'function': 'mine.update', ...
12:48:21,340 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = /salt/minion/minion_schedule_delete_complete; data = {'complete': True, 'schedule': {'__mine_interval': {'function': 'mine.update', ...
12:48:21,340 [salt.minion:1142][INFO][3604] >>>> ADRIAN running _connect_minion count 0
12:48:21,356 [salt.minion:2655][INFO][3604] Minion is starting as user 'minion-win-1\adrian'
12:48:21,372 [salt.minion:3099][INFO][3604] >>>> ADRIAN 1 Minion 'minion-win-1' trying to tune in
12:48:21,372 [salt.minion:3108][INFO][3604] >>>> ADRIAN _fire_minion_start 1: connected True start False
12:48:21,372 [salt.minion:2416][INFO][3604] >>>> ADRIAN Firing start event to master 172.21.0.11
12:48:21,372 [salt.minion:1681][INFO][3604] >>>> ADRIAN _fire_master None 172.21.0.11 sync: True load: {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'tok': b'V\xdf...', 'data': 'Minion minion-win-1 started at Thu Apr 11 12:48:21 2024', 'tag': 'salt/minion/minion-win-1/start'}
12:48:21,372 [salt.minion:1605][INFO][3604] >>>>> ADRIAN send sync
12:48:21,372 [salt.minion:1617][INFO][3604] >>>>> ADRIAN event fire_event send sync
12:48:21,372 [salt.utils.event:823][INFO][3604] >>>> Sending event: tag = __master_req_channel_payload; data = {'id': 'minion-win-1', 'cmd': '_minion_event', 'pretag': None, 'tok': b'V\xdf...', 'data': 'Minion minion-win-1 started at Thu Apr 11 12:48:21 2024', 'tag': 'salt/minion/minion-win-1/start', '_stamp': '2024-04-11T12:48:21.372054'}
12:48:21,387 [salt.minion:3110][INFO][3604] Minion is ready to receive requests!
12:48:21,700 [salt.utils.schedule:::1792][INFO][3604] Running scheduled job: __mine_interval with jid 20240411124821700188
IMPORTANT, seems fixed for the /start event, but still an issue for custom events generated from the minion with salt-call configured in multimaster. #66933
You can see below unique /start event but duplicate custom event hello/world (salt-call event.send hello/world from Windows minion)
salt/auth {
"_stamp": "2024-09-27T22:35:12.294711",
"act": "accept",
"id": "minion-win-1",
"pub": "-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAt5l76Z2TNrTeSZJOK7ga\nTUrvQozspW3shL7TYSfGGFJzsY9GD4GBYF9UO68I5/jPYHWh+8se+8QF8mh6y4TQ\nbQU4GN4oSKCAyT8CdwjZnQSpqtgDHenEgI8a4oX1yYPatt/EtGj3MKvMSn5VMVVn\nPnsPzWWS8r25wkwHVDadP2oZrO51fM6niEKbCoXOtgwIp4dzOJMpaZU4Jeu2f+BJ\n3tr5E8W7Q/zJoBEacjlKfrrKwzfS2Ygu9+lefAc4VX5ug9wFgst0W/bmRHa9Ma0L\nNCvzUY0+WFI4qVudsijxOVpvY7nzJTunyCgmfXbJB7968nKHds6g4+xvR7qJ2JPZ\n/wIDAQAB\n-----END PUBLIC KEY-----",
"result": true
}
minion/refresh/minion-win-1 {
"Minion data cache refresh": "minion-win-1",
"_stamp": "2024-09-27T22:35:12.482072"
}
minion_start {
"_stamp": "2024-09-27T22:35:14.175126",
"cmd": "_minion_event",
"data": "Minion minion-win-1 started at Fri Sep 27 22:35:13 2024",
"id": "minion-win-1",
"pretag": null,
"tag": "minion_start"
}
salt/minion/minion-win-1/start {
"_stamp": "2024-09-27T22:35:14.203084",
"cmd": "_minion_event",
"data": "Minion minion-win-1 started at Fri Sep 27 22:35:13 2024",
"id": "minion-win-1",
"pretag": null,
"tag": "salt/minion/minion-win-1/start"
}
salt/auth {
"_stamp": "2024-09-27T22:35:27.398730",
"act": "accept",
"id": "minion-win-1",
"pub": "-----BEGIN PUBLIC KEY-----\nMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAt5l76Z2TNrTeSZJOK7ga\nTUrvQozspW3shL7TYSfGGFJzsY9GD4GBYF9UO68I5/jPYHWh+8se+8QF8mh6y4TQ\nbQU4GN4oSKCAyT8CdwjZnQSpqtgDHenEgI8a4oX1yYPatt/EtGj3MKvMSn5VMVVn\nPnsPzWWS8r25wkwHVDadP2oZrO51fM6niEKbCoXOtgwIp4dzOJMpaZU4Jeu2f+BJ\n3tr5E8W7Q/zJoBEacjlKfrrKwzfS2Ygu9+lefAc4VX5ug9wFgst0W/bmRHa9Ma0L\nNCvzUY0+WFI4qVudsijxOVpvY7nzJTunyCgmfXbJB7968nKHds6g4+xvR7qJ2JPZ\n/wIDAQAB\n-----END PUBLIC KEY-----",
"result": true
}
minion/refresh/minion-win-1 {
"Minion data cache refresh": "minion-win-1",
"_stamp": "2024-09-27T22:35:27.796261"
}
hello/world {
"_stamp": "2024-09-27T22:35:27.964432",
"cmd": "_minion_event",
"data": {
"__pub_fun": "event.send",
"__pub_jid": "20240927223527882312",
"__pub_pid": 3700,
"__pub_tgt": "salt-call"
},
"id": "minion-win-1",
"tag": "hello/world"
}
hello/world {
"_stamp": "2024-09-27T22:35:27.989619",
"cmd": "_minion_event",
"data": {
"__pub_fun": "event.send",
"__pub_jid": "20240927223527882312",
"__pub_pid": 3700,
"__pub_tgt": "salt-call"
},
"id": "minion-win-1",
"tag": "hello/world"
}
salt/job/20240927223528011683/ret/minion-win-1 {
"_stamp": "2024-09-27T22:35:28.012717",
"arg": [
"hello/world"
],
"cmd": "_return",
"fun": "event.send",
"fun_args": [
"hello/world"
],
"id": "minion-win-1",
"jid": "20240927223528011683",
"retcode": 0,
"return": true,
"tgt": "minion-win-1",
"tgt_type": "glob"
}