Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

[BUG] Salt State msteams.post_card 400 Bad request #64973

Closed
8 tasks
haykhovsepyan opened this issue Aug 14, 2023 · 16 comments · Fixed by #65007
Closed
8 tasks

[BUG] Salt State msteams.post_card 400 Bad request #64973

haykhovsepyan opened this issue Aug 14, 2023 · 16 comments · Fixed by #65007
Assignees
Labels
Bug broken, incorrect, or confusing behavior

Comments

@haykhovsepyan
Copy link

Description
after execution msteams.post_card getting ERROR
Failed to send message (400)
using Curl post request to the same hook_url works fine

Setup
send-msteams-message:
msteams.post_card:
- title: Patching Failed
- message: "{{grains["id"]}} Patch State Failed"
- hook_url: {{ pillar['teams']['webhooks']['patching-channel'] }}

salt centos-test-minion pillar.item teams:webhooks:patching-channel

centos-test-minion:
    ----------
    teams:webhooks:patching-channel:
        https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775

Please be as specific as possible and give set-up details.

  • on-prem machine
  • [ X] 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
salt centos-test-minion state.apply os.updates.teams-notification

centos-test-minion:

      ID: send-msteams-message
Function: msteams.post_card
  Result: False
 Comment: Failed to send message (400): send-msteams-message
 Started: 13:56:45.087942
Duration: 1932.238 ms
 Changes:   

curl -X POST -H 'Content-Type: application/json' -d '{"text": "Test"}' https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5

with curl WORKS

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 salt --versions-report Salt Version: Salt: 3006.1

Python Version:
Python: 3.10.11 (main, May 5 2023, 02:31:54) [GCC 11.2.0]

Dependency Versions:
cffi: 1.14.6
cherrypy: unknown
dateutil: 2.8.1
docker-py: Not Installed
gitdb: Not Installed
gitpython: Not Installed
Jinja2: 3.1.2
libgit2: Not Installed
looseversion: 1.0.2
M2Crypto: Not Installed
Mako: Not Installed
msgpack: 1.0.2
msgpack-pure: Not Installed
mysql-python: Not Installed
packaging: 22.0
pycparser: 2.21
pycrypto: Not Installed
pycryptodome: 3.9.8
pygit2: Not Installed
python-gnupg: 0.4.8
PyYAML: 5.4.1
PyZMQ: 23.2.0
relenv: 0.12.3
smmap: Not Installed
timelib: 0.2.4
Tornado: 4.5.3
ZMQ: 4.3.4

System Versions:
dist: rocky 8.7 Green Obsidian
locale: utf-8
machine: x86_64
release: 4.18.0-425.19.2.el8_7.x86_64
system: Linux
version: Rocky Linux 8.7 Green Obsidian

PASTE HERE

Additional context
Add any other context about the problem here.

@haykhovsepyan haykhovsepyan added Bug broken, incorrect, or confusing behavior needs-triage labels Aug 14, 2023
@Ch3LL Ch3LL added this to the Sulfur v3006.4 milestone Aug 14, 2023
@OrangeDog
Copy link
Contributor

Can you add debug logs from the minion when running this state?

@haykhovsepyan
Copy link
Author

Below Minion DEBUG logs:

