URL Encoded Webhook - Python3 Encoding Failure

[jamesdreid]

SUMMARY

Provide a quick summary of your bug report.

STACKSTORM VERSION

Paste the output of st2 --version:

st2 3.1.0, on Python 3.6.8

OS, environment, install method

Post what OS you are running this on, along with any other relevant information/

• e.g. Docker, Vagrant, Kubernetes, etc. Describe how you installed ST2
• e.g. one-line install, custom install, etc -->

Ubuntu 18.04.3 LTS - Manual install

Steps to reproduce the problem

When running the system with Python3, configuring a webhook as a trigger to receive data from a remote source. Configure the remote source to send text data that is URL encoded in the body of the message, as shown in sample curl output below:

curl --location --request POST 'https://127.0.0.1/api/v1/webhooks/test_hook'
--header 'St2-Api-Key: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
--header 'Content-Type: application/x-www-form-urlencoded'
--data-raw 'MyVariableOne=ValueOne&MyVariableTwo=ValueTwo'

Expected Results

What did you expect to happen when running the steps above?

The system should properly process the URL encoded body data and should return it a proper JSON

{
"MyVariableOne": [
"ValueOne"
],
"MyVariableTwo": [
"ValueTwo\n"
]
}

Actual Results

What happened? What output did you get?

The process fails with the following debug output:

