Request body is empty

Webhooks
1

Hi,

I’m testing WebHook in Azure Functions (Linux and Python3.7).
I’ve noticed an occasional error during testing.
I looked into the cause and it looked like the request body was empty.
Do you have any idea why this is happening?

Sample code

import azure.functions
def main(req: azure.functions.HttpRequest) -> azure.functions.HttpResponse:
    payload = req.get_json()

Error log

Traceback (most recent call last): File “/azure-functions-host/workers/python/3.7/LINUX/X64/azure/functions/http.py”, line 59, in get_json return json.loads(self.__body_bytes.decode(‘utf-8’)) File “/usr/local/lib/python3.7/json/init.py”, line 348, in loads return _default_decoder.decode(s) File “/usr/local/lib/python3.7/json/decoder.py”, line 337, in decode obj, end = self.raw_decode(s, idx=_w(s, 0).end()) File “/usr/local/lib/python3.7/json/decoder.py”, line 355, in raw_decode raise JSONDecodeError(“Expecting value”, s, err.value) from None json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0) The above exception was the direct cause of the following exception: Traceback (most recent call last): File “/home/site/wwwroot/update_task_current_reviewer/init.py”, line 14, in main payload = req.get_json() File “/azure-functions-host/workers/python/3.7/LINUX/X64/azure/functions/http.py”, line 62, in get_json ‘HTTP request does not contain valid JSON data’) from e ValueError: HTTP request does not contain valid JSON data

In this case, the content of req.get_body() is b"".

Thank you

2 Likes
3

Here’s something I’ve noticed about this issue.
If the response is more than 6 seconds old, the body of the next call is empty. (There are two calls from the same delivery.)
Seems to be relevant to this topic, is this a specification ?
If it is a specification, is it okay to terminate it normally without doing anything if the body is empty ?

Best regards.

4

Hi Kmori,
Thanks for posting this!

It is true that if the webhook endpoint takes more than 6 seconds to process the HTTP request, Shotgun will consider this request as failed.

But if I understand correctly, you are saying the next HTTP request contains an empty body?
…and there are 2 HTTP requests for the same delivery in the case the first one times out?

Please confirm. That second call for the same delivery definitely sounds like a bug.

5

Hi daigles,

But if I understand correctly, you are saying the next HTTP request contains an empty body?
…and there are 2 HTTP requests for the same delivery in the case the first one times out?

Yes.
I tested it with the code below.

import logging
import time
import azure.functions

def main(req: azure.functions.HttpRequest) -> azure.functions.HttpResponse:
	# debug log
	logging.info('Request Headers:')
	logging.info(dict([(k, req.headers[k]) for k in sorted(req.headers.keys())]))
	logging.info('Request Body:')
	logging.info(req.get_body())
	# wait
	time.sleep(6)
	# return status 200
	return azure.functions.HttpResponse()

It seems that there are 3 requests for one delivery.

1st log

Request Header:
{'accept': 'application/json', 'client-ip': 'x.x.x.x:x', 'connection': 'Keep-Alive', 'content-length': '573', 'content-type': 'application/json; charset=utf-8', 'disguised-host': 'xxxx.azurewebsites.net', 'host': 'xxxx.azurewebsites.net', 'max-forwards': '9', 'user-agent': 'SG event-pipeline', 'was-default-hostname': 'xxxx.azurewebsites.net', 'x-appservice-proto': 'https', 'x-arr-log-id': 'a9c53af4-b192-4776-8405-fc9d1017762a', 'x-arr-ssl': '2048|256|C=US, S=Washington, L=Redmond, O=Microsoft Corporation, OU=Microsoft IT, CN=Microsoft IT TLS CA 5|CN=*.azurewebsites.net', 'x-forwarded-for': '34.224.232.103:30348', 'x-forwarded-proto': 'https', 'x-forwarded-tlsversion': '1.2', 'x-original-url': '/api/HttpTrigger1', 'x-sg-delivery-id': '6b41e10e-0af7-4c8f-8104-96f0d808a075', 'x-sg-event-batch-id': '49602010876473365002699255549496003273915374833489674306', 'x-sg-event-batch-index': '0', 'x-sg-event-batch-size': '1', 'x-sg-webhook-id': 'f1ad3b02-a5eb-4dd3-a761-79c45df0d8d4', 'x-sg-webhook-site-url': 'https://xxxx.shotgunstudio.com/', 'x-site-deployment-id': 'xxxx', 'x-waws-unencoded-url': '/api/HttpTrigger1'}
Request Body:
b'{"data":{"id":"2449013.972351.0","event_log_entry_id":43422033,"event_type":"Shotgun_Asset_Change","operation":"update","user":{"type":"HumanUser","id":95},"entity":{"type":"Asset","id":3852},"project":{"type":"Project","id":120},"meta":{"type":"attribute_change","attribute_name":"sg_status_list","entity_type":"Asset","entity_id":3852,"field_data_type":"status_list","old_value":"cmpt","new_value":"wtg"},"created_at":"2020-10-14 13:34:05.860902","attribute_name":"sg_status_list","session_uuid":"496c7afe-0e0d-11eb-acbe-0242ac110005"},"timestamp":"2020-10-14T13:34:21Z"}'

