Repository navigation
async operations with patched aiobotocore gives error "Already ended segment and subsegment cannot be modified." #164
Description
I'm running into some problems with XRay in combination with async functions and aiobotocore.
Packages:
aioboto3==6.4.1
aiobotocore==0.10.2
aws-xray-sdk==2.4.2
boto3==1.9.176
botocore==1.12.176
I've created a very small sample script to demonstrate my issue:
import aioboto3
import asyncio
import logging
import sys
from datetime import datetime
from aws_xray_sdk.core import patch
from aws_xray_sdk.core import xray_recorder
from aws_xray_sdk.core.async_context import AsyncContext
logger = logging.getLogger()
logger.setLevel(logging.INFO)
xray_logger = logging.getLogger('aws_xray_sdk')
xray_logger.setLevel(logging.INFO)
handler = logging.StreamHandler(sys.stdout)
handler.setLevel(logging.DEBUG)
logging.getLogger().addHandler(handler)
xray_recorder.configure(service='Test', context=AsyncContext(), sampling=False)
patch([
'aiobotocore',
], raise_errors=False)
async def perform_test(gather=False, loop_count=10):
async_client = aioboto3.client('clouddirectory', region_name='eu-west-1')
try:
with xray_recorder.in_segment_async('ASYNC'):
@xray_recorder.capture_async('execute')
async def execute(client):
retval = await client.list_directories(state='ENABLED')
return retval['Directories']
results = []
if gather:
with xray_recorder.capture_async('gather'):
for result in await asyncio.gather(*[execute(async_client) for i in range(loop_count)]):
results += result
else:
with xray_recorder.capture_async('loop'):
for i in range(loop_count):
results += await execute(async_client)
return results
finally:
await async_client.close()
def test_gather(loop_count=10):
try:
now = datetime.utcnow()
asyncio.get_event_loop().run_until_complete(perform_test(gather=True, loop_count=loop_count))
logger.info('GATHER: PASS %s' % str(datetime.utcnow() - now))
except:
logger.exception('GATHER: FAIL')
def test_loop(loop_count=10):
try:
now = datetime.utcnow()
asyncio.get_event_loop().run_until_complete(perform_test(gather=False, loop_count=loop_count))
logger.info('LOOP: PASS %s' % str(datetime.utcnow() - now))
except:
logger.exception('LOOP: FAIL')
logger.info('==========================================')
test_gather()
logger.info('==========================================')
logger.info('==========================================')
test_loop()
logger.info('==========================================')
The expected outcome should be something like:
==========================================
Found credentials in shared credentials file: ~/.aws/credentials
GATHER: PASS 0:00:00.251635
==========================================
==========================================
LOOP: PASS 0:00:01.386801
==========================================
The timings are irrelevant, but it it means that both approaches of using aiobotocore and XRay work together. However, the actual outcome is:
successfully patched module aiobotocore
==========================================
Found credentials in shared credentials file: ~/.aws/credentials
GATHER: FAIL
Traceback (most recent call last):
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/async_recorder.py", line 82, in record_subsegment_async
return_value = await wrapped(*args, **kwargs)
File "/home/idoorn/xray_test.py", line 36, in execute
retval = await client.list_directories(state='ENABLED')
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/ext/aiobotocore/patch.py", line 36, in _xray_traced_aiobotocore
meta_processor=aws_meta_processor,
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/async_recorder.py", line 101, in record_subsegment_async
stack=stack,
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/ext/boto_utils.py", line 57, in aws_meta_processor
resp_meta.get('HTTPStatusCode'))
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/models/entity.py", line 102, in put_http_meta
self._check_ended()
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/models/entity.py", line 283, in _check_ended
raise AlreadyEndedException("Already ended segment and subsegment cannot be modified.")
aws_xray_sdk.core.exceptions.exceptions.AlreadyEndedException: Already ended segment and subsegment cannot be modified.
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/idoorn/xray_test.py", line 58, in test_gather
asyncio.get_event_loop().run_until_complete(perform_test(gather=True, loop_count=loop_count))
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/asyncio/base_events.py", line 484, in run_until_complete
return future.result()
File "/home/idoorn/xray_test.py", line 42, in perform_test
for result in await asyncio.gather(*[execute(async_client) for i in range(loop_count)]):
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/async_recorder.py", line 33, in __call__
meta_processor=None,
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/async_recorder.py", line 105, in record_subsegment_async
subsegment.add_exception(exception, stack)
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/models/entity.py", line 220, in add_exception
self._check_ended()
File "/home/idoorn/anaconda2/envs/bazelenv36/lib/python3.6/site-packages/aws_xray_sdk/core/models/entity.py", line 283, in _check_ended
raise AlreadyEndedException("Already ended segment and subsegment cannot be modified.")
aws_xray_sdk.core.exceptions.exceptions.AlreadyEndedException: Already ended segment and subsegment cannot be modified.
==========================================
==========================================
LOOP: PASS 0:00:01.989784
==========================================
Using asyncio.gather() doesn't seem to play nice with xray, as when the call to clouddirectory comes, the subsegment which was used for tracing the call has already been closed. Only when calling the async calls sequentially will xray work nicely. But that obviously would kind of defeat the benefits of using async. :)
NOTE: if I remove the lines:
patch([
'aiobotocore',
], raise_errors=False)
from the above test script, everything works well, but no tracing is occurring on the clouddirectory calls obviously.
Reacted by David Filiatrault, Anatol Bivol, amplify-kfujio, Brandon Suzuki, Zach Fuller, Kyle King and Ryan Causey
Activity
IvDoorn commentedon Jul 1, 2019
Not sure if it is relevant, but I've noticed that the XRay segments when using asyncio.gather() are build up in a deep tree.
For example:
asyncio.gather([task() for i in range(5)])
yields segments:
which doesn't really feel correct, as I would expect a similar outcome as when I called them sequentially:
I'm just raising this as observation, as maybe this isconstruction is the cause of the issue. If not then my comment can be discarded.
IvDoorn commentedon Jul 10, 2019
I've added annotations in the AsyncContext, where the (sub)segment id and name are being printed.
The output when aiobotocore is not being patched:
The output when aiobotocore is being patched:
The number of subsegments which are being closed before the segment is being closed varies between runs.
IvDoorn commentedon Jul 10, 2019
The problem seems to be that the aws_xray_sdk has a single list of traces which are open. And has problems when segments are closed out of order (which is a normal pattern when asyncio.gather() is being used, and I think also common for the async pattern in general)
With some debugging I found that async_recorder.py::record_subsegment_async() keeps track of the subsegment. as soon as it arrives in the finally statement, it adds the required annotations to the subsegment which it has a reference to. But when it calls end_subsegment it doesn't close the subsegment it has a reference to, but it closes a subsegment which is on top of the entities stack, which might actually be a completely different subsegment.
oba11 commentedon Jul 31, 2019
I'm experiencing this as well. This happens if I have an async function that uses
await asyncio.gather(*[foo(x) for x in list]).Once it's switched to
for x in list: await foo(x), it works fine.chanchiem commentedon Aug 1, 2019
Hey,
Thank you for reporting the issue you are having and giving a detailed explanation of it. This will definitely help us in determining the root cause and finding a solution for it. It sounds like the issue is that the asynchronous tasks aren't holding the appropriate references to their parents, and so when the tasks are finished and the subsegments are closed, only the top-most parents in the context entity list are being referenced. We'll have to investigate this and see what changes are necessary to provide a fix. Please stay tuned
Thanks again for reporting this issue!
dangtrinhnt-mmt commentedon Oct 1, 2019
Any update on this issue? I'm experiencing a similar problem but even with or without patching aiobotocore.
This is how I used aws_xray_sdk
These are the modules I'm using:
chanchiem commentedon Oct 9, 2019
Hey,
Sorry for the delayed response. We're still investigating this internally and are really breaking it down so that we can isolate whether the issue is truly coming from the way we are patching aiobotocore or if it's a bug with how we propagate the context information using TaskLocalStorage.
@dangtrinhnt-mmt You mentioned that you are experiencing the problem with or without patching aiobotocore. Is there a way you can provide a minimal reproduction code sample to us?
IvDoorn commentedon Oct 10, 2019
Hey,
I'm afraid you are staring at
aiobotocore, while that is not where the problem is. As mentioned in my first post, the problem is in asyncio.gather(). Also please see my comment here: #164 (comment)Here is my updated script, which still demonstrates the issue, but does not use aiobotocore.
The problem is this:
As you can see, steps 7, 10 and 12 are all performing bad operations. If the handlers would try to put an annotation to their segment, handler2 would discover his segment to have been closed already.
The XRay code assumes that each handler passed to asyncio.gather() are completing in the exact reversed order as provided to asyncio.gather call. For which there is no such guarantee, stuff is async, so one handler might be much faster then another.
I guess what needs to happen is:
chanchiem commentedon Oct 17, 2019
Thanks for confirming that this is not related to aiobotocore. In our async tasks, we store the information context inside task local storage here. It makes me wonder why this mechanism breaks inside the asyncio.gather() call. By design, each context should be confined within a particular task that is running the code.
It seems asyncio.gather() might spin off its own tasks, which might be why we're seeing nested subsegments instead. I think we have a good starting point to work with here.
For reference, here is where asyncio.gather() is implemented.
dangtrinhnt-mmt commentedon Nov 26, 2019
oh sorry, I miss your comment. It's a little bit complicated for me to provide the minimal reproduction code sample because the error comes from many of our services in the microservice stack. Let me see if I can do something. Thanks for looking into this.
jmgamboa commentedon Jan 9, 2020
Hi! Having a similar issue however not with asyncio but the segmentio library which uses a background thread to send http requests. I am doing patch_all and essentially my background threads are failing and not performing the their task.
cejohnson-bw commentedon Feb 20, 2020
I'm seeing this using gevent as well, with the regular, non-aio versions of
boto3andbotocore. Sincegeventdoesn't useasyncio(it's a concurrency alternative toasynciothat uses greenlets for anyone unfamiliar with it), I would guess it's running into the issue @IvDoorn mentioned where segments are assumed to be stacks, but I can't say for sure.srprash commentedon Mar 3, 2020
Hi all,
Apologies for the delay on diving into this issue. I'll try to get this prioritized on our backlog. Thank you for being patient.
xjia1 commentedon Mar 7, 2020
#203 might be relevant. Please see if that's an easier repro.
22 remaining items
jall commentedon Aug 24, 2023
I did try & hit this
which I couldn't resolve with some brief debugging. IIRC it seemed like the patch library could've been out of date?
I ended up removing aiboto from the patched libraries until this is fixed:
garyd203 commentedon Sep 1, 2023
@jall do you happen to have some code that reproduces your error? Context propagation is dependent on the actual calling code, so if it fails (which is what
cannot find the current segment/subsegmentgenerally means) then that might help us track down what the specific problem is.If you don't know where the error comes from, IIRC you can change the config on your dev environment (with something like
xray_recorder.configure(context_missing="RUNTIME_ERROR")) to raise an exception, and you can hopefully follow the traceback to figure it out.garyd203 commentedon Sep 1, 2023
@carolabadeer note that there's multiple similar-looking issues here.
Already ended segment and subsegment cannot be modifiedin conjunction with parallel subsegments being incorrectly nested in a strange order. This was caused by the buggyAsyncContextimplementation inaws_xray_sdkv2.9 and earlier. The fix inaws_xray_sdkv2.10 (see Bug Fix: Defensively copy context entities #340) is substantially the same as the fix inxraysink, so this problem should no longer occur.cannot find the current segment/subsegmenterror likejallencountered. A solution for this will involve integrating with each individual framework's context-propagation system.cannot find the current segment/subsegmenterror.mdnorman commentedon Sep 11, 2023
I'm still getting the original error as well when using
aws-xray-sdk==2.12.0, and when testing thexraysink, it gave the samecannot find the current segment/subsegmenterror, along with a warning:No segment found, cannot begin subsegment ecs.The new errors may be because I'm using an older version of psycopg that doesn't support async operations, and I'm calling it from an async function.In any case, I don't think that this error should throw an exception out to the caller. Logging shouldn't ever cause my system to break, and xray is effectively a logger. So, similar to the
context_missingconfig, I would expect that the original error should just log and move on and let me do something with the logs (or not).If it helps, I'm using
strawberry-graphql==0.193.1which makes heavy use of asyncio.garyd203 commentedon Sep 13, 2023
@mdnorman can you confirm my suspicion that your strawberry resolver functions are not async (as a consequence of using non-async
psycopg)?mdnorman commentedon Sep 13, 2023
My resolver functions are asynchronous, because they do other things besides the Postgres calls
garyd203 commentedon Sep 13, 2023
Fair enough. How do you call the non-async postgres functions?
mdnorman commentedon Sep 13, 2023
Not at my computer right now but I don't do anything special. It's just a call to most-likely already open connection to make a query. I use a connections pool so it's not exactly straightforward but I'm also not explicitly passing any additional context down to it.
garyd203 commentedon Sep 13, 2023
oh, i mean how do you execute the non-async function from within an async function (like the resolver). Do you call it directly, or do you put it in a thread-pool, or some other approach?
No rush to respond, I'm just trying to figure out how to support your use case. Ta!
mdnorman commentedon Sep 13, 2023
The async function is in a class, and the sync function is in the same class, so it's something like this:
The
conn.executeis synchronous (as is theget_db_connection).No thread-pools for this right now.
garyd203 commentedon Sep 13, 2023
Thanks @mdnorman , it's helpful to know how people are using xray.
In your case, I suspect the problem is that the instrumented sync code for
psycopgdoesn't know where to find the information on the current xray trace, since sync and async code store the trace data differently. I don't know of any solution for this yet - "someone" will have to code something up :-)Cheers,
gary
georgebv commentedon Mar 28, 2024
I'm having this error when patching
httpxwhich sends requests ayncrhonously inside a task group.My solution was to patch the httpx patcher (pun intended) - you can see that error happens after response. For some reason subsegment gets closed before context manager is exited.
ryancausey commentedon Apr 12, 2024
I'm getting this while using aioboto3 with aws-xray-sdk = "2.13.0". Any progress on a fix?
sevetseh28 commentedon Jul 21, 2024
Same, I'm getting this same error when using
asyncio.gatherto perform concurrent calls to different AWS services. It's the whole point of looking traces to see if our code is efficient and making concurrent calls, so I'm a bit surprised this hasn't gotten the attention it deserves for five years already!I'm using AWS Lambda Powertools + aioboto3.
Looking forward to a much needed fix soon,
thanks! 🙏
ShedPlant commentedon Dec 13, 2024
I have seen this when trying to enable X-Ray for a lambda webapp using aws-powertools. It fails to makes multiple simultaneous aiobotocore calls in
gather.Snippets to demonstrate (incomplete, not runnable as is):
I agree with above posters that:
gathershould work