[BUG] Minion sends duplicate /start event (3006.1, 3006.4) #66341

amalaguti · 2024-04-10T13:19:07Z

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.

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

amalaguti · 2024-04-11T13:26:47Z

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

amalaguti · 2024-05-09T18:55:49Z

It seems fixed in 3006.8, I no longer see multiple /start events

amalaguti · 2024-09-27T22:37:56Z

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"
}

amalaguti added Bug broken, incorrect, or confusing behavior needs-triage labels Apr 10, 2024

amalaguti mentioned this issue Apr 19, 2024

[BUG] Master shows duplicate minion IDs after being offline for a couple of hours #66406

Open

amalaguti mentioned this issue Sep 30, 2024

[BUG] 3006.x / 3007.x Windows minion throws duplicate custom event in multimaster config #66933

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] Minion sends duplicate /start event (3006.1, 3006.4) #66341

[BUG] Minion sends duplicate /start event (3006.1, 3006.4) #66341

amalaguti commented Apr 10, 2024 •

edited

Loading

amalaguti commented Apr 11, 2024

amalaguti commented May 9, 2024

amalaguti commented Sep 27, 2024 •

edited

Loading

[BUG] Minion sends duplicate /start event (3006.1, 3006.4) #66341

[BUG] Minion sends duplicate /start event (3006.1, 3006.4) #66341

Comments

amalaguti commented Apr 10, 2024 • edited Loading

amalaguti commented Apr 11, 2024

amalaguti commented May 9, 2024

amalaguti commented Sep 27, 2024 • edited Loading

amalaguti commented Apr 10, 2024 •

edited

Loading

amalaguti commented Sep 27, 2024 •

edited

Loading