Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(async-io): instrumented asyncio.wait_for properly raises asyncio.TimeoutError #2637

Conversation

smoke
Copy link
Contributor

@smoke smoke commented Jun 26, 2024

Description

As per the example from https://docs.python.org/3.13/library/asyncio-task.html#asyncio.wait_for when asyncio.wait_for hits the defined timeout it should raise an asyncio.TimeoutError,
however this is not the case when opentelemetry-instrumentation-asyncio is enabled

If everything is good running the below code in both cases should print timeout!

# asyncio-wait-for-example.py
import asyncio
import os

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.instrumentation.asyncio import AsyncioInstrumentor

OTEL_PYTHON_DISABLED_INSTRUMENTATIONS = os.getenv("OTEL_PYTHON_DISABLED_INSTRUMENTATIONS", "")
if 'asyncio' not in OTEL_PYTHON_DISABLED_INSTRUMENTATIONS:
    AsyncioInstrumentor().instrument()

trace.set_tracer_provider(TracerProvider())
tracer = trace.get_tracer(__name__)

# code below taken from https://docs.python.org/3.13/library/asyncio-task.html#asyncio.wait_for
async def eternity():
    # Sleep for one hour
    await asyncio.sleep(3600)
    print('yay!')

async def main():
    # Wait for at most 1 second
    try:
        await asyncio.wait_for(eternity(), timeout=1.0)
    except TimeoutError:
        print('timeout!')

asyncio.run(main())

# Expected output:
#
#     timeout!

The PR fixes that by not swallowing asyncio.CancelledError that is used internally from asyncio timeouts.

Type of change

Please delete options that are not relevant.

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to not work as expected)
  • This change requires a documentation update

How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Provide instructions so we can reproduce. Please also list any relevant details for your test configuration

  • disabled asyncio instrumentation OTEL_PYTHON_DISABLED_INSTRUMENTATIONS="asyncio" python asyncio-wait-for-example.py prints timeout!
  • enabled asyncio instrumentation python asyncio-wait-for-example.py as well prints timeout!

Does This PR Require a Core Repo Change?

  • Yes. - Link to PR:
  • No.

Checklist:

See contributing.md for styleguide, changelog guidelines, and more.

  • Followed the style guidelines of this project
  • Changelogs have been updated
  • Unit tests have been added
  • Documentation has been updated

Copy link

linux-foundation-easycla bot commented Jun 26, 2024

CLA Signed

The committers listed above are authorized under a signed CLA.

  • ✅ login: smoke / name: Radoslav Kirilov (094a085)
  • ✅ login: xrmx / name: Riccardo Magliocchetti (cd8e723)
  • ✅ login: ocelotl / name: Diego Hurtado (0ec96d1, 636fb3b)

@smoke smoke force-pushed the fix/asyncio-wait-for-with-timeout-returning-none branch from 650cbfd to ffb012d Compare June 26, 2024 13:29
@smoke smoke requested a review from a team June 26, 2024 13:29
CHANGELOG.md Outdated Show resolved Hide resolved
@xrmx
Copy link
Contributor

xrmx commented Jun 26, 2024

@smoke please fix lint

@smoke
Copy link
Contributor Author

smoke commented Jun 26, 2024

@smoke please fix lint

@xrmx Done, thanks for noting!

@smoke smoke requested a review from xrmx June 26, 2024 14:13
@smoke smoke force-pushed the fix/asyncio-wait-for-with-timeout-returning-none branch from 3c7766f to 094a085 Compare June 26, 2024 14:17
smoke added a commit to smoke/opentelemetry-python-contrib that referenced this pull request Jun 26, 2024
Copy link
Member

@aabmass aabmass left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM but would appreciate a review from @bourbonkk

Copy link
Contributor

@bourbonkk bourbonkk left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM. Thank you for your PR.

@smoke
Copy link
Contributor Author

smoke commented Jun 27, 2024

@xrmx @aabmass I see the branch is out of date, do I need to update it or you will take care?

@xrmx
Copy link
Contributor

xrmx commented Jun 27, 2024

@smoke we'll take care of it

@ocelotl ocelotl enabled auto-merge (squash) June 27, 2024 16:44
auto-merge was automatically disabled June 27, 2024 16:47

Pull Request is not mergeable

@smoke
Copy link
Contributor Author

smoke commented Jun 28, 2024

There seems to be a test failing that is not related to this PR https://github.com/open-telemetry/opentelemetry-python-contrib/actions/runs/9700988497/job/26773822151?pr=2637#step:6:626

=================================== FAILURES ===================================
_______________ TestProgrammatic.test_flask_metrics_new_semconv ________________
/home/runner/work/opentelemetry-python-contrib/opentelemetry-python-contrib/.tox/pypy3-test-instrumentation-flask-1/lib/pypy3.8/site-packages/pytest_benchmark/logger.py:46: PytestBenchmarkWarning: Not saving anything, no benchmarks have been run!
  warner(PytestBenchmarkWarning(text))

self = <tests.test_programmatic.TestProgrammatic testMethod=test_flask_metrics_new_semconv>

    def test_flask_metrics_new_semconv(self):
        start = default_timer()
        self.client.get("/hello/123")
        self.client.get("/hello/321")
        self.client.get("/hello/756")
        duration = max(round((default_timer() - start) * 1000), 0)
        metrics_list = self.memory_metrics_reader.get_metrics_data()
        number_data_point_seen = False
        histogram_data_point_seen = False
        self.assertTrue(len(metrics_list.resource_metrics) != 0)
        for resource_metric in metrics_list.resource_metrics:
            self.assertTrue(len(resource_metric.scope_metrics) != 0)
            for scope_metric in resource_metric.scope_metrics:
                self.assertTrue(len(scope_metric.metrics) != 0)
                for metric in scope_metric.metrics:
                    self.assertIn(metric.name, _expected_metric_names_new)
                    data_points = list(metric.data.data_points)
                    self.assertEqual(len(data_points), 1)
                    for point in data_points:
                        if isinstance(point, HistogramDataPoint):
                            self.assertEqual(point.count, 3)
>                           self.assertAlmostEqual(
                                duration, point.sum, delta=10
                            )
E                           AssertionError: 15 != 0.013619539999979224 within 10 delta (14.9863804[600](https://github.com/open-telemetry/opentelemetry-python-contrib/actions/runs/9700988497/job/26773822151?pr=2637#step:6:601)0002 difference)

@xrmx
Copy link
Contributor

xrmx commented Jun 28, 2024

@smoke fix for that here #2645

@smoke
Copy link
Contributor Author

smoke commented Jul 2, 2024

@xrmx I see #2645 is merged and all checks are passing now, I hope to see this PR merged and released sooner than later 🙌

@lzchen lzchen merged commit a29242f into open-telemetry:main Jul 2, 2024
365 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants