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.

Sign up for GitHub

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

Jump to bottom

SQL client instrumentation does not deliver any traces - how to debug? #1797

Closed
Sam13 opened this issue Feb 23, 2022 · 4 comments
Closed

SQL client instrumentation does not deliver any traces - how to debug? #1797

Sam13 opened this issue Feb 23, 2022 · 4 comments
Labels
comp:instrumentation.sqlclient Things related to OpenTelemetry.Instrumentation.SqlClient question Further information is requested

Comments

@Sam13
Copy link

Sam13 commented Feb 23, 2022

Question

I have instrumented an ASP.NET core microservice with OpenTelemetry (ASP.NET core, HTTP client, SQL client instrumentations).
Everything works well except that SQL client instrumentation does not deliver any tracing data (other instrumentations do).
This only happens if I deploy the service into a K8s cluster, I cannot reproduce it locally with the same Docker image.

For basic troubleshooting I instrumented my microservice as described here: https://github.com/open-telemetry/opentelemetry-dotnet/tree/main/src/OpenTelemetry#troubleshooting - log level: LogAlways

The log I get is the following:

2022-02-23T10:12:27.3353767Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-ec584e9e6f41730b9452d364b907606b-e2bd88d346cf95d2-00}
2022-02-23T10:12:27.3377486Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-ec584e9e6f41730b9452d364b907606b-e2bd88d346cf95d2-00}
2022-02-23T10:12:29.3529690Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-21f6f0a185f8c44b0a2301c7e344df6f-5168202cad3e9281-01}
2022-02-23T10:12:29.3535602Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-21f6f0a185f8c44b0a2301c7e344df6f-5168202cad3e9281-01}
2022-02-23T10:12:30.0946298Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-e411659c77ed556ba3480c6979b54421-646d410e965fba25-01}
2022-02-23T10:12:30.0998655Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-e411659c77ed556ba3480c6979b54421-646d410e965fba25-01}
2022-02-23T10:12:31.9948133Z:Activity started. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-f268b69b425e25878ab98e7d6073533d-94d53018ba882ee3-00}
2022-02-23T10:12:31.9966433Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-f268b69b425e25878ab98e7d6073533d-94d53018ba882ee3-00}
2022-02-23T10:12:34.5267498Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-2987e14086678c4333c3f82c36f84dfc-58447bde008e70a3-00}
2022-02-23T10:12:34.5291432Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-2987e14086678c4333c3f82c36f84dfc-58447bde008e70a3-00}
2022-02-23T10:12:41.8389466Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-3604e47143729a3df554c808b966b701-534e694557f1ab70-00}
2022-02-23T10:12:41.8408480Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-3604e47143729a3df554c808b966b701-534e694557f1ab70-00}
2022-02-23T10:12:47.3283338Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-562095ace72700de0ee40c2da24f1a47-c99145569366be94-00}
2022-02-23T10:12:47.3286127Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-562095ace72700de0ee40c2da24f1a47-c99145569366be94-00}
2022-02-23T10:12:49.3543815Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-90b07eed582fa4e92a6da2149a239024-5146955aa7f43468-01}
2022-02-23T10:12:49.3547137Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-90b07eed582fa4e92a6da2149a239024-5146955aa7f43468-01}
2022-02-23T10:12:51.9976091Z:Activity started. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-f06007baf72bef1fa5ea25679373f83a-2324ae4b1da7a6d5-00}
2022-02-23T10:12:52.0005320Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-f06007baf72bef1fa5ea25679373f83a-2324ae4b1da7a6d5-00}
2022-02-23T10:12:54.5289178Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-e3173fc53707f059f0df7efcd541142b-7b9ae735f9cd2ac6-00}
2022-02-23T10:12:54.5311142Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-e3173fc53707f059f0df7efcd541142b-7b9ae735f9cd2ac6-00}

When I do the same in a local environment I get the following:

2022-02-23T12:05:39.3576381Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-93b4ab3b63b834b219879e754771e83a-4c531c10f92fb08e-01}
2022-02-23T12:05:39.5055319Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-0cb5ad2ffb0c7176e9b127c1edbf14a1-35187061c2b63237-00}
2022-02-23T12:05:39.6557002Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-0cb5ad2ffb0c7176e9b127c1edbf14a1-35187061c2b63237-01}
2022-02-23T12:05:43.8117782Z:Activity started. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-3000aa160422587a25da8e4ee532b298-f05e6beb06d1a4e7-00}
2022-02-23T12:05:43.8929861Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-3000aa160422587a25da8e4ee532b298-f05e6beb06d1a4e7-00}
2022-02-23T12:05:50.1431527Z:Activity started. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-520b840e8a29c2bbfeb2d7aba078a8f8-02e485ab652cd3b9-00}
2022-02-23T12:05:50.4294962Z:Activity started. OperationName = '{0}', Id = '{1}'.{OpenTelemetry.SqlClient.Execute}{00-520b840e8a29c2bbfeb2d7aba078a8f8-52a448969b8b6241-01}
2022-02-23T12:05:50.4704577Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{OpenTelemetry.SqlClient.Execute}{00-520b840e8a29c2bbfeb2d7aba078a8f8-52a448969b8b6241-01}
2022-02-23T12:05:50.5653461Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-520b840e8a29c2bbfeb2d7aba078a8f8-02e485ab652cd3b9-01}
2022-02-23T12:05:53.9180330Z:Activity started. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-39cfeebdeab214fea318127da2d66121-43870a66b1839c4d-00}
2022-02-23T12:05:53.9204102Z:Activity stopped. OperationName = '{0}', Id = '{1}'.{System.Net.Http.HttpRequestOut}{00-39cfeebdeab214fea318127da2d66121-43870a66b1839c4d-00}

In short: Logs about OpenTelemetry.SqlClient.Execute are missing when running non locally but SQL query is executed (data is reported back).

In addition to that I printed out the diagnostic listener event names. They match the names defined in https://github.com/open-telemetry/opentelemetry-dotnet/tree/main/src/OpenTelemetry.Instrumentation.SqlClient.
This means those events are fired...

Question: How can I get more information about what might be failing in SQL client instrumentation?

Describe your environment.

  • ASP.NET core 3.1 microservice
  • OpenTelemetry.Exporter.OpenTelemetryProtocol 1.2.0-rc2
  • OpenTelemetry.Extensions.Hosting 1.0.0-rc9
  • OpenTelemetry.Instrumentation.AspNetCore 1.0.0-rc9
  • OpenTelemetry.Instrumentation.Http 1.0.0-rc9
  • OpenTelemetry.Instrumentation.SqlClient 1.0.0-rc9
@Sam13 Sam13 added the question Further information is requested label Feb 23, 2022
@cijothomas
Copy link
Member

Could you share the name and version of the SQLClient package? there were some versions which broke telemetry, so its possible that in your prod version is different?

@Sam13
Copy link
Author

Sam13 commented Feb 24, 2022 •
edited
Loading

Hello @cijothomas

Thanks for your reply.
I'm using Microsoft.Data.SqlClient version 3.0.1.

Meanwhile I found some more details by creating a custom build of SQL instrumentation with some logging.
I turns out that the activity is never stopped.
The handler always returns because activity source cannot be matched:
https://github.com/open-telemetry/opentelemetry-dotnet/blob/f8a1f3caa43f15e4ff1bb747cea972ebd029f9dd/src/OpenTelemetry.Instrumentation.SqlClient/Implementation/SqlClientDiagnosticListener.cs#L145

I dumped the activity source name: Sometimes it's from another instrumentation (e.g. ASP.NET core) sometimes it's empty...

@Sam13
Copy link
Author

Sam13 commented Feb 28, 2022

An upgrade to Microsoft.Data.SqlClient version 4.1.0 did not resolve the issue. Still no SQL tracing

@vishweshbankwar vishweshbankwar transferred this issue from open-telemetry/opentelemetry-dotnet May 14, 2024
@Kielek Kielek added the comp:instrumentation.sqlclient Things related to OpenTelemetry.Instrumentation.SqlClient label May 17, 2024
@martinjt
Copy link
Member

martinjt commented Jun 2, 2024

This definitely does work now. If this is still an issue, please reopen the issue.

@martinjt martinjt closed this as not planned Won't fix, can't repro, duplicate, stale Jun 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
comp:instrumentation.sqlclient Things related to OpenTelemetry.Instrumentation.SqlClient question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@martinjt @Sam13 @cijothomas @Kielek