2nd log

Request Header:
{'accept': 'application/json', 'client-ip': 'x.x.x.x:x', 'connection': 'Keep-Alive', 'content-length': '0', 'content-type': 'application/json; charset=utf-8', 'disguised-host': 'xxxx.azurewebsites.net', 'host': 'xxxx.azurewebsites.net', 'max-forwards': '9', 'user-agent': 'SG event-pipeline', 'was-default-hostname': 'xxxx.azurewebsites.net', 'x-appservice-proto': 'https', 'x-arr-log-id': '626b434b-a107-4ea7-b343-4f14592adf10', 'x-arr-ssl': '2048|256|C=US, S=Washington, L=Redmond, O=Microsoft Corporation, OU=Microsoft IT, CN=Microsoft IT TLS CA 5|CN=*.azurewebsites.net', 'x-forwarded-for': '34.224.232.103:59665', 'x-forwarded-proto': 'https', 'x-forwarded-tlsversion': '1.2', 'x-original-url': '/api/HttpTrigger1', 'x-sg-delivery-id': '6b41e10e-0af7-4c8f-8104-96f0d808a075', 'x-sg-event-batch-id': '49602010876473365002699255549496003273915374833489674306', 'x-sg-event-batch-index': '0', 'x-sg-event-batch-size': '1', 'x-sg-webhook-id': 'f1ad3b02-a5eb-4dd3-a761-79c45df0d8d4', 'x-sg-webhook-site-url': 'https://xxxx.shotgunstudio.com/', 'x-site-deployment-id': 'xxxx', 'x-waws-unencoded-url': '/api/HttpTrigger1'}
Request Body:
b''

3rd log

Request Header:
{'accept': 'application/json', 'client-ip': 'x.x.x.x:x', 'connection': 'Keep-Alive', 'content-length': '0', 'content-type': 'application/json; charset=utf-8', 'disguised-host': 'xxxx.azurewebsites.net', 'host': 'xxxx.azurewebsites.net', 'max-forwards': '9', 'user-agent': 'SG event-pipeline', 'was-default-hostname': 'xxxx.azurewebsites.net', 'x-appservice-proto': 'https', 'x-arr-log-id': '21975645-3b29-40b4-8bd7-84dfeb4f7cd4', 'x-arr-ssl': '2048|256|C=US, S=Washington, L=Redmond, O=Microsoft Corporation, OU=Microsoft IT, CN=Microsoft IT TLS CA 5|CN=*.azurewebsites.net', 'x-forwarded-for': '34.224.232.103:60298', 'x-forwarded-proto': 'https', 'x-forwarded-tlsversion': '1.2', 'x-original-url': '/api/HttpTrigger1', 'x-sg-delivery-id': '6b41e10e-0af7-4c8f-8104-96f0d808a075', 'x-sg-event-batch-id': '49602010876473365002699255549496003273915374833489674306', 'x-sg-event-batch-index': '0', 'x-sg-event-batch-size': '1', 'x-sg-webhook-id': 'f1ad3b02-a5eb-4dd3-a761-79c45df0d8d4', 'x-sg-webhook-site-url': 'https://xxxx.shotgunstudio.com/', 'x-site-deployment-id': 'xxxx', 'x-waws-unencoded-url': '/api/HttpTrigger1'}
Request Body:
b''

client-ip, disguised-host, host, was-default-hostname, x-sg-webhook-site-url, x-site-deployment-id are dummy.

best regards.

6

This is definitely not normal. I will open a ticket to dig into this.

In the meantime it does seem like just ignoring messages with empty payload (that will eventually go away when we fix the bug) is the only solution.

Thanks again for reporting this and helping us make this the best possible system it can be!

7

OK, I hope it will be fixed. :smile:

8

Hi Kmori,
A fix was deployed in production today.That should be the end of empty bodies!

Many thanks for the details you have provided. They were key in helping us understand where the issue was and fixing it promptly!

9

Hi daigles,

It was fixed.
Thanks for the quick support !