Missing Code Level Tracing

[DeanLangford]

I'm trying to get code-level tracing working using either setup option:

• Option 1: AUTOWRAPT_BOOTSTRAP=autodynatrace
• Option 2: import autodynatrace + @autodynatrace.trace annotation on main()

Working through Dynatrace support via in-product chat, I was asked to post the issue here instead. Support Ticket #128811.

After dropping down to the oneagent package instead of the autodynatrace package, and adding some additional debug statements, I verified that the agent is loading correctly:

...
Agent init:  InitResult(status=InitResult.STATUS_ALREADY_INITIALIZED, error=None)
Agent state: 0
Agent found: True
Agent is compatible: True
Agent version: 1.257.240.20230127-171125/1.7.1
...

The above is with autodynatrace not being used. Before doing that, I was seeing this, which leads me to think that autodynatrace was also loading the agent, as expected:

WARNING autodynatrace - init: Could not initialize the OneAgent SDK, AgentState: 1

I also added some additional logging by increasing the logging level:

...
[D 230201 16:34:24 __init__:252] initialize: ref count = 0
[I 230201 16:34:24 __init__:275] Initializing SDK on Python=3.8.16 (default, Jan 24 2023, 00:12:41)   [GCC 10.2.1 20210110] with options=['loglevelsdk=finest
[I 230201 16:34:24 sdkctypesiface:808] Loading native SDK library "/usr/local/lib/python3.8/site-packages/oneagent/_impl/native/libonesdk_shared.so".
[I 230201 16:34:24 sdkctypesiface:221] Native SDK library "/usr/local/lib/python3.8/site-packages/oneagent/_impl/native/libonesdk_shared.so" version 1.7.1 lo
2023-02-01 16:34:24.290 UTC [a37f28e2] info    [onesdk] Initializing Dynatrace OneAgent SDK for C/C++ ...
2023-02-01 16:34:24.290 UTC [a37f28e2] info    [onesdk] SDK stub version 1.7.1.1, build date 2022.12.15 10:27:48.
2023-02-01 16:34:24.290 UTC [a37f28e2] fine    [onesdk] Preparing arguments...
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]   Options:
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]     Agent active:  true
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]     Agent module:  ''
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]     SDK log level: finest
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]   Additional options:
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]     loglevel=finest
2023-02-01 16:34:24.290 UTC [a37f28e2] config  [onesdk]     ONESDK_INTERNAL_CA627667445C40F0_INIT_FLAGS=0
2023-02-01 16:34:24.290 UTC [a37f28e2] fine    [onesdk] Loading agent module...
2023-02-01 16:34:24.308 UTC [a37f28e2] fine    [onesdk] Loaded agent module provided by process agent.
2023-02-01 16:34:24.308 UTC [a37f28e2] fine    [onesdk] Initializing agent module...
2023-02-01 16:34:26.482 UTC [a37f28e2] info    [onesdk] Loaded agent module version: 1.257.240.20230127-171125
2023-02-01 16:34:26.482 UTC [a37f28e2] info    [onesdk] Dynatrace OneAgent SDK for C/C++ agent module loaded successfully.
2023-02-01 16:34:26.482 UTC [a37f28e2] fine    [onesdk] Initializing agent...
2023-02-01 16:34:26.482 UTC [a37f28e2] info    [onesdk] Loaded extension API metrics.
2023-02-01 16:34:28.632 UTC [a37f28e2] info    [onesdk] Dynatrace OneAgent SDK for C/C++ initialized successfully.
2023-02-01 16:34:28.632 UTC [a37f28e2] info    [onesdk] Loaded extension API techtype.
[D 230201 16:34:28 __init__:298] initialize successful, adding tech types...
[D 230201 16:34:28 __init__:302] tech type reporting complete
...

Sample code being used:

import oneagent
from logzero import logger

def main():
    fake_long_running_process()

if __name__ == "__main__":
    oneagent.logger = logger
    oneagent.logger.setLevel(1)
    print("Agent init: ", oneagent.initialize(["loglevelsdk=finest", "loglevel=finest"]))
    # The agent state is one of the integers in oneagent.sdk.AgentState.
    print("Agent state:", oneagent.get_sdk().agent_state)

    # The instance attribute 'agent_found' indicates whether an agent could be found or not.
    print("Agent found:", oneagent.get_sdk().agent_found)

    # If an agent was found but it is incompatible with this version of the SDK for Python
    # then 'agent_is_compatible' would be set to false.
    print("Agent is compatible:", oneagent.get_sdk().agent_is_compatible)

    # The agent version is a string holding both the OneAgent version and the
    # OneAgent SDK for C/C++ version separated by a '/'.
    print("Agent version:", oneagent.get_sdk().agent_version_string)

    with oneagent.get_sdk().trace_custom_service('main', 'test'):
        main()

I don't see any code-level Python traces using this minimal setup.

Related: I found this issue which looks similar, where version 1.257 was also mentioned and 1.258 resolved it: https://github.com/dynatrace-oss/OneAgent-SDK-Python-AutoInstrumentation/issues/64.

[DeanLangford]

Additional debug info. I added autodynatrace back into the application and set AUTODYNATRACE_LOG_LEVEL=True. This provided additional information:

...
2023-02-01 20:58:43,978: 1 DEBUG autodynatrace - init: Initialized autodynatrace with AgentState: 0
2023-02-01 20:58:43,982: 1 DEBUG autodynatrace - instrument_lib: Attempting to instrument urllib
2023-02-01 20:58:44,002: 1 DEBUG autodynatrace - instrument_lib: Attempting to instrument subprocess
2023-02-01 20:58:44,004: 1 INFO autodynatrace - instrument: Instrumented 2/23 libraries (subprocess, urllib). Will instrument when imported: (aiohttp, bottle, celery, conflu
2023-02-01 20:58:44,016: 1 DEBUG autodynatrace - dynatrace_trace: Tracing subprocess.check_output
2023-02-01 20:58:44,016: 1 DEBUG autodynatrace - dynatrace_trace: Tracing subprocess.run
2023-02-01 20:58:44,016: 1 DEBUG autodynatrace - dynatrace_trace: Tracing subprocess.Popen
2023-02-01 20:58:44,726: 1 DEBUG autodynatrace - on_import: Instrumenting imported lib 'sqlalchemy'
2023-02-01 20:58:45,618: 1 DEBUG autodynatrace - on_import: Instrumenting imported lib 'paramiko'
[D 230201 20:58:46 __init__:252] initialize: ref count = 1
[D 230201 20:58:46 __init__:265] Attempt to re-initialize agent with options=['loglevelsdk=finest', 'loglevel=finest'], libname=None only increases reference count.
2023-02-01 20:58:46,294: 1 DEBUG autodynatrace - wrapper: Custom tracing - axis-linker-dev: __main__.main
2023-02-01 20:58:46,295: 1 DEBUG autodynatrace - dynatrace_trace: Tracing subprocess.Popen
2023-02-01 20:58:46,575: 1 DEBUG autodynatrace - dynatrace_putrequest: Tracing urllib, url: '<REDACTED>', tag: 'b'FW4;219149364;1;1861374877;1;0;45
Agent init:  InitResult(status=InitResult.STATUS_ALREADY_INITIALIZED, error=None)
Agent state: 0
Agent found: True
Agent is compatible: True
Agent version: 1.257.240.20230127-171125/1.7.1
...

💡 Also, I did find a Service called __main__ in Dynatrace. I had overlooked that earlier because I was filtering on a specific Management Zone.

❓Does that mean I have to add the @autodynatrace.trace annotation to every method I was to trace? Is there a way to do that at a higher lever: class, module, or even package?

[Oberon00]

The SDK here does not do any tracing automatically, you have to manually use tracers, or develop the automation yourself (e.g. using Pythons monkey patching capabilities). However, since most tracers here create full services, not only code-level nodes, it may be a bit too heavyweight to trace everything. It is usually better to only trace operations of particular interest. The SDK has no support for code-level-only nodes.

For the autodynatrace question I defer to @dlopes7.

[DeanLangford]

Thanks @Oberon00. I started using openTelemetry-instrumentation and some of its plugins directly (because I happen to not be using any of the auto instrumented technologies that this package handles) since the time I created this "issue" and have manually traced a few, key entry points.

I'm closing this issue since it appears to be expected behavior and not a "bug" as I first thought. Thanks, again!