[DEBUG   ] PubChannel received: {'enc': 'aes', 'load': {'fun': 'state.apply', 'arg': ['os.updates.teams-notification'], 'tgt': 'centos-test-minion', 'jid': '20230815123418021378', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_hayk.hovsepyan'}, 'sig': b"\x1c\x82\x18\x86\xf4\xa4\x91\x8c@\xfe\xfc\xa6\xa1<6\x8dZc\x84\xb3\x0e\xf3\xca\x93/\xb8\x0cUv\x80\xdbhr\xd6\xd0\xd7\x11\x9c=\xf4\x85'\x87Y\xbf\xb5\xc1\xbc\x17 ?\x85Ts\xfc(\xee\xe5,8\t\xe0\xd6YR\x96\xd12du>h\x9c\x1d\xc9\xf9\xf7\xa3T&\xd2(/?E\xdb\x03\x80^\t\xaf1\xa3c\x8e\x99\x08lCa\x1e~)\x8b\xd3\x95\x88{.N\t-;\xda:\xce\x94\xf1U\x12\x97+-3`\xf1v+\x85=\xe4\xfb+kL\xe5\xf4\xb6\x10\x02p\xba\x91{]m\xc8Bz%\xc4$\xc1Ib\t{\xcbT\x1f=\x81c\x92\xae\xeb~\xff\xf2\x85\xbd\xbf\x87\x9bw\xac\x12)QB\x11\xf1\xd1\xa1l\x13\x8cCl\r\x90\xe3!nf\x8cK\xd4\x8b\xc1%\xa0\x19GH\xa3\x0c\xcf\xc2\xa5\xf1\x02\xa0\xd8\xc8i)\xfa:,\xef\x97\xf7\x86\x03P0\xffW\x13\xad\xa7\x8c\x13\xf8\\\xc6\xe7n\x0f\xf6\xac\x8a|\n\xf8\xe6\xab\x13\x82\x1d\xc8\x90\xf0\xcd\x15"}
[DEBUG   ] The functions from module 'glob_match' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded glob_match.match
[INFO    ] User sudo_hayk.hovsepyan Executing command state.apply with jid 20230815123418021378
[DEBUG   ] Command details {'fun': 'state.apply', 'arg': ['os.updates.teams-notification'], 'tgt': 'centos-test-minion', 'jid': '20230815123418021378', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_hayk.hovsepyan'}
[DEBUG   ] Subprocess ProcessPayload(jid=20230815123418021378) added
[DEBUG   ] The functions from module 'jinja' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] The functions from module 'yaml' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded yaml.render
[INFO    ] Starting a new job 20230815123418021378 with PID 235980
[DEBUG   ] The functions from module 'direct_call' are being loaded by dir() on the loaded module
[DEBUG   ] The functions from module 'splay' are being loaded by dir() on the loaded module
[DEBUG   ] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.apply
[DEBUG   ] The functions from module 'config' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] The functions from module 'saltutil' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] Override  __grains__: <module 'salt.loaded.int.module.grains' from '/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/grains.py'>
[DEBUG   ] The functions from module 'grains' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'centos-test-minion', 'tcp://10.130.132.14:4506')
[DEBUG   ] Gathering pillar data for state run
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'centos-test-minion', 'tcp://10.130.132.14:4506')
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] salt.crypt.verify_signature: Loading public key
[DEBUG   ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG   ] salt.crypt.verify_signature: Verifying signature
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] Finished gathering pillar data for state run
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] The functions from module 'jinja' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] The functions from module 'yaml' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded yaml.render
[DEBUG   ] In saltenv 'base', looking at rel_path 'os/updates/teams-notification.sls' to resolve 'salt://os/updates/teams-notification.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/os/updates/teams-notification.sls' to resolve 'salt://os/updates/teams-notification.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/os/updates/teams-notification.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/os/updates/teams-notification.sls' using 'jinja' renderer: 0.003906726837158203
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/os/updates/teams-notification.sls:
send-msteams-message:
  msteams.post_card:
    - title: Patching Failed
    - message: "centos-test-minion Patch State Failed"
    - hook_url: https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/os/updates/teams-notification.sls' using 'yaml' renderer: 0.0009374618530273438
[DEBUG   ] The functions from module 'config' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] The functions from module 'msteams' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded msteams.post_card
[DEBUG   ] The functions from module 'msteams' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded msteams.post_card
[INFO    ] Running state [send-msteams-message] at time 12:31:44.836117
[INFO    ] Executing state msteams.post_card for [send-msteams-message]
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/ms.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/ms.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/psql.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/psql.conf
[DEBUG   ] Using cached minion ID from /etc/salt/minion_id: centos-test-minion
[DEBUG   ] Requesting URL https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775 using POST method
[DEBUG   ] Using backend: tornado
/opt/saltstack/salt/lib/python3.10/site-packages/salt/ext/tornado/netutil.py:493: DeprecationWarning: ssl.PROTOCOL_TLS is deprecated
  context = ssl.SSLContext(
[ERROR   ] Failed to send message (400): send-msteams-message
[INFO    ] Completed state [send-msteams-message] at time 12:31:46.753692 (duration_in_ms=1917.576)
[DEBUG   ] File /var/cache/salt/minion/accumulator/140165728101248 does not exist, no need to cleanup
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[INFO    ] Returning information for job: 20230815123418021378
[DEBUG   ] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_41542b805e_pub.ipc
[DEBUG   ] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_41542b805e_pull.ipc
[DEBUG   ] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'centos-test-minion', 'success': False, 'return': {'msteams_|-send-msteams-message_|-send-msteams-message_|-post_card': {'name': 'send-msteams-message', 'changes': {}, 'result': False, 'comment': 'Failed to send message (400): send-msteams-message', '__sls__': 'os.updates.teams-notification', '__run_num__': 0, 'start_time': '12:31:44.836116', 'duration': 1917.576, '__id__': 'send-msteams-message'}}, 'retcode': 2, 'jid': '20230815123418021378', 'fun': 'state.apply', 'fun_args': ['os.updates.teams-notification'], 'out': 'highstate', '_stamp': '2023-08-15T12:31:46.757695'}
[DEBUG   ] Closing IPCMessageClient instance
[DEBUG   ] minion return: {'success': False, 'return': {'msteams_|-send-msteams-message_|-send-msteams-message_|-post_card': {'name': 'send-msteams-message', 'changes': {}, 'result': False, 'comment': 'Failed to send message (400): send-msteams-message', '__sls__': 'os.updates.teams-notification', '__run_num__': 0, 'start_time': '12:31:44.836116', 'duration': 1917.576, '__id__': 'send-msteams-message'}}, 'retcode': 2, 'jid': '20230815123418021378', 'fun': 'state.apply', 'fun_args': ['os.updates.teams-notification']}
[DEBUG   ] Minion of 'saltmaster' is handling event tag '__master_req_channel_payload'
[DEBUG   ] Minion return retry timer set to 8 seconds (randomized)
[DEBUG   ] Subprocess ProcessPayload(jid=20230815123418021378) cleaned up
^C[DEBUG   ] Closing IPCMessageClient instance
[DEBUG   ] Closing IPCMessageSubscriber instance
[WARNING ] Minion received a SIGINT. Exiting.
[INFO    ] Shutting down the Salt Minion

Thanks.

@whytewolf
Copy link
Collaborator

so, in this case to since the state uses salt.utils.http.query we would need trace not debug. that would give us what is actually sent.

@haykhovsepyan
Copy link
Author

Thanks @whytewolf , below are trace logs.

[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] Decoding payload: {'enc': 'aes', 'load': b'w\xc1\xdd!x\xa5\xaf\x113M\x16\xf5\x9fBm\xd9\xf6k\x0f\xbf\x16v\xf9\xc4c\x96\xae\xed\xaa\xbf"P8\n\xe3"\x07r\xc0\x1f\xfcJe\x80t\x8e3\x8bR\x9e\x9an;z\x03\x89Tc\x02\x8c\xb1\x7f\x9d\xb1\xf6O\xfb\x9b\x1d\x17\x92\xa6II\xc0\xa3\x9aO\xa5S\xc9\xe0b\x81\xa8\xe5\xd3\x05\xe7\xde\x1b\xc2\xa9M\xf9\xa2J#\xb0\x9e<\xba3\xb6\x82Y`\xe7;\x96:\x0f\xbfo\xb9;9\x89`\x9dy;\x89\x0f\xa2UP \x02K\x99Y\xe0cm\xd66\x80\xdb\xb9\xd2G\x08~\r\x90\xdc\x03h\x07!\xbc!\xfcm\xc4\xb8\x97\xf7\xa0\x94\xb9\x7f\x9d\x19\xeaB\\K\x99\x89\xae!\x98-\x84\x05X\x88$\x99\x03A\xb5\'\xcd\x82\xa1\x15DP\xaa\\\xb9k\xa1\x8f\xced&\xb1\x92^\x08\xd6\xcbb\x91\xba# \xa6\xdf\x9de\x04\x86\x17\x02\xeaK\x15\xbc\xee', 'sig': b'qz\xaa\xf4\x99;dE\xfa\xd5`\xff\xecF\x90[\xdag\xaes\r\xe4,v\xdd\xe8^\xc3<\x98\xcf\x04\xfc\x84\x93\xaav\x9f\xf9\xe6\x17 \xf5\x8d\xbf\x9f\x90\xfe\x15\xd0M\x83v[\x806\x925*\xd2\xa6\xd7\xb8Z\xcd\x1c\xaf\x9b\x9a\xce\xd4\xfbE\xadr\x88H5/)v\xf5\xc8\x89\x88\x96\xd10\x04}\xa6\xce0\xe0\xb9\xcd\xc4\x18\xe2\xc9\t\xe0\x00\x8e8u\xa2\xaa\x9f\x914\x8a\xee\xaa\n[8\xcb%fT\x14\x03\xec\xac\xda\\Y\x8a\x91\x00\x02{gq\xf3\xfc\xa3\xfd8q\x17\xd4\xefTX\x931\xc8g\xc5;\x94a\xd4Jux\xeeA\xe7\xc1)\x07@_\x02ta\xb1@\x80\x03\'\xfc\x99\x0e\xa3\xf0\x80\x83\x1a\xbb\x1cT\xf4\xc0\x0e\x07\xd4m\x10/U/\x15\xdf,\x80\xc4\x94\x96Z\x1a\xbf\x1d\xd1\xd0\xfaRn\xae\xce!\xbe\x9bF\xf9\xed0\xc1\x04A\x0b;\xee\x8e\xaa\xaen^w\x08&o\xe6A\x1f\xb3\xd6\xe2T\xf6\xa8\xf9\xb0\x13\xc5"o,\x90_\x10R\x8e'}
[DEBUG   ] PubChannel received: {'enc': 'aes', 'load': {'fun': 'state.apply', 'arg': ['os.updates.teams-notification'], 'tgt': 'centos-test-minion', 'jid': '20230816071543116504', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_hayk.hovsepyan'}, 'sig': b'qz\xaa\xf4\x99;dE\xfa\xd5`\xff\xecF\x90[\xdag\xaes\r\xe4,v\xdd\xe8^\xc3<\x98\xcf\x04\xfc\x84\x93\xaav\x9f\xf9\xe6\x17 \xf5\x8d\xbf\x9f\x90\xfe\x15\xd0M\x83v[\x806\x925*\xd2\xa6\xd7\xb8Z\xcd\x1c\xaf\x9b\x9a\xce\xd4\xfbE\xadr\x88H5/)v\xf5\xc8\x89\x88\x96\xd10\x04}\xa6\xce0\xe0\xb9\xcd\xc4\x18\xe2\xc9\t\xe0\x00\x8e8u\xa2\xaa\x9f\x914\x8a\xee\xaa\n[8\xcb%fT\x14\x03\xec\xac\xda\\Y\x8a\x91\x00\x02{gq\xf3\xfc\xa3\xfd8q\x17\xd4\xefTX\x931\xc8g\xc5;\x94a\xd4Jux\xeeA\xe7\xc1)\x07@_\x02ta\xb1@\x80\x03\'\xfc\x99\x0e\xa3\xf0\x80\x83\x1a\xbb\x1cT\xf4\xc0\x0e\x07\xd4m\x10/U/\x15\xdf,\x80\xc4\x94\x96Z\x1a\xbf\x1d\xd1\xd0\xfaRn\xae\xce!\xbe\x9bF\xf9\xed0\xc1\x04A\x0b;\xee\x8e\xaa\xaen^w\x08&o\xe6A\x1f\xb3\xd6\xe2T\xf6\xa8\xf9\xb0\x13\xc5"o,\x90_\x10R\x8e'}
[DEBUG   ] The functions from module 'glob_match' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded glob_match.match
[INFO    ] User sudo_hayk.hovsepyan Executing command state.apply with jid 20230816071543116504
[DEBUG   ] Command details {'fun': 'state.apply', 'arg': ['os.updates.teams-notification'], 'tgt': 'centos-test-minion', 'jid': '20230816071543116504', 'ret': '', 'tgt_type': 'glob', 'user': 'sudo_hayk.hovsepyan'}
[TRACE   ] Started JIDs: []
[DEBUG   ] Subprocess ProcessPayload(jid=20230816071543116504) added
[TRACE   ] Setting up log file logging: {'log_path': '/var/log/salt/minion', 'log_level': 'warning', 'log_format': '%(asctime)s,%(msecs)03d [%(name)-17s:%(lineno)-4d][%(levelname)-8s][%(process)d] %(message)s', 'date_format': '%Y-%m-%d %H:%M:%S', 'max_bytes': 0, 'backup_count': 0, 'user': 'root'}
[TRACE   ] The required configuration section, 'fluent_handler', was not found the in the configuration. Not loading the fluent logging handlers module.
[TRACE   ] None of the required configuration sections, 'logstash_udp_handler' and 'logstash_zmq_handler', were found in the configuration. Not loading the Logstash logging handlers module.
[TRACE   ] Error loading log_handlers.sentry_mod: Cannot find 'raven' python library, 'sentry_handler' config is empty or not defined
[DEBUG   ] The functions from module 'jinja' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] The functions from module 'yaml' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded yaml.render
[INFO    ] Starting a new job 20230816071543116504 with PID 242160
[DEBUG   ] The functions from module 'direct_call' are being loaded by dir() on the loaded module
[TRACE   ] Error loading executor.docker: Docker executor is only meant to be used with Docker Proxy Minions
[DEBUG   ] The functions from module 'splay' are being loaded by dir() on the loaded module
[TRACE   ] 'transactional-update' could not be found in the following search path: '['/sbin', '/bin', '/usr/sbin', '/usr/bin', '/usr/local/sbin', '/usr/local/bin']'
[TRACE   ] Error loading executor.transactional_update: transactional_update executor requires a transactional system
[DEBUG   ] Could not LazyLoad direct_call.allow_missing_func: 'direct_call.allow_missing_func' is not available.
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.apply
[TRACE   ] Executors list ['direct_call']
[DEBUG   ] The functions from module 'config' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] The functions from module 'saltutil' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded saltutil.is_running
[DEBUG   ] Override  __grains__: <module 'salt.loaded.int.module.grains' from '/opt/saltstack/salt/lib/python3.10/site-packages/salt/modules/grains.py'>
[DEBUG   ] The functions from module 'grains' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded grains.get
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'centos-test-minion', 'tcp://10.130.132.14:4506')
[TRACE   ] ReqChannel send crypt load={'cmd': '_master_opts'}
[DEBUG   ] Gathering pillar data for state run
[DEBUG   ] Determining pillar cache
[DEBUG   ] Initializing new AsyncAuth for ('/etc/salt/pki/minion', 'centos-test-minion', 'tcp://10.130.132.14:4506')
[TRACE   ] ext_pillar_extra_data = {}
[DEBUG   ] salt.crypt.get_rsa_key: Loading private key
[DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
[DEBUG   ] salt.crypt.verify_signature: Loading public key
[DEBUG   ] salt.crypt.get_rsa_pub_key: Loading public key
[DEBUG   ] salt.crypt.verify_signature: Verifying signature
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] Finished gathering pillar data for state run
[INFO    ] Loading fresh modules for state activity
[DEBUG   ] The functions from module 'jinja' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded jinja.render
[DEBUG   ] The functions from module 'yaml' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded yaml.render
[TRACE   ] ReqChannel send crypt load={'saltenv': 'base', 'prefix': '', 'cmd': '_file_list'}
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] Failed to send msg SaltReqTimeoutError('Message timed out')
[TRACE   ] ReqChannel send crypt load={'id': 'centos-test-minion', 'cmd': '_minion_event', 'pretag': None, 'tok': b',\xbf\'\xd5\xce\x88u\xbb\x0fi\xb9\xd2\xdf\xce\xbc\xc0P<\x97\x15\x96\x1b!c\xc2Z\\=\x80\xbc\xea\x0b\xb3Z\xcf\t\xe4\xe3\xeemm\xd0\n,\'\x0e\x8ea\x1a\xf2$\x90x\xcf{f\x1fVCoL\xb6Y\xc5\x04R\x98\x9d\x90x\xf9\xaeJ|n\xbd}\x0fL\xef"\x16{\xa8~\x8c\x87\xee\x87\x1d&\xb2\x1e\x99\xd0\xea\xebL#\x0f!\xfdf\xc7\xa1\x9eo\xe0\x14\xcb"\xce\x92\xd0\x17z\x1b`Ax\x08L7[(\xba\x9d\xd6\x9d\x9b\xeb\rM,\xbdi\xedF\xb7((\xc3t\xc2\x9f\x9b\x06\x0fl\x04\xc1C\x01\xa0\xf8n0o]f\x17\xa8\x80\x143\xd2\x16!\xc9\x9f\xc0\xb4\xc7T\x14L\x00Sl\xe7\t\xb6\xd1V\xc3\xb8g\xd0\x86\xa5f|\xbb\x08!q\x85\xe7\xc5y\xd82\xcd\x1d\xa7=\xbbi\x89`\x0b2!\x1bK\x13c\xbf\x10\x89\x0c\x12R\xbb\xd51t\x86J\x95\xeb\x18\xdd\xe2\xd2\x1d\xc87\xfe\xb55B27.\x10\x9e\x92\x16\x83\xe2\xe6c\x8d<[', 'data': 'Minion centos-test-minion started at Wed Aug 16 07:12:56 2023', 'tag': 'minion_start', '_stamp': '2023-08-16T07:12:56.264186', 'nonce': '99f421c623314b61b9073f156e8afacc'}
[TRACE   ] ReqChannel send crypt load={'path': 'os/updates/teams-notification.sls', 'saltenv': 'base', 'cmd': '_file_hash'}
[TRACE   ] ReqChannel send crypt load={'path': 'os/updates/teams-notification.sls', 'saltenv': 'base', 'cmd': '_file_find'}
[DEBUG   ] In saltenv 'base', looking at rel_path 'os/updates/teams-notification.sls' to resolve 'salt://os/updates/teams-notification.sls'
[DEBUG   ] In saltenv 'base', ** considering ** path '/var/cache/salt/minion/files/base/os/updates/teams-notification.sls' to resolve 'salt://os/updates/teams-notification.sls'
[DEBUG   ] compile template: /var/cache/salt/minion/files/base/os/updates/teams-notification.sls
[DEBUG   ] Jinja search path: ['/var/cache/salt/minion/files/base']
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/os/updates/teams-notification.sls' using 'jinja' renderer: 0.004015922546386719
[DEBUG   ] Rendered data from file: /var/cache/salt/minion/files/base/os/updates/teams-notification.sls:
send-msteams-message:
  msteams.post_card:
    - title: Patching Failed
    - message: "centos-test-minion Patch State Failed"
    - hook_url: https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775
[PROFILE ] Time (in seconds) to render '/var/cache/salt/minion/files/base/os/updates/teams-notification.sls' using 'yaml' renderer: 0.0009946823120117188
[DEBUG   ] The functions from module 'config' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded config.option
[DEBUG   ] The functions from module 'msteams' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded msteams.post_card
[DEBUG   ] The functions from module 'msteams' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded msteams.post_card
[INFO    ] Running state [send-msteams-message] at time 07:13:06.342039
[INFO    ] Executing state msteams.post_card for [send-msteams-message]
[DEBUG   ] Reading configuration from /etc/salt/minion
[DEBUG   ] Including configuration from '/etc/salt/minion.d/_schedule.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/_schedule.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/ms.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/ms.conf
[DEBUG   ] Including configuration from '/etc/salt/minion.d/psql.conf'
[DEBUG   ] Reading configuration from /etc/salt/minion.d/psql.conf
[DEBUG   ] Using cached minion ID from /etc/salt/minion_id: centos-test-minion
[DEBUG   ] Requesting URL https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775 using POST method
[DEBUG   ] Using backend: tornado
[TRACE   ] Request POST Data: ('{"text": "centos-test-minion Patch State Failed", "title": "Patching '
 'Failed", "themeColor": null}')
/opt/saltstack/salt/lib/python3.10/site-packages/salt/ext/tornado/netutil.py:493: DeprecationWarning: ssl.PROTOCOL_TLS is deprecated
  context = ssl.SSLContext(
[TRACE   ] ==== evaluating schedule now None =====
[ERROR   ] Failed to send message (400): send-msteams-message
[INFO    ] Completed state [send-msteams-message] at time 07:13:08.152870 (duration_in_ms=1810.83)
[DEBUG   ] File /var/cache/salt/minion/accumulator/140437689831040 does not exist, no need to cleanup
[DEBUG   ] Closing AsyncReqChannel instance
[DEBUG   ] The functions from module 'state' are being loaded by dir() on the loaded module
[DEBUG   ] LazyLoaded state.check_result
[INFO    ] Returning information for job: 20230816071543116504
[TRACE   ] Return data: {'success': False, 'return': {'msteams_|-send-msteams-message_|-send-msteams-message_|-post_card': {'name': 'send-msteams-message', 'changes': {}, 'result': False, 'comment': 'Failed to send message (400): send-msteams-message', '__sls__': 'os.updates.teams-notification', '__run_num__': 0, 'start_time': '07:13:06.342040', 'duration': 1810.83, '__id__': 'send-msteams-message'}}, 'retcode': 2, 'jid': '20230816071543116504', 'fun': 'state.apply', 'fun_args': ['os.updates.teams-notification']}
[DEBUG   ] SaltEvent PUB socket URI: /var/run/salt/minion/minion_event_41542b805e_pub.ipc
[DEBUG   ] SaltEvent PULL socket URI: /var/run/salt/minion/minion_event_41542b805e_pull.ipc
[TRACE   ] IPCClient: Connecting to socket: /var/run/salt/minion/minion_event_41542b805e_pull.ipc
[TRACE   ] IPCServer: Handling connection to address: <socket.socket fd=47, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/var/run/salt/minion/minion_event_41542b805e_pull.ipc>
[DEBUG   ] Sending event: tag = __master_req_channel_payload; data = {'cmd': '_return', 'id': 'centos-test-minion', 'success': False, 'return': {'msteams_|-send-msteams-message_|-send-msteams-message_|-post_card': {'name': 'send-msteams-message', 'changes': {}, 'result': False, 'comment': 'Failed to send message (400): send-msteams-message', '__sls__': 'os.updates.teams-notification', '__run_num__': 0, 'start_time': '07:13:06.342040', 'duration': 1810.83, '__id__': 'send-msteams-message'}}, 'retcode': 2, 'jid': '20230816071543116504', 'fun': 'state.apply', 'fun_args': ['os.updates.teams-notification'], 'out': 'highstate', '_stamp': '2023-08-16T07:13:08.157949'}
[DEBUG   ] Minion of 'saltmaster' is handling event tag '__master_req_channel_payload'
[DEBUG   ] Minion return retry timer set to 6 seconds (randomized)
[TRACE   ] ReqChannel send crypt load={'cmd': '_return', 'id': 'centos-test-minion', 'success': False, 'return': {'msteams_|-send-msteams-message_|-send-msteams-message_|-post_card': {'name': 'send-msteams-message', 'changes': {}, 'result': False, 'comment': 'Failed to send message (400): send-msteams-message', '__sls__': 'os.updates.teams-notification', '__run_num__': 0, 'start_time': '07:13:06.342040', 'duration': 1810.83, '__id__': 'send-msteams-message'}}, 'retcode': 2, 'jid': '20230816071543116504', 'fun': 'state.apply', 'fun_args': ['os.updates.teams-notification'], 'out': 'highstate', '_stamp': '2023-08-16T07:13:08.157949'}
[DEBUG   ] Closing IPCMessageClient instance
[TRACE   ] ret_val = True
[DEBUG   ] minion return: {'success': False, 'return': {'msteams_|-send-msteams-message_|-send-msteams-message_|-post_card': {'name': 'send-msteams-message', 'changes': {}, 'result': False, 'comment': 'Failed to send message (400): send-msteams-message', '__sls__': 'os.updates.teams-notification', '__run_num__': 0, 'start_time': '07:13:06.342040', 'duration': 1810.83, '__id__': 'send-msteams-message'}}, 'retcode': 2, 'jid': '20230816071543116504', 'fun': 'state.apply', 'fun_args': ['os.updates.teams-notification']}
[TRACE   ] Client disconnected from IPC /var/run/salt/minion/minion_event_41542b805e_pull.ipc
[TRACE   ] ==== evaluating schedule now None =====
[DEBUG   ] Subprocess ProcessPayload(jid=20230816071543116504) cleaned up
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] ==== evaluating schedule now None =====
[TRACE   ] ==== evaluating schedule now None =====
^C[TRACE   ] Waiting to kill process manager children
[DEBUG   ] Closing IPCMessageClient instance
[DEBUG   ] Closing IPCMessageSubscriber instance
[WARNING ] Minion received a SIGINT. Exiting.
[INFO    ] Shutting down the Salt Minion
[TRACE   ] Processing <function DaemonMixIn._mixin_before_exit at 0x7fba44af2a70>
[TRACE   ] Processing <function LogLevelMixIn.__shutdown_logging at 0x7fba44af24d0>
The Salt Minion is shutdown. Minion received a SIGINT. Exited.

@OrangeDog
Copy link
Contributor

{"text": "centos-test-minion Patch State Failed", "title": "Patching Failed", "themeColor": null}

Does that fail when you send it with curl?

Aside: it would be very useful if the body of the error response were logged.

@haykhovsepyan
Copy link
Author

yes I can confirm that with curl it works:

curl -s -w "\n%{http_code}"  -X  POST -H  'Content-Type: application/json' -d '{"text": "Patch State Failed"}' https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775 | {
>     read body
>     read code
>     echo $code
>     
> }
200

@OrangeDog
Copy link
Contributor

No, with the same body as Salt is sending.

@haykhovsepyan
Copy link
Author

curl -s -w "\n%{http_code}"  -X  POST -H  'Content-Type: application/json' -d '{"text": "centos-test-minion Patch State Failed", "title": "Patching Failed", "themeColor": null}' https://XXXXXX.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775 | {
>     read body
>     read code
>     echo $code
>     
> }
200

working as well with the same body.
image

@mastrong
Copy link
Collaborator

mastrong commented Aug 16, 2023

I am also seeing this in v3005.2 classic, since 3005.1 at least. I have a daily job that would post to teams, last successful post was 7/4/23.

@whytewolf
Copy link
Collaborator

I am also seeing this in v3005.2 classic, since 3005.1 at least. I have a daily job that would post to teams, last successful post was 7/4/23.

That is to be expected. the issue wasn't a change on salts side it was microsoft changed something without documenting the change. right now we are trying to figure out what changed, so that we can get a fix in.

@whytewolf
Copy link
Collaborator

looking at the code i have an idea of what it might be. @haykhovsepyan can you try one more curl test. without the json header? the code doesn't have the header.

@haykhovsepyan
Copy link
Author

Hi @whytewolf ,

without json header I got the same error with curl.

curl -s -w "\n%{http_code}"  -X  POST  -d '{"text": "centos-test-minion Patch State Failed", "title": "Patching Failed", "themeColor": null}' https://teamviewer.webhook.office.com/webhookb2/926261a9-26ac-45e6-bbc8-3b8715a30972@ff009f2c-d651-472e-b73e-e0f894c6011e/IncomingWebhook/5c13f52123ab41b8875199cd3bebd667/996cec87-5503-4ee2-a0d1-3ad25a6f5775
Bad payload received by generic incoming webhook.
400

@whytewolf
Copy link
Collaborator

@haykhovsepyan perfect, thank you. looks like i was right it is the lack of the header. Microsoft must have changed to enforcing the header when they haven't for years.

I'll get the header added. thank you very much. this was exactly what I needed.

@haykhovsepyan
Copy link
Author

hi @whytewolf ,

I appreciate your attention to this matter. Could you please clarify on which version expected this fix (as I got on 3006.4) , and if possible, I would like to receive an approximation of the release date for this fixed version.

Thanks.

@whytewolf
Copy link
Collaborator

@haykhovsepyan this was changed to 3006.4 milestone when the pr was put in because there was a freeze in place for 3006.3 and it didn't look like it would make it into that version. however the freeze was bumped a little bit which allowed me to get this into the 3006.3 version.

I can't give the exact eta on its release but 3006.3 is right around the corner. like within a week or two.

@whytewolf
Copy link
Collaborator

3006.3 was released and #65007 was included, closing bug report

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug broken, incorrect, or confusing behavior
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants