async operations with patched aiobotocore gives error "Already ended segment and subsegment cannot be modified."

[IvDoorn]

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.

[IvDoorn]

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:

segment = {
  id = 1
  subsegment = [{
    id = 2
    subsegment = [{
      id = 3
      subsegment = [{
        id = 4
        subsegment = [{
          id = 5
          subsegment = [{
            id = 6
          }]
        }]
      }]
    }]
  }]
}

which doesn't really feel correct, as I would expect a similar outcome as when I called them sequentially:

segment = {
  id = 1
  subsegment = [{
    id = 2
  },{
    id = 3
  },{
    id = 4
  },{
    id = 5
  },{
    id = 6
  }]
}

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]

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:

==========================================
Found credentials in shared credentials file: ~/.aws/credentials
 put_segment 711fcc470e7cbb6f ASYNC
    put_subsegment 792f4b2aad19f420 gather
    put_subsegment 216f5c6ac6ccd048 execute
    put_subsegment ba38aa8f88d00fb2 execute
    put_subsegment c36a983cea5ab9f6 execute
    put_subsegment 6ee6263fb314a68c execute
    put_subsegment 789485876d6d256b execute
    put_subsegment 31690b346919ac6c execute
    put_subsegment 81a182a0ba306165 execute
    put_subsegment 4d21fdd41115ddae execute
    put_subsegment a63f45b6de4a6e99 execute
    put_subsegment b3b3e4c98a08c13f execute
    end_subsegment b3b3e4c98a08c13f execute
    end_subsegment a63f45b6de4a6e99 execute
    end_subsegment 4d21fdd41115ddae execute
    end_subsegment 81a182a0ba306165 execute
    end_subsegment 31690b346919ac6c execute
    end_subsegment 789485876d6d256b execute
    end_subsegment 6ee6263fb314a68c execute
    end_subsegment c36a983cea5ab9f6 execute
    end_subsegment ba38aa8f88d00fb2 execute
    end_subsegment 216f5c6ac6ccd048 execute
    end_subsegment 792f4b2aad19f420 gather
 end_segment 711fcc470e7cbb6f ASYNC
 clear_trace_entities
GATHER: PASS 0:00:00.297979
==========================================
==========================================
 put_segment 6c96a0ef56cf1b02 ASYNC
    put_subsegment b8ec066ffbcd99cf loop
    put_subsegment 3c3482cda5262ec8 execute
    end_subsegment 3c3482cda5262ec8 execute
    put_subsegment 7ac32e55b3374b38 execute
    end_subsegment 7ac32e55b3374b38 execute
    put_subsegment 982172a693e4a66a execute
    end_subsegment 982172a693e4a66a execute
    put_subsegment 50b4e3b69de27bed execute
    end_subsegment 50b4e3b69de27bed execute
    put_subsegment f57d1221c5dfb563 execute
    end_subsegment f57d1221c5dfb563 execute
    put_subsegment 2366ef95317cd3af execute
    end_subsegment 2366ef95317cd3af execute
    put_subsegment 3e026e0c86b8271b execute
    end_subsegment 3e026e0c86b8271b execute
    put_subsegment 943026938a58dd59 execute
    end_subsegment 943026938a58dd59 execute
    put_subsegment 54bbf67d63f2fe2f execute
    end_subsegment 54bbf67d63f2fe2f execute
    put_subsegment 65264211d9e192b6 execute
    end_subsegment 65264211d9e192b6 execute
    end_subsegment b8ec066ffbcd99cf loop
 end_segment 6c96a0ef56cf1b02 ASYNC
 clear_trace_entities
LOOP: PASS 0:00:00.580935

The output when aiobotocore is being patched:

successfully patched module aiobotocore
==========================================
Found credentials in shared credentials file: ~/.aws/credentials
 put_segment 78e4d90abc45a819 ASYNC
    put_subsegment a082565910e4592a gather
    put_subsegment 14b465d5c688d2d0 execute
    put_subsegment 7b191e9abbb0d7bf clouddirectory
    put_subsegment 323647a6f040e268 execute
    put_subsegment ba22149f76c4fc29 clouddirectory
    put_subsegment d14964c4e833cc61 execute
    put_subsegment d2556484dd044914 clouddirectory
    put_subsegment ab770ada232edea0 execute
    put_subsegment ac084b5cfa75188f clouddirectory
    put_subsegment bbc0eb69fb076fc6 execute
    put_subsegment 568672914d3e285d clouddirectory
    put_subsegment 3c7be0ff1506e0f1 execute
    put_subsegment d2222a649d43b44b clouddirectory
    put_subsegment 2723da4417455290 execute
    put_subsegment dc8bbbc0562f5a94 clouddirectory
    put_subsegment 0ace3622760b52d1 execute
    put_subsegment 77883c8fc76a8a54 clouddirectory
    put_subsegment 53b97b82d0e67aee execute
    put_subsegment c37d884576651c9d clouddirectory
    put_subsegment bb9e01f8106a9197 execute
    put_subsegment 6a818f5c10a7d7f4 clouddirectory
    end_subsegment 6a818f5c10a7d7f4 clouddirectory
    end_subsegment bb9e01f8106a9197 execute
    end_subsegment c37d884576651c9d clouddirectory
    end_subsegment 53b97b82d0e67aee execute
    end_subsegment 77883c8fc76a8a54 clouddirectory
    end_subsegment 0ace3622760b52d1 execute
    end_subsegment dc8bbbc0562f5a94 clouddirectory
    end_subsegment 2723da4417455290 execute
    end_subsegment d2222a649d43b44b clouddirectory
    end_subsegment 3c7be0ff1506e0f1 execute
    end_subsegment 568672914d3e285d clouddirectory
    end_subsegment bbc0eb69fb076fc6 execute
    end_subsegment ac084b5cfa75188f clouddirectory
    end_subsegment ab770ada232edea0 execute
    end_subsegment d2556484dd044914 clouddirectory
 end_segment 78e4d90abc45a819 ASYNC STILL HAS OPENED SUBSEGMENTS
 end_subsegment d14964c4e833cc61 execute
 end_subsegment ba22149f76c4fc29 clouddirectory
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 "xray_test.py", line 79, 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 "xray_test.py", line 101, 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 "xray_test.py", line 85, 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.
==========================================
==========================================
 put_segment b6fedb006c67a028 ASYNC
    put_subsegment 671b3fabef5c1d20 loop
    put_subsegment 8ea469a8e76f7e8d execute
    put_subsegment cfc5e9c02e445749 clouddirectory
    end_subsegment cfc5e9c02e445749 clouddirectory
    end_subsegment 8ea469a8e76f7e8d execute
    put_subsegment bf7ef80b842e0860 execute
    put_subsegment 68b3ecec109207b9 clouddirectory
    end_subsegment 68b3ecec109207b9 clouddirectory
    end_subsegment bf7ef80b842e0860 execute
    put_subsegment 7f80392a32abc60a execute
    put_subsegment f8f32b915be7a8f8 clouddirectory
    end_subsegment f8f32b915be7a8f8 clouddirectory
    end_subsegment 7f80392a32abc60a execute
    put_subsegment 238af8551c63c191 execute
    put_subsegment b36f43bb28a0d133 clouddirectory
    end_subsegment b36f43bb28a0d133 clouddirectory
    end_subsegment 238af8551c63c191 execute
    put_subsegment 8a30e5f2397d5e38 execute
    put_subsegment 006d078cbf530831 clouddirectory
    end_subsegment 006d078cbf530831 clouddirectory
    end_subsegment 8a30e5f2397d5e38 execute
    put_subsegment 48391cd8290590fc execute
    put_subsegment d3cedf188da9f5d6 clouddirectory
    end_subsegment d3cedf188da9f5d6 clouddirectory
    end_subsegment 48391cd8290590fc execute
    put_subsegment 99bd19c4174e0484 execute
    put_subsegment 33fd5a68dd3901c3 clouddirectory
    end_subsegment 33fd5a68dd3901c3 clouddirectory
    end_subsegment 99bd19c4174e0484 execute
    put_subsegment e0da9caf1d677cff execute
    put_subsegment a3315fa97484ff42 clouddirectory
    end_subsegment a3315fa97484ff42 clouddirectory
    end_subsegment e0da9caf1d677cff execute
    put_subsegment fbfbf5e350e94293 execute
    put_subsegment 74dc916aa8d9d322 clouddirectory
    end_subsegment 74dc916aa8d9d322 clouddirectory
    end_subsegment fbfbf5e350e94293 execute
    put_subsegment c16594d7542ccc5c execute
    put_subsegment 17ef29ec0b79aee0 clouddirectory
    end_subsegment 17ef29ec0b79aee0 clouddirectory
    end_subsegment c16594d7542ccc5c execute
    end_subsegment 671b3fabef5c1d20 loop
 end_segment b6fedb006c67a028 ASYNC
 clear_trace_entities
LOOP: PASS 0:00:00.614093
==========================================

The number of subsegments which are being closed before the segment is being closed varies between runs.

[IvDoorn]

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]

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]

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]

Any update on this issue? I'm experiencing a similar problem but even with or without patching aiobotocore.

Traceback (most recent call last):
  File '/path/to/app/tasks.py', line 276, in work
    await self._fire_medium_messages(medium, client)
  File '/path/to/app/tasks.py', line 243, in _fire_medium_messages
    await self._execute_fire_tasks(tasks, message_ids, is_bulk_test=bulk_test, template=msg_state_template)
  File '/path/to/app/tasks.py', line 200, in _execute_fire_tasks
    results = await asyncio.gather(*tasks)
  File '/path/to/app/mediums/message.py', line 51, in fire
    await client.send_message(**args)
  File '/usr/local/lib/python3.6/site-packages/aws_xray_sdk/ext/aiobotocore/patch.py', line 36, in _xray_traced_aiobotocore
    meta_processor=aws_meta_processor,
  File '/usr/local/lib/python3.6/site-packages/aws_xray_sdk/core/async_recorder.py', line 101, in record_subsegment_async
    stack=stack,
  File '/usr/local/lib/python3.6/site-packages/aws_xray_sdk/ext/boto_utils.py', line 57, in aws_meta_processor
    resp_meta.get('HTTPStatusCode'))
  File '/usr/local/lib/python3.6/site-packages/aws_xray_sdk/core/models/entity.py', line 102, in put_http_meta
    self._check_ended()
  File '/usr/local/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.

This is how I used aws_xray_sdk

import aiobotocore
from aws_xray_sdk.core import patch, xray_recorder
from aws_xray_sdk.core.async_context import AsyncContext
xray_recorder.configure(service='sqs', context=AsyncContext())
patch(modules_to_patch=['aiobotocore'])

These are the modules I'm using:

aiobotocore==0.10.3
aiohttp==3.3.2
aioredlock==0.2.0
aiomysql==0.0.19
aioelasticsearch
asyncpgsa==0.22.0
aws-xray-sdk==2.4.2
boto3==1.9.99

[chanchiem]

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]

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.

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)

async def perform_test(gather=False, loop_count=10):

    with xray_recorder.in_segment_async('ASYNC'):
        @xray_recorder.capture_async('execute')
        async def execute(i, maximum):
            segment = xray_recorder.current_subsegment()
            segment.put_annotation('before', True)
            await asyncio.sleep(maximum - 1)
            segment.put_annotation('after', True)

        if gather:
            with xray_recorder.capture_async('gather'):
                await asyncio.gather(*[execute(i, loop_count) for i in range(loop_count)])
        else:
            with xray_recorder.capture_async('loop'):
                for i in range(loop_count):
                    await execute(i, loop_count)


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(5)
logger.info('==========================================')
logger.info('==========================================')
test_loop(5)
logger.info('==========================================')

The problem is this:

1) -> start Segment
2) -> Run asyncio.gather([range(5)])
3) -> Handler 1 starts
4) -> Create Subsegment 1, grab current segment as parent (which is Segment)
5) -> Perform an IO operation (go to sleep)
6) -> Handler 2 starts
7) -> Create Subsegment 2, grab current segment as parent (which is Subsegment 1)
8) -> Perform an IO operation (go to sleep)
9) -> Handler 1 IO operation completes
10) -> Handler 1 closes the current segment (which is Subsegment 2)
11) -> Handler 2 IO operation completes
12 -> Handler 2 closes the current segment (which is Subsegment 1)

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:

• Patch asyncio.gather(), to ensure that each of the handlers which is passed get an environment where the "current segment" points at the correct segment (the segment which was current at the time of calling asyncio.gather().
• Anywhere in the code where the stack of segments is conspired a lifo queue, should be updated, to ensure they always interact with correct segment.

[chanchiem]

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]

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?

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]

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]

I'm seeing this using gevent as well, with the regular, non-aio versions of boto3 and botocore. Since gevent doesn't use asyncio (it's a concurrency alternative to asyncio that 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]

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]

#203 might be relevant. Please see if that's an easier repro.