TypeError when setting the key 'exceptions' for 'Entity.cause'

[cliffxuan]

If I understand correctly, Entity.cause is turned into a string from a dictionary, and raised a TypeError when calling self.cause['exceptions'] = exceptions.

Relevant traceback:

  File \\"/var/task/aws_xray_sdk/core/models/subsegment.py\\", line 31, in __call__\
    meta_processor=None,\
  File \\"/var/task/aws_xray_sdk/core/recorder.py\\", line 423, in record_subsegment\
    subsegment.add_exception(exception, stack)\
  File \\"/var/task/aws_xray_sdk/core/models/entity.py\\", line 228, in add_exception\
    self.cause[\'exceptions\'] = exceptions\
TypeError: \'str\' object does not support item assignment", "OrderId": "test8f2f5c5dbf774df6b900870bc50b2f7d", "LegacyOrderId": 20168, "Tenant": "uk", "requestId": "7cc85af8-a6a2-454f-8d63-b88339ada756", "XRayTraceId": "1-5ccbed5a-dff39c00f83f3190a93aa1f8"}

Full traceback:

b'_longitude=-3.2135957 (Caused by NewConnectionError(\'<urllib3.connection.HTTPConnection object at 0x7fc086466dd8>: Failed to establish a new connection: [Errno -2] Name or service not known\'))\
\
The above exception was the direct cause of the following exception:\
\
Traceback (most recent call last):\
  File \\"/var/task/aws_xray_sdk/core/recorder.py\\", line 401, in record_subsegment\
    return_value = wrapped(*args, **kwargs)\
  File \\"/var/task/lastmile/lambdas/predict/client.py\\", line 153, in predict_restaurant_working_time\
    response = self._call(url, params)\
  File \\"/var/task/lastmile/lambdas/predict/client.py\\", line 75, in _call\
    raise ConnectError(repr(exc)) from exc\
lastmile.lambdas.predict.client.ConnectError: ConnectionError(MaxRetryError(\\"HTTPConnectionPool(host=\'lastmilepredict-qa28.cogpart.je-labs.com\', port=80): Max retries exceeded with url: /uk/restaurant/1/delivery-eta?restaurant_latitude=50.746794&restaurant_longitude=-1.91133&customer_latitude=54.1120821&customer_longitude=-3.2135957 (Caused by NewConnectionError(\'<urllib3.connection.HTTPConnection object at 0x7fc086466dd8>: Failed to establish a new connection: [Errno -2] Name or service not known\'))\\"))\
\
During handling of the above exception, another exception occurred:\
\
Traceback (most recent call last):\
  File \\"/var/task/lastmile/lambdas/lambdastar.py\\", line 175, in __call__\
    result = self.injector.run([self.handler], state=state)\
  File \\"/var/task/apistar/server/injector.py\\", line 106, in run\
    state[output_name] = func(**func_kwargs)\
  File \\"/var/task/lastmile/handlers/rdsacceptedorder/handler.py\\", line 196, in rds_accepted_order\
    customer_location=order.private_customer_location,\
  File \\"/var/task/aws_xray_sdk/core/models/subsegment.py\\", line 31, in __call__\
    meta_processor=None,\
  File \\"/var/task/aws_xray_sdk/core/recorder.py\\", line 423, in record_subsegment\
    subsegment.add_exception(exception, stack)\
  File \\"/var/task/aws_xray_sdk/core/models/entity.py\\", line 228, in add_exception\
    self.cause[\'exceptions\'] = exceptions\
TypeError: \'str\' object does not support item assignment", "OrderId": "test8f2f5c5dbf774df6b900870bc50b2f7d", "LegacyOrderId": 20168, "Tenant": "uk", "requestId": "7cc85af8-a6a2-454f-8d63-b88339ada756", "XRayTraceId": "1-5ccbed5a-dff39c00f83f3190a93aa1f8"}
[ERROR] TypeError: \'str\' object does not support item assignment\rTraceback (most recent call last):\r\xc2\xa0\xc2\xa0File "/var/task/lastmile/common/serialisation.py", line 152, in _wrapper\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0response_dict = func(*args, **kwargs)\r\xc2\xa0\xc2\xa0File "/var/task/aws_xray_sdk/core/models/subsegment.py", line 31, in __call__\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0meta_processor=None,\r\xc2\xa0\xc2\xa0File "/var/task/aws_xray_sdk/core/recorder.py", line 401, in record_subsegment\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0return_value = wrapped(*args, **kwargs)\r\xc2\xa0\xc2\xa0File "/var/task/lastmile/lambdas/lambdastar.py", line 189, in __call__\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0return self.injector.run([exception_handler], state=state)\r\xc2\xa0\xc2\xa0File "/var/task/apistar/server/injector.py", line 106, in run\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0state[output_name] = func(**func_kwargs)\r\xc2\xa0\xc2\xa0File "/var/task/lastmile/lambdas/lambdastar.py", line 212, in default_exception_handler\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0raise exc\r\xc2\xa0\xc2\xa0File "/var/task/lastmile/lambdas/lambdastar.py", line 175, in __call__\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0result = self.injector.run([self.handler], state=state)\r\xc2\xa0\xc2\xa0File "/var/task/apistar/server/injector.py", line 106, in run\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0state[output_name] = func(**func_kwargs)\r\xc2\xa0\xc2\xa0File "/var/task/lastmile/handlers/rdsacceptedorder/handler.py", line 196, in rds_accepted_order\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0customer_location=order.private_customer_location,\r\xc2\xa0\xc2\xa0File "/var/task/aws_xray_sdk/core/models/subsegment.py", line 31, in __call__\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0meta_processor=None,\r\xc2\xa0\xc2\xa0File "/var/task/aws_xray_sdk/core/recorder.py", line 423, in record_subsegment\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0subsegment.add_exception(exception, stack)\r\xc2\xa0\xc2\xa0File "/var/task/aws_xray_sdk/core/models/entity.py", line 228, in add_exception\r\xc2\xa0\xc2\xa0\xc2\xa0\xc2\xa0self.cause[\'exceptions\'] = exceptions
END RequestId: 7cc85af8-a6a2-454f-8d63-b88339ada756
REPORT RequestId: 7cc85af8-a6a2-454f-8d63-b88339ada756\tDuration: 1394.24 ms\tBilled Duration: 1400 ms \tMemory Size: 256 MB\tMax Memory Used: 70 MB\t
'

versions of xray tried: 2.2.0, 2.4.0

[cliffxuan]

I figured this is probably because we are patching requests using aws_xray_sdk.core.patch. after I removed the patch, the problem went away.

[chanchiem]

Hey, thanks for reporting the issue that you are having.

You mentioned that taking away requests seems to take away this issue, yet it's strange that the underlying issue seems to be that the cause field of the entity is converted into a string. This field should actually be a dictionary, and entity.['exceptions'] is a list.

Is there anywhere in your code that might be modifying the entities? What's your configuration for your application like; i.e. what patchers are you using (or are you calling patch_all())? Are you able to provide the lines of code that can reproduce this? As a sanity check, are you able to verify that the type of the entity prior to the failing call isn't a dictionary?

To do the last thing, I recommend running something like this:
type(xray_recorder.current_subsegment().cause) == dict
or
print type(xray_recorder.current_subsegment().cause) and verify that it's a dict. (Although I'm expecting it to be a string since we're getting the exception you showed.

[cliffxuan]

@chanchiem sorry for the late reply.
I think the cause of the problem is here:
https://github.com/aws/aws-xray-sdk-python/blob/master/aws_xray_sdk/core/models/entity.py#L224

if hasattr(exception, '_recorded'):
    setattr(self, 'cause', getattr(exception, '_cause_id'))
    return

the cause is modified and the type changed to whatever getattr(exception, '_cause_id') is.

[chanchiem]

Wow, very nice find! I think your analysis is correct; Your application might be hitting an edge case which is finally revealing this bug. The cause field within the entity object is getting set to the caught exception's cause ID, when it should most definitely be a dictionary. I think the line is trying to change the last exception added to the cause['exception'] list's ID to the already recorded exception.

I think the reason why it's finally being revealed to us as a bug is because your application is hitting sort of an edge case; It looks like the call to add_exception() is being called twice within the same subsegment, where the first one sets exception._recorded to true, and the second one is a new exception that doesn't have the _recorded field populated to true, and so it is attempting to access a cause dictionary which was previously overwritten by the first exception caught.

I believe the fix would be to remove the line setattr(self, 'cause', getattr(exception, '_cause_id')) because it seems to serve no purpose. I'll run additional tests to confirm before concluding it as a solution.

I was able to reproduce the issue you were having through the following code:

from aws_xray_sdk.core import xray_recorder

xray_recorder.begin_segment("Test")
subseg = xray_recorder.begin_subsegment("test_subseg")
e = Exception("test")
# Add the same exception twice to trigger e._recorder so that entity.cause is modified
subseg.add_exception(e, ['path', 'line', 'label'])
subseg.add_exception(e, ['path', 'line', 'label'])

# Add a whole new exception to trigger cause['exception'], where cause is a string now
subseg.add_exception(Exception("Test2"), ['path', 'line', 'label'])
xray_recorder.end_subsegment()
xray_recorder.end_segment()