[2020-01-27 11:49:57 +0000] [10770] [DEBUG] POST /v1/webhooks/valero_cpe
2020-01-27 11:49:57,579 140064340756784 DEBUG (unknown file) [-] Match path: /v1/webhooks/valero_cpe
2020-01-27 11:49:57,580 140064340756784 INFO (unknown file) [-] 684b74a5-5ea6-4602-9006-2a9a0033710c - POST /v1/webhooks/valero_cpe with query={} (method='POST',path='/v1/webhooks/valero_cpe',remote_addr='127.0.0.1',query={},request_id='684b74a5-5ea6-4602-9006-2a9a0033710c')
2020-01-27 11:49:57,580 140064340756784 DEBUG (unknown file) [-] Received call with WebOb: POST /v1/webhooks/valero_cpe HTTP/1.0
Accept: */*
Accept-Encoding: gzip, deflate, br
Cache-Control: no-cache
Content-Length: 46
Content-Type: application/x-www-form-urlencoded
Host: 81296fd8.ngrok.io,81296fd8.ngrok.io
Postman-Token: 00a125ee-11b4-46fe-9500-75f5d9a811d8
St2-Api-Key: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
User-Agent: PostmanRuntime/7.22.0
X-Forwarded-For: 68.187.78.177, 127.0.0.1
X-Forwarded-Proto: https
X-Real-Ip: 127.0.0.1
X-Request-Id: 684b74a5-5ea6-4602-9006-2a9a0033710c

MyVariableOne=ValueOne&MyVariableTwo=ValueTwo

2020-01-27 11:49:57,580 140064340756784 DEBUG (unknown file) [-] Match path: /v1/webhooks/valero_cpe
2020-01-27 11:49:57,581 140064340756784 DEBUG (unknown file) [-] Parsed endpoint: {'operationId': 'st2api.controllers.v1.webhooks:webhooks_controller.post', 'x-requirements': {'hook': '.*'}, 'description': 'Trigger a webhook.\n', 'parameters': [{'name': 'hook', 'in': 'path', 'description': 'Webhook path', 'type': 'string', 'required': True}, {'name': 'webhook_body_api', 'in': 'body', 'description': 'Webhook payload', 'schema': {'$ref': '#/definitions/WebhookBody'}}], 'x-parameters': [{'name': 'headers', 'in': 'request', 'description': 'List of headers attached to the request.'}, {'name': 'user', 'in': 'context', 'x-as': 'requester_user', 'description': 'User performing the operation.'}], 'responses': {'202': {'description': 'Single action being created', 'schema': {'$ref': '#/definitions/WebhookBody'}, 'examples': {'application/json': {'ref': 'core.local'}}}, 'default': {'description': 'Unexpected error', 'schema': {'$ref': '#/definitions/Error'}}}}
2020-01-27 11:49:57,581 140064340756784 DEBUG (unknown file) [-] Parsed path_vars: {'hook': 'valero_cpe'}
2020-01-27 11:49:57,583 140064340756784 AUDIT (unknown file) [-] API key with id "5ddbbb999e14ef34dced4bfc" is validated.
2020-01-27 11:49:57,587 140064340756784 DEBUG (unknown file) [-] Dispatching trigger {'uid': 'trigger:core:8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d:f7c2bb36b9bae14671835604c4167e1c', 'ref': 'core.8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d', 'name': '8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d', 'pack': 'core', 'type': 'core.st2.webhook', 'parameters': {'url': '/valero_cpe'}, 'id': '5df13f759e14ef0c5f1bcc3a'} with payload {'headers': {'Host': '81296fd8.ngrok.io,81296fd8.ngrok.io', 'X-Real-Ip': '127.0.0.1', 'X-Forwarded-For': '68.187.78.177, 127.0.0.1', 'Content-Length': '46', 'St2-Api-Key': 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx', 'Content-Type': 'application/x-www-form-urlencoded', 'User-Agent': 'PostmanRuntime/7.22.0', 'Accept': '*/*', 'Cache-Control': 'no-cache', 'Postman-Token': '00a125ee-11b4-46fe-9500-75f5d9a811d8', 'Accept-Encoding': 'gzip, deflate, br', 'X-Forwarded-Proto': 'https', 'X-Request-Id': '684b74a5-5ea6-4602-9006-2a9a0033710c'}, 'body': {b'MyVariableOne': [b'ValueOne'], b'MyVariableTwo': [b'ValueTwo\n']}}.
2020-01-27 11:49:57,590 140064340756784 DEBUG (unknown file) [-] Dispatching trigger (trigger={'uid': 'trigger:core:8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d:f7c2bb36b9bae14671835604c4167e1c', 'ref': 'core.8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d', 'name': '8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d', 'pack': 'core', 'type': 'core.st2.webhook', 'parameters': {'url': '/valero_cpe'}, 'id': '5df13f759e14ef0c5f1bcc3a'},payload={'trigger': {'uid': 'trigger:core:8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d:f7c2bb36b9bae14671835604c4167e1c', 'ref': 'core.8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d', 'name': '8e1eb20c-33f6-4e4e-b0e9-dc166b37be7d', 'pack': 'core', 'type': 'core.st2.webhook', 'parameters': {'url': '/valero_cpe'}, 'id': '5df13f759e14ef0c5f1bcc3a'}, 'payload': {'headers': {'Host': '81296fd8.ngrok.io,81296fd8.ngrok.io', 'X-Real-Ip': '127.0.0.1', 'X-Forwarded-For': '68.187.78.177, 127.0.0.1', 'Content-Length': '46', 'St2-Api-Key': 'MzE0NDQ2MzI1YjhiZDFjNmRjZjE5NmUzODEyYTViYmZjNzY3YjYyNzVlNGMxMGQ3ODQ3NzI0YzE0YjNjNjVjNA', 'Content-Type': 'application/x-www-form-urlencoded', 'User-Agent': 'PostmanRuntime/7.22.0', 'Accept': '*/*', 'Cache-Control': 'no-cache', 'Postman-Token': '00a125ee-11b4-46fe-9500-75f5d9a811d8', 'Accept-Encoding': 'gzip, deflate, br', 'X-Forwarded-Proto': 'https', 'X-Request-Id': '684b74a5-5ea6-4602-9006-2a9a0033710c'}, 'body': {b'MyVariableOne': [b'ValueOne'], b'MyVariableTwo': [b'ValueTwo\n']}}, 'trace_context': <st2common.models.api.trace.TraceContext object at 0x7f634564e518>})
2020-01-27 11:49:57,591 140064340756784 DEBUG channel [-] using channel_id: 1
2020-01-27 11:49:57,596 140064340756784 DEBUG channel [-] Channel open
2020-01-27 11:49:57,600 140064340756784 DEBUG channel [-] Closed channel #1
2020-01-27 11:49:57,601 140064340756784 ERROR (unknown file) [-] Failed to call controller function "post" for operation "st2api.controllers.v1.webhooks:webhooks_controller.post": key b'MyVariableOne' is not a string
Traceback (most recent call last):
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/router.py", line 515, in __call__
    resp = func(**kw)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2api/controllers/v1/webhooks.py", line 172, in post
    return Response(json=body, status=http_client.ACCEPTED)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/router.py", line 150, in __init__
    body = json_encode(json_body).encode('UTF-8')
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/util/jsonify.py", line 45, in json_encode
    return json.dumps(obj, cls=GenericJSON, indent=indent)
  File "/usr/lib/python3.6/json/__init__.py", line 238, in dumps
    **kw).encode(obj)
  File "/usr/lib/python3.6/json/encoder.py", line 201, in encode
    chunks = list(chunks)
  File "/usr/lib/python3.6/json/encoder.py", line 430, in _iterencode
    yield from _iterencode_dict(o, _current_indent_level)
  File "/usr/lib/python3.6/json/encoder.py", line 376, in _iterencode_dict
    raise TypeError("key " + repr(key) + " is not a string")
