Describe the bug After installing 2.21.0, the CPU profile of a couple of our microservices went crazy, increasing significantly. On occasion a container running the service would start failing a large percentage of requests timing out calling downstream services and need to be terminated. Upon rolling back to 2.20.0, the performance returned to normal.

To Reproduce Steps to reproduce the behavior: Install Datadog.Tracing.Bundle 2.21.0

Expected behavior Updating to latest version should not completely break our applications.

Screenshots

Above is for an application where you can clearly see the impact of running with the impacted version. (graph is CPU utilization for the ECS service in log scale for clarity).

Runtime environment (please complete the following information):

• Instrumentation mode: Using Datadog.Tracing.Bundle to be able to use both automatic and manual instrumentation.
• Tracer version: 2.21.0
• OS: Ubuntu Linux running on ECS Docker container
• CLR: .NET 6

Additional context We originally saw this problem before switching to the bundle (we were previously downloading the .deb file and installing in the container and matching the version in code). I thought this may have been the issue based on previous issues I've encountered, so switched to using the bundle, but it was still an issue. In both services where we saw this issue, deploying a rollback of this library (and only this library) was enough to return it to a functioning state.

We might be experiencing the same issue. In our case, tracer runs fine, but if I activate code profiling, then eventually the app becomes unresponsive, however in our case CPU usage goes down to <0.5% does as like the app process is completely off, but the container keeps running. Controller methods are invoked with a minute delays leading to http client timeouts. Disabling code profiling resolves the issue...

@george-zubrienko Thanks for commenting. We also have profiling enabled on the impacted services, and your description of the behavior (long pause times) sounds extremely similar. So it does seem like this might be localized to the profiler in the latest update.

Hi @turacma @george-zubrienko is it possible to have:

• The profiler log files located in /var/log/datadog/dotnet/
• The environment variables you set up for the profiler (DD_XXX and LD_PRELOAD)
• How many managed threads do you have when the issue occurs ? do you a have graph with its evolution?

In the meantime, I'll try to reproduce it at my end.

@gleocadie this is our Dockerfile for the app in question (.NET 6). We run our apps in AKS, installed with helm 3.9.2

FROM mcr.microsoft.com/dotnet/sdk:6.0 AS build-env
ARG NUGET_TOKEN

WORKDIR /app

# Copy csproj and restore as distinct layers
COPY src/*.csproj ./
RUN dotnet nuget add source --username USERNAME --password $NUGET_TOKEN --store-password-in-clear-text --name github "https://nuget.pkg.github.com/SneaksAndData/index.json"
RUN dotnet restore

# Copy everything else and build
COPY src/. ./
RUN dotnet publish "Beast.csproj" -c Release -o out

# Build runtime image
FROM mcr.microsoft.com/dotnet/aspnet:6.0-bullseye-slim

ARG TRACER_VERSION="2.21.0"

RUN apt-get update -y && apt-get install -y curl jq

# Download and install the Tracer
RUN mkdir -p /opt/datadog \
    && mkdir -p /var/log/datadog \
    && curl -LO https://github.com/DataDog/dd-trace-dotnet/releases/download/v${TRACER_VERSION}/datadog-dotnet-apm_${TRACER_VERSION}_amd64.deb \
    && dpkg -i ./datadog-dotnet-apm_${TRACER_VERSION}_amd64.deb \
    && rm ./datadog-dotnet-apm_${TRACER_VERSION}_amd64.deb

WORKDIR /app
COPY --from=build-env /app/out .
ENTRYPOINT ["dotnet", "Beast.dll"]

we map the following on the container:

apiVersion: v1
kind: ConfigMap
metadata:
  name: {{ template "app.name" . }}-tracer
  labels:
    app.kubernetes.io/name: {{ template "app.name" . }}
    {{- include "app.labels" . | nindent 4 }}
data:
  DD_ENV: "{{ .Values.environment }}"
  DD_SERVICE: "beast"
  DD_VERSION: "{{ .Values.tag }}"
  DD_LOGS_INJECTION: "true"
  DD_APPSEC_ENABLED: "true"
  DD_TRACE_SAMPLE_RATE: "1.0"
  DD_RUNTIME_METRICS_ENABLED: "true"
  DD_PROFILING_ENABLED: "1"

and

    - name: CORECLR_ENABLE_PROFILING
      value: "1"
    - name: CORECLR_PROFILER
      value: "{846F5F1C-F9AE-4B07-969E-05C26BC060D8}"
    - name: CORECLR_PROFILER_PATH
      value: "/opt/datadog/Datadog.Trace.ClrProfiler.Native.so"
    - name: DD_DOTNET_TRACER_HOME
      value: "/opt/datadog"
    - name: DD_INTEGRATIONS
      value: "/opt/datadog/integrations.json"
    - name: LD_PRELOAD
      value: "/opt/datadog/continuousprofiler/Datadog.Linux.ApiWrapper.x64.so"

I don't have logs rn, will conjure some on test env later this week.

Problem resolves if I set DD_PROFILING_ENABLED to "0".

This makes me actually wonder if /var/log/datadog can exhaust container storage space?

This makes me actually wonder if /var/log/datadog can exhaust container storage space?

if you do not set the DD_TRACE_DEBUG env var to 1, it should be ok. By default we try to be minimal (we are way too verbose in DEBUG. Currently improving this)

How much CPU do you allocate to your container ?

And @george-zubrienko you mentioned that the CPU drops to < 0.5%. We might be in a deadlock situation in your case. Can you run this gdb command line to get the callstacks please and share the output in this issue ? gdb -p <process id> -batch -ex "thread apply all bt full" -ex "detach" -ex "quit"

@gleocadie So, from /var/log/datadog:

[2023-01-12 10:55:20.183 | info | PId: 1 | TId: 18] StackSamplerLoopManager::PerformDeadlockIntervention(): The ongoing StackSampleCollection duration crossed the threshold. A deadlock intervention was performed. Deadlocked target thread=(OsThreadId=1146,  ClrThreadId=0x7fbe94087ea0); ongoingStackSampleCollectionDurationN
s=5.19502e+08 millisecs; _isTargetThreadResumed=true; _currentPeriod=20196; _deadlocksInPeriod=1; _totalDeadlockDetectionsCount=2030; wasThreadSafeForStackSampleCollection=true; isThreadSafeForStackSampleCollection=true; threadDeadlockTotalCount=2030; threadDeadlockInAggPeriodCount=1; threadUsedDeadlocksAggPeriodIndex=201
96.
[2023-01-12 10:55:21.183 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:22.183 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:23.183 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:24.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:25.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:26.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:27.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:28.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:29.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:30.184 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:31.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:32.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:33.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:34.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:35.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:36.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:37.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:38.185 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:39.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:40.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:41.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:42.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:43.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:44.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:45.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:46.186 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:47.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:48.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:49.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:50.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:51.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:52.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:53.187 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:54.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:55.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:56.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:57.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:58.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:55:59.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:00.188 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:01.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:02.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:03.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:04.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:05.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:06.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:07.189 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:08.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:09.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:10.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:11.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:12.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:13.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:14.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:15.190 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:16.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:17.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:18.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:19.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:20.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:21.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:22.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:23.191 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-12 10:56:24.192 | info | PId: 1 | TId: 18] StackSamplerLoopManager::WatcherLoopIteration - Deadlock intervention still in progress for thread 1146 (= 0x47a)
[2023-01-05 10:36:04.626 | info | PId: 1 | TId: 1] No "DD_TRACE_DEBUG" environment variable has been found. Enable debug log = 0 (default).
[2023-01-05 10:36:04.626 | info | PId: 1 | TId: 1] DynamicDispatcherImpl::LoadConfiguration: Reading configuration file from: "/opt/datadog/loader.conf"
[2023-01-05 10:36:04.630 | info | PId: 1 | TId: 1] ICorProfilerInfo12 available. Profiling API compatibility: .NET Core 5.0 or later.
[2023-01-05 10:36:04.630 | info | PId: 1 | TId: 1] Initializing the Profiler: Reported runtime version : { clrInstanceId: 0, runtimeType:CORE_CLR, majorVersion: 6, minorVersion: 0, buildNumber: 12, qfeVersion: 0 }.
[2023-01-05 10:36:04.630 | info | PId: 1 | TId: 1] Instrumentation Verification log is disabled.
[2023-01-05 10:36:04.631 | info | PId: 1 | TId: 1] CorProfiler::Initialize: Continuous Profiler initialized successfully.
[2023-01-05 10:36:04.632 | info | PId: 1 | TId: 1] CorProfiler::Initialize: Tracer Profiler initialized successfully.
2023-01-05 10:36:04.751 +00:00 [INF] ByRef instrumentation enabled.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.783 +00:00 [INF] CallTarget State ByRef enabled.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.806 +00:00 [INF] TraceAttribute instrumentation enabled with Assembly=Datadog.Trace, Version=2.21.0.0, Culture=neutral, PublicKeyToken=def86d061d0d2eeb and Type=Datadog.Trace.ClrProfiler.AutoInstrumentation.TraceAnnotations.TraceAnnotationsIntegration.  { MachineName: ".", Process: "[1 dotnet]", AppDom
ain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.808 +00:00 [INF] [Assembly metadata] Location: /opt/datadog/net6.0/Datadog.Trace.dll, HostContext: 0, SecurityRuleSet: None  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", Tra
cerVersion: "2.21.0.0" }
2023-01-05 10:36:04.846 +00:00 [INF] Loaded library 'libddwaf.so' from '/opt/datadog' with handle '94158901868304'  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.852 +00:00 [INF] DDWAF_INFO: [ddwaf_set_log_cb]interface.cpp(266): Sending log messages to binding, min level info  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersio
n: "2.21.0.0" }
2023-01-05 10:36:04.926 +00:00 [INF] DDAS-0015-00: AppSec loaded 132 from file null.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.935 +00:00 [INF] 1 AppSec definitions and 1 AppSec derived definitions added to the profiler.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.936 +00:00 [INF] AppSec is now Enabled, _settings.Enabled is true, coming from remote config: false  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:04.974 +00:00 [INF] Using SocketHandlerRequestFactory for discovery transport, with UDS path /var/run/datadog/apm.socket.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVe
rsion: "2.21.0.0" }
2023-01-05 10:36:04.990 +00:00 [INF] Using SocketHandlerRequestFactory for trace transport, with UDS path /var/run/datadog/apm.socket.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersio
n: "2.21.0.0" }
2023-01-05 10:36:05.035 +00:00 [INF] Building automatic tracer  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.046 +00:00 [INF] Runtime id retrieved from native loader: 3345795c-233f-4b33-a8e7-4596d27dfe15  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.050 +00:00 [INF] Continuous Profiler is enabled.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.058 +00:00 [INF] Using unix domain sockets for metrics transport.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.087 +00:00 [INF] Using SocketHandlerRequestFactory for telemetry transport, with UDS path /var/run/datadog/apm.socket.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVe
rsion: "2.21.0.0" }
2023-01-05 10:36:05.500 +00:00 [INF] DATADOG TRACER CONFIGURATION - {"date":"2023-01-05T10:36:05.497019+00:00","os_name":"Linux","os_version":"Unix 5.4.0.1089","version":"2.21.0.0","platform":"x64","lang":".NET","lang_version":"6.0.12","env":"Test","enabled":true,"service":"beast","agent_url":"unix:///var/run/datadog/apm.
socket","agent_transport":"UnixDomainSocket","debug":false,"health_checks_enabled":false,"analytics_enabled":false,"sample_rate":1.0,"sampling_rules":null,"tags":[],"log_injection_enabled":true,"runtime_metrics_enabled":true,"disabled_integrations":["OpenTelemetry"],"routetemplate_resourcenames_enabled":true,"routetemplat
e_expansion_enabled":false,"querystring_reporting_enabled":true,"obfuscation_querystring_regex_timout":200.0,"partialflush_enabled":false,"partialflush_minspans":500,"runtime_id":"3345795c-233f-4b33-a8e7-4596d27dfe15","agent_reachable":true,"agent_error":"","appsec_enabled":true,"appsec_trace_rate_limit":100,"appsec_rules
_file_path":"(default)","appsec_libddwaf_version":"1.5.1","iast_enabled":false,"iast_deduplication_enabled":true,"iast_weak_hash_algorithms":"HMACMD5,MD5,HMACSHA1,SHA1","iast_weak_cipher_algorithms":"DES,TRIPLEDES,RC2","direct_logs_submission_enabled_integrations":[],"direct_logs_submission_enabled":false,"direct_logs_sub
mission_error":"","exporter_settings_warning":[],"dd_trace_methods":"","activity_listener_enabled":false,"profiler_enabled":true,"code_hotspots_enabled":true,"wcf_obfuscation_enabled":true,"data_streams_enabled":false,"span_sampling_rules":null,"stats_computation_enabled":false}  { MachineName: ".", Process: "[1 dotnet]",
 AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.518 +00:00 [INF] Initializing ServiceFabric instrumentation  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.525 +00:00 [INF] The profiler has been initialized with 312 definitions.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.548 +00:00 [INF] The profiler has been initialized with 12 derived definitions.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.548 +00:00 [INF] The profiler has been initialized with 2 interface definitions.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.549 +00:00 [INF] TraceMethods instrumentation enabled with Assembly=Datadog.Trace, Version=2.21.0.0, Culture=neutral, PublicKeyToken=def86d061d0d2eeb, Type=Datadog.Trace.ClrProfiler.AutoInstrumentation.TraceAnnotations.TraceAnnotationsIntegration, and Configuration={}.  { __2: "", MachineName: ".", Pro
cess: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.553 +00:00 [INF] Using SocketHandlerRequestFactory for rcm transport, with UDS path /var/run/datadog/apm.socket.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion:
 "2.21.0.0" }
2023-01-05 10:36:05.556 +00:00 [INF] Live Debugger is disabled. To enable it, please set DD_DYNAMIC_INSTRUMENTATION_ENABLED environment variable to 'true'.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadCont
ext #1", TracerVersion: "2.21.0.0" }
2023-01-05 10:36:05.570 +00:00 [INF] Live Debugger is disabled. To enable it, please set DD_DYNAMIC_INSTRUMENTATION_ENABLED environment variable to 'true'.  { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadCont
ext #1", TracerVersion: "2.21.0.0" }
2023-01-05 15:57:07.204 +00:00 [INF] Error sending telemetry data, unable to communicate with 'http://localhost/telemetry/proxy/api/v2/apmtelemetry to /var/run/datadog/apm.socket' System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.
 ---> System.TimeoutException: The operation was canceled.
 ---> System.Threading.Tasks.TaskCanceledException: The operation was canceled.
 ---> System.IO.IOException: Unable to read data from the transport connection: Operation canceled.
 ---> System.Net.Sockets.SocketException (125): Operation canceled
   --- End of inner exception stack trace ---
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
   at System.Net.Http.HttpConnection.InitialFillAsync(Boolean async)
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Datadog.Trace.ClrProfiler.CallTarget.Handlers.Continuations.TaskContinuationGenerator`4.SyncCallbackHandler.ContinuationAction(Task`1 previousTask, TTarget target, CallTargetState state) in /project/tracer/src/Datadog.Trace/ClrProfiler/CallTarget/Handlers/Continuations/TaskContinuationGenerator`1.cs:line 133
   at Datadog.Trace.ClrProfiler.CallTarget.Handlers.Continuations.TaskContinuationGenerator`4.SyncCallbackHandler.ContinuationAction(Task`1 previousTask, TTarget target, CallTargetState state) in /project/tracer/src/Datadog.Trace/ClrProfiler/CallTarget/Handlers/Continuations/TaskContinuationGenerator`1.cs:line 133
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpClient.HandleFailure(Exception e, Boolean telemetryStarted, HttpResponseMessage response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   at Datadog.Trace.Agent.Transports.HttpClientRequest.PostAsync(ArraySegment`1 bytes, String contentType, String contentEncoding) in /project/tracer/src/Datadog.Trace/Agent/Transports/HttpClientRequest.cs:line 100
   at Datadog.Trace.Telemetry.Transports.JsonTelemetryTransport.PushTelemetry(TelemetryData data) in /project/tracer/src/Datadog.Trace/Telemetry/Transports/JsonTelemetryTransport.cs:line 76
 { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
2023-01-06 08:19:56.996 +00:00 [INF] Error sending telemetry data, unable to communicate with 'http://localhost/telemetry/proxy/api/v2/apmtelemetry to /var/run/datadog/apm.socket' System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.
 ---> System.TimeoutException: The operation was canceled.
 ---> System.Threading.Tasks.TaskCanceledException: The operation was canceled.
 ---> System.IO.IOException: Unable to read data from the transport connection: Operation canceled.
 ---> System.Net.Sockets.SocketException (125): Operation canceled
   --- End of inner exception stack trace ---
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
   at System.Net.Http.HttpConnection.InitialFillAsync(Boolean async)
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Datadog.Trace.ClrProfiler.CallTarget.Handlers.Continuations.TaskContinuationGenerator`4.SyncCallbackHandler.ContinuationAction(Task`1 previousTask, TTarget target, CallTargetState state) in /project/tracer/src/Datadog.Trace/ClrProfiler/CallTarget/Handlers/Continuations/TaskContinuationGenerator`1.cs:line 133
   at Datadog.Trace.ClrProfiler.CallTarget.Handlers.Continuations.TaskContinuationGenerator`4.SyncCallbackHandler.ContinuationAction(Task`1 previousTask, TTarget target, CallTargetState state) in /project/tracer/src/Datadog.Trace/ClrProfiler/CallTarget/Handlers/Continuations/TaskContinuationGenerator`1.cs:line 133
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpClient.HandleFailure(Exception e, Boolean telemetryStarted, HttpResponseMessage response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   at Datadog.Trace.Agent.Transports.HttpClientRequest.PostAsync(ArraySegment`1 bytes, String contentType, String contentEncoding) in /project/tracer/src/Datadog.Trace/Agent/Transports/HttpClientRequest.cs:line 100
   at Datadog.Trace.Telemetry.Transports.JsonTelemetryTransport.PushTelemetry(TelemetryData data) in /project/tracer/src/Datadog.Trace/Telemetry/Transports/JsonTelemetryTransport.cs:line 76
 { MachineName: ".", Process: "[1 dotnet]", AppDomain: "[1 Beast]", AssemblyLoadContext: "\"\" Datadog.Trace.ClrProfiler.Managed.Loader.ManagedProfilerAssemblyLoadContext #1", TracerVersion: "2.21.0.0" }
01/05/23 10:36:04.630 AM [1|1] [info] Datadog CLR Profiler 2.21.0 on Linux (amd64)
01/05/23 10:36:04.631 AM [1|1] [info] ProcessName: dotnet
01/05/23 10:36:04.631 AM [1|1] [info] Process CommandLine: dotnet Beast.dll
01/05/23 10:36:04.631 AM [1|1] [info] Environment variables:
01/05/23 10:36:04.631 AM [1|1] [info]   DD_DOTNET_TRACER_HOME=/opt/datadog
01/05/23 10:36:04.631 AM [1|1] [info]   DD_ENV=Test
01/05/23 10:36:04.631 AM [1|1] [info]   DD_SERVICE=beast
01/05/23 10:36:04.631 AM [1|1] [info]   DD_VERSION=v2.3.1-1-g3ccf247
01/05/23 10:36:04.631 AM [1|1] [info] Runtime Information: .NET 6.0.12
01/05/23 10:36:04.631 AM [1|1] [info] JIT Inlining is enabled.
01/05/23 10:36:04.631 AM [1|1] [info] NGEN is enabled.
01/05/23 10:36:04.631 AM [1|21] [info] Initializing ReJIT request thread.
01/05/23 10:36:04.631 AM [1|1] [info] Profiler filepath: /opt/datadog/./linux-x64/Datadog.Tracer.Native.so
01/05/23 10:36:04.631 AM [1|1] [info] Profiler attached.
01/05/23 10:36:04.639 AM [1|1] [info] COR library: System.Private.CoreLib 6.0.0
01/05/23 10:36:04.658 AM [1|1] [info] JITCompilationStarted: Startup hook registered in function_id=140457185415504 token=100663301 name=Beast.Program.Main(), assembly_name=Beast app_domain_id=94158884919440 domain_neutral=0
01/05/23 10:36:04.664 AM [1|1] [info] ModuleLoadFinished: Datadog.Trace.ClrProfiler.Managed.Loader loaded into AppDomain 94158884919440 clrhost
01/05/23 10:36:04.698 AM [1|1] [info] ModuleLoadFinished: Datadog.Trace v2.21.0.0 - Fix PInvoke maps
01/05/23 10:36:04.698 AM [1|1] [info] Rewriting PInvokes to native: /opt/datadog/./linux-x64/Datadog.Tracer.Native.so
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: IsProfilerAttached
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: InitializeProfiler
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: RemoveCallTargetDefinitions
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: EnableByRefInstrumentation
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: EnableCallTargetStateByRef
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: AddDerivedInstrumentations
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: AddInterfaceInstrumentations
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: AddTraceAttributeInstrumentation
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: InitializeTraceMethods
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: DisableTracerCLRProfiler
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvokes to native: /opt/datadog/./linux-x64/Datadog.Tracer.Native.so
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: dddlopen
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: dddlerror
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: dddlsym
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvokes to native: /opt/datadog/./linux-x64/Datadog.Tracer.Native.so
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: InstrumentProbes
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: GetProbesStatuses
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvokes to native: /opt/datadog/Datadog.Trace.ClrProfiler.Native.so
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: GetRuntimeIdFromNative
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvokes to native: /opt/datadog/./linux-x64/Datadog.Profiler.Native.so
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: GetProfilerStatusPointer
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: GetTraceContextNativePointer
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: SetApplicationInfoForAppDomain
01/05/23 10:36:04.700 AM [1|1] [info] Rewriting PInvoke method: SetEndpoint
01/05/23 10:36:04.704 AM [1|1] [info] Successfully added method DistributedTracer.__GetInstanceForProfiler__ for ModuleID=140457188146664
01/05/23 10:36:04.705 AM [1|1] [info] AssemblyLoadFinished: Datadog.Trace.dll v2.21.0.0 matched profiler version v2.21.0.0
01/05/23 10:36:04.750 AM [1|1] [info] ByRef Instrumentation enabled.
01/05/23 10:36:04.783 AM [1|1] [info] CallTargetState ByRef enabled.
01/05/23 10:36:04.805 AM [1|1] [info] AddTraceAttributeInstrumentation: Initialized assembly=Datadog.Trace, Version=2.21.0.0, Culture=neutral, PublicKeyToken=def86d061d0d2eeb, type=Datadog.Trace.ClrProfiler.AutoInstrumentation.TraceAnnotations.TraceAnnotationsIntegration
01/05/23 10:36:04.934 AM [1|1] [info] InitializeProfiler: received id: 8A0651DE92625A7EF3E2BBF32F0D2048 from managed side with 1 integrations.
01/05/23 10:36:04.934 AM [1|1] [info] Total number of modules to analyze: 13
01/05/23 10:36:04.934 AM [1|1] [info] InitializeProfiler: Total integrations in profiler: 1
01/05/23 10:36:04.934 AM [1|1] [info] InitializeProfiler: received id: 02043D9EE45819725C08A53565EFDB14 from managed side with 1 integrations.
01/05/23 10:36:04.935 AM [1|1] [info] Total number of modules to analyze: 13
01/05/23 10:36:04.935 AM [1|1] [info] InitializeProfiler: Total integrations in profiler: 2
01/05/23 10:36:05.520 AM [1|1] [info] InitializeProfiler: received id: FFAFA5168C4F4718B40CA8788875C2DA from managed side with 312 integrations.
01/05/23 10:36:05.520 AM [1|1] [info] Total number of modules to analyze: 19
01/05/23 10:36:05.521 AM [1|21] [info] ReJIT handler stored metadata for 140457185609480 Serilog AppDomain 94158884919440 clrhost
01/05/23 10:36:05.521 AM [1|21] [info] ReJIT handler stored metadata for 140457186893208 System.Diagnostics.Process AppDomain 94158884919440 clrhost
01/05/23 10:36:05.523 AM [1|21] [info] ReJIT handler stored metadata for 140457203742128 System.Net.Http AppDomain 94158884919440 clrhost
01/05/23 10:36:05.524 AM [1|21] [info] ReJIT handler stored metadata for 140457210378536 System.Data.Common AppDomain 94158884919440 clrhost
01/05/23 10:36:05.525 AM [1|21] [info] Request ReJIT done for 10 methods
01/05/23 10:36:05.525 AM [1|1] [info] InitializeProfiler: Total integrations in profiler: 314
01/05/23 10:36:05.525 AM [1|1] [info] NGEN:: Processed with 1 inliners [ModuleId=140457203742128,MethodDef=100663918]
01/05/23 10:36:05.525 AM [1|21] [info] Request ReJIT done for 1 methods
01/05/23 10:36:05.525 AM [1|1] [info] AddDerivedInstrumentations: received id: 61BF627FA9B5477F85595A9F0D68B29C from managed side with 12 integrations.
01/05/23 10:36:05.526 AM [1|1] [info] Total number of modules to analyze: 19
01/05/23 10:36:05.548 AM [1|1] [info] InitializeProfiler: Total integrations in profiler: 326
01/05/23 10:36:05.548 AM [1|1] [info] AddInterfaceInstrumentations: received id: 6410E14A2A2343BABBB45940190E1C3F from managed side with 2 integrations.
01/05/23 10:36:05.548 AM [1|1] [info] Total number of modules to analyze: 19
01/05/23 10:36:05.548 AM [1|1] [info] InitializeProfiler: Total integrations in profiler: 328
01/05/23 10:36:05.556 AM [1|1] [info] *** CallTarget_RewriterCallback() Finished: Serilog.LoggerConfiguration.CreateLogger() [IsVoid=0, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.Logging.Serilog.DirectSubmission.LoggerConfigurationInstrumentation, Arguments=0]
01/05/23 10:36:05.619 AM [1|1] [info] *** CallTarget_RewriterCallback() Finished: Serilog.Core.Logger.Dispatch() [IsVoid=1, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.Logging.Serilog.LogsInjection.LoggerDispatchInstrumentation, Arguments=1]
01/05/23 10:36:05.638 AM [1|1] [info] ReJIT handler stored metadata for 140457227965296 Microsoft.Extensions.Logging AppDomain 94158884919440 clrhost
01/05/23 10:36:05.638 AM [1|21] [info] Request ReJIT done for 2 methods
01/05/23 10:36:05.652 AM [1|1] [info] ReJIT handler stored metadata for 140457236639360 Microsoft.AspNetCore.Mvc.Core AppDomain 94158884919440 clrhost
01/05/23 10:36:05.652 AM [1|21] [info] Request ReJIT done for 2 methods
01/05/23 10:36:05.694 AM [1|1] [info] ReJIT handler stored metadata for 140457243145704 Microsoft.Extensions.Logging.Abstractions AppDomain 94158884919440 clrhost
01/05/23 10:36:05.694 AM [1|21] [info] Request ReJIT done for 1 methods
01/05/23 10:36:05.701 AM [1|1] [info] ReJIT handler stored metadata for 140457245053200 Microsoft.AspNetCore.Http AppDomain 94158884919440 clrhost
01/05/23 10:36:05.701 AM [1|21] [info] Request ReJIT done for 1 methods
01/05/23 10:36:05.885 AM [1|37] [info] *** CallTarget_RewriterCallback() Finished: System.Net.Http.HttpClientHandler.SendAsync() [IsVoid=0, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.Http.HttpClient.HttpClientHandler.HttpClientHandlerIntegration, Arguments=2]
01/05/23 10:36:05.965 AM [1|37] [info] *** CallTarget_RewriterCallback() Finished: System.Net.Http.SocketsHttpHandler.SendAsync() [IsVoid=0, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.Http.HttpClient.SocketsHttpHandler.SocketsHttpHandlerIntegration, Arguments=2]
01/05/23 10:36:06.905 AM [1|1] [info] *** CallTarget_RewriterCallback() Finished: Microsoft.AspNetCore.Builder.ApplicationBuilder.Build() [IsVoid=0, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.AspNetCore.AspNetCoreBlockMiddlewareIntegrationEnd, Arguments=0]
01/05/23 10:45:35.686 AM [1|94] [info] *** CallTarget_RewriterCallback() Finished: Microsoft.AspNetCore.Mvc.ModelBinding.DefaultModelBindingContext.set_Result() [IsVoid=1, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.AspNetCore.DefaultModelBindingContext_SetResult_Integration, Arguments=1]
01/05/23 10:45:35.734 AM [1|101] [info] *** CallTarget_RewriterCallback() Finished: System.Net.Http.SocketsHttpHandler.Send() [IsVoid=0, IsStatic=0, IntegrationType=Datadog.Trace.ClrProfiler.AutoInstrumentation.Http.HttpClient.SocketsHttpHandler.SocketsHttpHandlerSyncIntegration, Arguments=2]
01/05/23 03:57:07.202 PM [1|423] [info] ReJIT handler stored metadata for 140457299087808 System.Net.Requests AppDomain 94158884919440 clrhost
01/05/23 03:57:07.203 PM [1|21] [info] Request ReJIT done for 4 methods

from one of the affected instances

re CPU, here are the specs

      resources:
        limits:
          cpu: 1500m
          memory: 2000Mi
        requests:
          cpu: 1500m
          memory: 2000Mi

for gdb command i get ptrace: operation not permitted - i guess i need to launch container in some privileged mode?

for gdb command i get ptrace: operation not permitted - i guess i need to launch container in some privileged mode?

:/ it can be that (I tested on a bare metal linux with a privileged user) gdb -p <process id> -batch -ex "thread apply all bt full" -ex "detach" -ex "quit" As I suspected, the profiler hit a new deadlock case. Having the callstack from the gdb command above would help us in fixing.

i'll get it out tomorrow for you, no problem :)

i'll get it out tomorrow for you, no problem :)

Thanks so much for the report.

sorry got a bit carried away by other stuff, i'll get gdb output tomorrow

@george-zubrienko no pb. That will be helpful

So this is the gdb output from a process that doesn't yet have the issue with profiler DISABLED, tracer ENABLED (see below). I'll enable it now and send an update when the issue reproduces

@gleocadie this is gdb output from the stuck app:

gbd.txt

@george-zubrienko It looks like the malloc-deadlock I managed to reproduce on my end and fixed in the 2.22. Can you try it out and give me feedback please ? Do not hesitate to run the gdb command-line if the application is still stuck. Thanks in advance.

will try out this week, thanks a lot!

will try out this week, thanks a lot!

Did you have a chance to try it out ?

@gleocadie we've rolled out 2.22 on some installations, but i didn't yet try running code profiling for >1h. I'll set up a guy on test now and let you know on Monday if we had any issues.

@gleocadie I think the issue with code profiler is fixed, but it seems there is another one.

With 2.22 tracer we see issues with Akka.Streams library we rely on. Adding throttling to the stream with 2.22 profiler causes throttling to go completely sideways - zero cpu activity and elements get picked from the buffer with minutes/element when throttling is set to seconds/element. With 2.21 this is not the case.

This is a bit more tricky to spot, because throttling only happens under certain conditions. Do I run the gdb command, when the app is under load, or there is some way to investigate post-mortem?

@gleocadie circling back on my previous statement - 2.22 fixes the issue and doesn't introduce new problems. I think the issue in question is resolved 👍

hey, just wanted to pitch in.

The fix in 2.22 didn't really help us, and setting DD_PROFILING_ENABLED to 0 doesn't fix it for us. We're using the datadog extension for azure app services v2.22.0 and instrumenting a .net framework 4.7.2 web app with the same version.

Everything works fine until it doesn't. Same behaviour, requests come in but are never processed. We have a previous App dump that we didn't detect and might be useful.

========================================================
 Dump Analysis for <redacted>
 ========================================================
Below is the list of all the threads active in the process
{
  "CallStack": [
    "ntdll!NtDelayExecution+0xc",
    "KERNELBASE!SleepEx+0x8a",
    "clr!EESleepEx+0x52",
    "clr!CExecutionEngine::ClrSleepEx+0xe",
    "clr!ClrSleepEx+0x1d",
    "clr!Thread::UserSleep+0xbb",
    "clr!CRWLock::StaticAcquireReaderLock+0x1ae",
    "clr!CRWLock::StaticAcquireReaderLockPublic+0x8f",
    "Datadog.Trace.AppSec.Concurrency.ReaderWriterLock.EnterReadLock()",
    "Datadog.Trace.AppSec.Waf.Context.GetContext(IntPtr, Datadog.Trace.AppSec.Waf.Waf, Datadog.Trace.AppSec.Concurrency.ReaderWriterLock, Datadog.Trace.AppSec.Waf.NativeBindings.WafLibraryInvoker)",
    "Datadog.Trace.AppSec.Waf.Waf.CreateContext(Datadog.Trace.AppSec.Concurrency.ReaderWriterLock)",
    "Datadog.Trace.AppSec.Coordinator.SecurityCoordinator.RunWaf(System.Collections.Generic.Dictionary`2<System.String,System.Object>)",
    "Datadog.Trace.AppSec.Coordinator.SecurityCoordinator.CheckAndBlock(System.Collections.Generic.Dictionary`2<System.String,System.Object>)",
    "Datadog.Trace.AspNet.TracingHttpModule.OnEndRequest(System.Object, System.EventArgs)",
    "System.Web.HttpApplication+SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()",
    "System.Web.HttpApplication+<>c__DisplayClass285_0.<ExecuteStepImpl>b__0()",
    "System.Web.HttpApplication+StepInvoker.Invoke(System.Action)",
    "System.Web.HttpApplication+StepInvoker+<>c__DisplayClass4_0.<Invoke>b__0()",
    "System.Web.HttpApplication+<>c__DisplayClass284_0.<OnExecuteRequestStep>b__0(System.Action)",
    "System.Web.HttpApplication+StepInvoker.Invoke(System.Action)",
    "System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep)",
    "System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)",
    "System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)",
    "System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)",
    "System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)",
    "System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)",
    "System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)",
    "webengine4!W3_MGD_HANDLER::ProcessNotification+0x62",
    "webengine4!W3_MGD_HANDLER::DoWork+0x32a",
    "webengine4!RequestDoWork+0x3a7",
    "webengine4!CMgdEngHttpModule::OnEndRequest+0x18",
    "iiscore!NOTIFICATION_CONTEXT::RequestDoWork+0x2e3",
    "iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+0x4af",
    "iiscore!NOTIFICATION_CONTEXT::CallModules+0x2b",
    "iiscore!NOTIFICATION_MAIN::DoWork+0x105",
    "iiscore!W3_CONTEXT_BASE::ContinueNotificationLoop+0x32",
    "iiscore!W3_CONTEXT_BASE::IndicateCompletion+0xa0",
    "webengine4!W3_MGD_HANDLER::IndicateCompletion+0x45",
    "webengine4!MgdIndicateCompletion+0x22",
    "DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)",
    "System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)",
    "System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)",
    "clr!UM2MThunk_Wrapper+0x76",
    "clr!Thread::DoADCallBack+0xbc",
    "clr!UM2MDoADCallBack+0x92",
    "webengine4!W3_MGD_HANDLER::ProcessNotification+0x62",
    "webengine4!ProcessNotificationCallback+0x33",
    "picohelper!DllMain+0x6c26",
    "clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x1a4",
    "clr!ThreadpoolMgr::ExecuteWorkRequest+0x4f",
    "clr!ThreadpoolMgr::WorkerThreadStart+0x36c",
    "clr!Thread::intermediateThreadProc+0x58",
    "kernel32!BaseThreadInitThunk+0x24",
    "ntdll!__RtlUserThreadStart+0x2f",
    "ntdll!_RtlUserThreadStart+0x1b"
  ],
  "Count": 461

After typing it I just noticed the AppSec namespace, seems to be an application security issue? if so is there a relevant flag I can add as well or some documentation that can point me to the direction of not having this happen in production and restore my happiness and sleep schedule? Many thanks 🙏

@george-zubrienko I'm glad to hear that. I was defining a strategy to investigate :) out of curiosity, was it something in your code? machine? option enabled from our side ?

If anything happen new, do not hesitate.

@Recio Yeah the fix in 2.22 was for a deadlock on linux. Can you try check if DD_APSEC_ENABLED is not set or at least set to 0 ? This should not be enabled by default. I hope it will restore your happiness and sleep schedule :)

@gleocadie yap, already removed that setting, hoping that this doesn't happen again anytime soon, these past 2 weeks have been kind of crazy 🥴

In regards to getting this fixed (since this seems to be the same issue but triggered by different code(?)) should I open another ticket?

@Recio I think that would be great if you can open a new ticket. I pinged someone from the ASM team to look at this.

I'm glad to hear that. I was defining a strategy to investigate :) out of curiosity, was it something in your code? machine? option enabled from our side ?

@gleocadie it was just a bug in our code this time. Tracer actually helped to narrow down the possible causes :) thank you again!