KeyError 'took' when pinging heartbeats api multiple times

[rcampos87]

I'm running Python 3.7, django 1.11.17 and opsgenie-sdk v2.0.3 (i tried on v2.1.1 as well), and I have several processes running on background that pings to the heartbeat api multiple times at once. Sometimes the processes are raising a KeyError: 'took'.

Here is the pertaining traceback to your lib:

File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/api/heartbeat/__init__.py", line 628, in ping
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/api/heartbeat/__init__.py", line 703, in ping_with_http_info
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/api_client.py", line 429, in call_api
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/api_client.py", line 219, in __call_api
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/api_client.py", line 203, in __call_api
File "/usr/local/lib/python3.7/dist-packages/tenacity/__init__.py", line 411, in call
File "/usr/local/lib/python3.7/dist-packages/tenacity/__init__.py", line 423, in __call__
File "/usr/local/lib/python3.7/dist-packages/tenacity/__init__.py", line 360, in iter
File "/usr/lib/python3.7/concurrent/futures/_base.py", line 428, in result
File "/usr/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
File "/usr/local/lib/python3.7/dist-packages/tenacity/__init__.py", line 426, in __call__
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/api_client.py", line 452, in request
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/rest.py", line 276, in GET
File "/usr/local/lib/python3.7/dist-packages/opsgenie_sdk/rest.py", line 254, in request

[asqui]

We noticed this started happening last week. It appears to be a change to the REST API where throttled responses used to always get a JSON response containing "message", "took", and "requestId" in the body, but starting 28 January sometimes the body of throttled responses only contain "message".

This is a breaking change for any users of the REST API that are assuming that all responses would always have a "took" and "requestId" in the body (which normally, they do), including this SDK.

We have raised this with Opsgenie support and are awaiting a response.

[rcampos87]

thank you for the reply @asqui

[mhamzak008]

Thanks for pointing it out @asqui @rcampos87 The issue will be resolved as soon as #46 is merged

[mhamzak008]

Also just pointing out that @asqui was correct in pointing out that the problem started because "took" and "requestId" started to be missing from the throttled responses. That will be fixed at the API level as well, but for now we are gonna be defensive in the SDK as well and not fail, if the information isn't there.

[asqui]

Note that we also observed a scenario where it appears there was no JSON in the response payload, which resulted in the following failure:

  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api/alert/__init__.py", line 2166, in list_alerts
    (data) = self.list_alerts_with_http_info(**kwargs)  # noqa: E501
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api/alert/__init__.py", line 2261, in list_alerts_with_http_info
    collection_formats=collection_formats)
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api_client.py", line 432, in call_api
    _preload_content, _request_timeout, _host)
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api_client.py", line 222, in __call_api
    raise exception
ValueError: No JSON object could be decoded

[mhamzak008]

@asqui did this happen while being throttled as well?

[asqui]

I don't know for certain, but I suspect so. It's only happened once so far but if it starts to happen more often I'll increase logging and get more details.

[mhamzak008]

Thanks @asqui. I did several tests on our end while being throttled and didn't come across this error. Please ping us with more details, if it happens again

[rcampos87]

thank you for resolving this issue @mhamzak008

[asqui]

Here is the example of response causing a ValueError: No JSON object could be decoded. It looks like we're getting an HTML error back from CloudFront rather than an actual response from the REST API:

2021-02-04 13:13:24|17241|urllib3.connectionpool|DEBUG   |https://api.opsgenie.com:443 "GET /v2/alerts?query=[...] HTTP/1.1" 504 1033
2021-02-04 13:13:24|17241|opsgenie_sdk.rest|DEBUG   |response body: <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=iso-8859-1">
<TITLE>ERROR: The request could not be satisfied</TITLE>
</HEAD><BODY>
<H1>504 ERROR</H1>
<H2>The request could not be satisfied.</H2>
<HR noshade size="1px">
CloudFront attempted to establish a connection with the origin, but either the attempt failed or the origin closed the connection.
We can't connect to the server for this app or website at this time. There might be too much traffic or a configuration error. Try again later, or contact the app or website owner.
<BR clear="all">
If you provide content to customers through CloudFront, you can find steps to troubleshoot and help prevent this error by reviewing the CloudFront documentation.
<BR clear="all">
<HR noshade size="1px">
<PRE>
Generated by cloudfront (CloudFront)
Request ID: 9-dSUJ03cQyeqlkCs7_SWraz0ArIMcX7KOrvQ-e7GqxlVjR0IKEMXw==
</PRE>
<ADDRESS>
</ADDRESS>
</BODY></HTML>
2021-02-04 13:13:24|17241|opsgenie_sdk  |DEBUG   |SDK Metrics Published
2021-02-04 13:13:24|17241|mtf.lib.script_manager|ERROR   |Processing failed:
Stack trace (oldest call first):
  [...]
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api/alert/__init__.py", line 2166, in list_alerts
    (data) = self.list_alerts_with_http_info(**kwargs)  # noqa: E501
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api/alert/__init__.py", line 2261, in list_alerts_with_http_info
    collection_formats=collection_formats)
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api_client.py", line 432, in call_api
    _preload_content, _request_timeout, _host)
  File "/opt/ecn/python_3rd_party/opsgenie_sdk/api_client.py", line 222, in __call_api
    raise exception
ValueError: No JSON object could be decoded

Update: I noticed there was some truncation in the urllib.connectionpool DEBUG log message which was obscuring the HTTP status code.

I've fixed this up to show that the HTTP status is coming back as 504 -- i.e. one of the statuses that should be retried by default.

[mhamzak008]

Opsgenie is experiencing increased error rates on its API and is working on fixing it. This might be related to that. You can track the status at https://opsgenie.status.atlassian.com/incidents/999fdbj29gd0

[asqui]

Almost certainly related, yes.

I think the SDK should retry on these errors, where at the moment it is blowing up immediately...

The previous fix can be summarised as "Don't assume that the JSON response contains a 'took' value when publishing statistics".

This remaining problem appears to be "Don't assume the response even contains valid JSON in all cases".