TypeError: key b'MyVariableOne' is not a string
2020-01-27 11:49:57,601 140064340756784 ERROR (unknown file) [-] API call failed: key b'MyVariableOne' is not a string
Traceback (most recent call last):
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/middleware/error_handling.py", line 48, in __call__
    return self.app(environ, start_response)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/middleware/streaming.py", line 47, in __call__
    return self.app(environ, start_response)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/router.py", line 594, in as_wsgi
    resp = self(req)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/router.py", line 519, in __call__
    raise e
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/router.py", line 515, in __call__
    resp = func(**kw)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2api/controllers/v1/webhooks.py", line 172, in post
    return Response(json=body, status=http_client.ACCEPTED)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/router.py", line 150, in __init__
    body = json_encode(json_body).encode('UTF-8')
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2common/util/jsonify.py", line 45, in json_encode
    return json.dumps(obj, cls=GenericJSON, indent=indent)
  File "/usr/lib/python3.6/json/__init__.py", line 238, in dumps
    **kw).encode(obj)
  File "/usr/lib/python3.6/json/encoder.py", line 201, in encode
    chunks = list(chunks)
  File "/usr/lib/python3.6/json/encoder.py", line 430, in _iterencode
    yield from _iterencode_dict(o, _current_indent_level)
  File "/usr/lib/python3.6/json/encoder.py", line 376, in _iterencode_dict
    raise TypeError("key " + repr(key) + " is not a string")
TypeError: key b'MyVariableOne' is not a string (_exception_class='TypeError',_exception_message="key b'MyVariableOne' is not a string",_exception_data={})
2020-01-27 11:49:57,606 140064340756784 DEBUG (unknown file) [-] Match path: /v1/webhooks/valero_cpe
2020-01-27 11:49:57,607 140064340756784 INFO (unknown file) [-] 684b74a5-5ea6-4602-9006-2a9a0033710c - 500 46 27.193ms (method='POST',path='/v1/webhooks/valero_cpe',remote_addr='127.0.0.1',status=500,runtime=27.193,content_length=46,request_id='684b74a5-5ea6-4602-9006-2a9a0033710c')
2020-01-27 11:49:57,608 140064340756784 DEBUG (unknown file) [-] 684b74a5-5ea6-4602-9006-2a9a0033710c - 500 46 27.193ms
b'{\n    "faultstring": "Internal Server Error"\n}' (method='POST',path='/v1/webhooks/valero_cpe',remote_addr='127.0.0.1',status=500,runtime=27.193,content_length=46,request_id='684b74a5-5ea6-4602-9006-2a9a0033710c',result='b\'{\\n    "faultstring": "Internal Server Error"\\n}\'')
[2020-01-27 11:49:57 +0000] [10770] [DEBUG] Closing connection.

I believe I have isolated the issue and it is due to the encoding for the body data that is returned by the WSGI server. In Python2, the body data was returned as a string so line 404 (below) in the router.py file worked properly to process the URL encoded body data.

data = urlparse.parse_qs(req.body)

In Python3, the WSGI server encoded the body data as a byte string and it needed to be decoded as a string before being processed further. Changing line 404 to the following, corrected the error and processed the web hook data properly:

data = urlparse.parse_qs(req.body.decode('utf-8'))

Making sure to follow these steps will guarantee the quickest resolution possible.

Thanks!

[arm4b]

Thanks for detailed bug report and more investigation around this.

Are you saying that your use case worked in py2 but failed in py3, you know where to fix and it confirmed to be working?
If I understand it correctly, can you please create a PR with the fix?

[jamesdreid]

I apologize for the ambiguity, but I have not tested the URLEncoded webhook functions in Python2 so my comment above about the original code working in Python2 was an assumption.

As far as the change to line 404 of the router.py file in my install is suggested above, it did correct the issue, I am no longer seeing the error and the webhook is processing as expected, but I am not sure what the impact will be in other systems aside from my own.

As far as the PR is concerned, I will see if I can work that out, but it may take some time as I am not a programmer by trade and I am still familiarizing myself with Git and how it functions.

[arm4b]

Your way of debugging and communicating this issue is technically solid!
Thanks again for more details @jamesdreid and for reporting this bug.

[Akshat977]

Hi @jamesdreid ,
This issue seems to be a good initiation of my journey towards contribution to FOSS projects.
Can you please assign this to me?