See trace (as multi-line string) if a test fails

[guettli]

I am new to opentelemetry. Can it help in this use case?

I have a flaky test which failure is not reproducible for me.

def test_bar():
    ...
    foo = bar(blue)
    assert foo == 'sunshine'

Up to now I only see a meaningless error message of the test fails.

like moonlight != sunshine

I would like to trace bar() every time it is called in the test.

If the assertion fails, then I want to see the trace as text.

The trace should contain all lines which get executed by bar() (excluding Python stdlib).

Maybe something like this:

def test_bar():
    ...
    tracer = SomeTracer()
    foo = tracer.call(bar, blue)
    assert foo == 'sunshine', tracer.trace_to_text()

Can opentelemetry-python provide something like SomeTracer and trace_to_text()?

I am using pytest.

AFAIK I am forced to the constrained text output.

[ocelotl]

Hello @guettli ✌️

I would suggest using this example as inspiration.

Maybe something like this would work for you?

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
    BatchSpanProcessor,
    ConsoleSpanExporter,
)


trace.set_tracer_provider(TracerProvider())
trace.get_tracer_provider().add_span_processor(
    BatchSpanProcessor(ConsoleSpanExporter())
)
tracer = trace.get_tracer(__name__)


def test_bar():

    def bar(color):
        if color == "blue":
            return "sunshine"

        return "moonlight"

    def call_bar(color):
        with tracer.start_as_current_span("test"):
            assert bar(color) == "sunshine"

    call_bar("blue")
    call_bar("blue")
    call_bar("red")

I saved this code in a file named test_bar.py, ran it with pytest test_bar.py -s and got this result:

============================= test session starts ==============================
platform linux -- Python 3.9.5, pytest-6.2.4, py-1.10.0, pluggy-0.13.1 -- /home/ocelotl/.pyenv/versions/3.9.5/bin/python3.9
cachedir: .pytest_cache
rootdir: /home/ocelotl/github/ocelotl/opentelemetry-python, configfile: pyproject.toml
collecting ... collected 1 item

test_bar.py::test_bar FAILED

=================================== FAILURES ===================================
___________________________________ test_bar ___________________________________

    def test_bar():
    
        def bar(color):
            if color == "blue":
                return "sunshine"
    
            return "moonlight"
    
        def call_bar(color):
            with tracer.start_as_current_span("test"):
                assert bar(color) == "sunshine"
    
        call_bar("blue")
        call_bar("blue")
>       call_bar("red")

test_bar.py:44: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

color = 'red'

    def call_bar(color):
        with tracer.start_as_current_span("test"):
>           assert bar(color) == "sunshine"
E           AssertionError: assert 'moonlight' == 'sunshine'
E             - sunshine
E             + moonlight

test_bar.py:40: AssertionError
============================== 1 failed in 0.11s ===============================
{
    "name": "test",
    "context": {
        "trace_id": "0x2eef039cf05752fee7a6e8027abce1f3",
        "span_id": "0xa38def53755d7bae",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2021-07-09T21:15:01.983042Z",
    "end_time": "2021-07-09T21:15:01.983059Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {},
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.3.0",
        "service.name": "unknown_service"
    }
}
{
    "name": "test",
    "context": {
        "trace_id": "0x4c1e9c9df6ca660306da7c2222dbca57",
        "span_id": "0xc1c319bc6d491110",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2021-07-09T21:15:01.983104Z",
    "end_time": "2021-07-09T21:15:01.983115Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {},
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.3.0",
        "service.name": "unknown_service"
    }
}
{
    "name": "test",
    "context": {
        "trace_id": "0xf33ebf8875734bf3f8b97123d75d04a5",
        "span_id": "0x139ca9c599943275",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2021-07-09T21:15:01.983151Z",
    "end_time": "2021-07-09T21:15:01.984384Z",
    "status": {
        "status_code": "ERROR",
        "description": "AssertionError: assert 'moonlight' == 'sunshine'\n  - sunshine\n  + moonlight"
    },
    "attributes": {},
    "events": [
        {
            "name": "exception",
            "timestamp": "2021-07-09T21:15:01.984369Z",
            "attributes": {
                "exception.type": "AssertionError",
                "exception.message": "assert 'moonlight' == 'sunshine'\n  - sunshine\n  + moonlight",
                "exception.stacktrace": "Traceback (most recent call last):\n  File \"/home/ocelotl/.pyenv/versions/3.9.5/lib/python3.9/site-packages/opentelemetry/trace/__init__.py\", line 522, in use_span\n    yield span\n  File \"/home/ocelotl/.pyenv/versions/3.9.5/lib/python3.9/site-packages/opentelemetry/sdk/trace/__init__.py\", line 923, in start_as_current_span\n    yield span_context\n  File \"/home/ocelotl/github/ocelotl/opentelemetry-python/docs/examples/basic_tracer/test_bar.py\", line 40, in call_bar\n    assert bar(color) == \"sunshine\"\nAssertionError: assert 'moonlight' == 'sunshine'\n  - sunshine\n  + moonlight\n",
                "exception.escaped": "False"
            }
        }
    ],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.3.0",
        "service.name": "unknown_service"
    }
}

[guettli]

Maybe I am blind, but what I would like to see is the trace of bar("red"). I would like to see every line which got executing during bar("red").

Is there a way to get this?

[ocelotl]

Hmm, now I am not sure OpenTelemetry is meant for what you are trying to do...
I think I don't really understand what you mean with see every line which got executing during bar("red").

Maybe you have already tried this, but to see how code gets executed line by line the usual tool is the pdb debugger.

[guettli]

I read:

OpenTelemetry is a collection of tools, APIs, and SDKs. You can use it to instrument, generate, collect, and export telemetry data (metrics, logs, and traces) for analysis in order to understand your software's performance and behavior.

So I thought OpenTelemetry can give me a trace which shows every line which the interpreter executed. Sorry, if I misunderstood this.

[srikanthccv]

You probably want something like https://docs.python.org/3/library/trace.html, https://github.com/ionelmc/python-hunter or something similar but open telemetry is not the right tool for you to trace program line by line.