ISPN-15156 Avoid to spam DEBUG log when OpenTelemetry is not found on the client #11272

fax4ever · 2023-09-07T08:03:25Z

https://issues.redhat.com/browse/ISPN-15156

pruivo · 2023-09-07T10:45:51Z

I would probably move all the checks to TelemetryService and cache the instance to avoid instantiating a new one every time. And no more catches or null checks in the code.
Note: create() can be removed since the instance can be accessed directly.

public interface TelemetryService {

   TelemetryService INSTANCE = createInstance();

   /**
    * Try to create a {@link TelemetryService} instance.
    *
    * @throws ClassCastException if the OpenTelemetry API module is not in the classpath
    * @return a {@link TelemetryService} instance
    */
   static TelemetryService create() {
      return INSTANCE;
   }

   void injectSpanContext(HeaderParams header);

   private static TelemetryService createInstance() {
      try {
         Class.forName("io.opentelemetry.api.trace.propagation.W3CTraceContextPropagator", false,
               TelemetryService.class.getClassLoader());
         return new TelemetryServiceImpl();
      } catch (ClassNotFoundException e) {
         // log warning that opentelemetry is not in the classpath
      }
      // return no-op implementation
      return header -> {
         //no-op
      };
   }

}

fax4ever · 2023-09-07T12:01:42Z

I would probably move all the checks to TelemetryService and cache the instance to avoid instantiating a new one every time. And no more catches or null checks in the code. Note: create() can be removed since the instance can be accessed directly.

public interface TelemetryService {

   TelemetryService INSTANCE = createInstance();

   /**
    * Try to create a {@link TelemetryService} instance.
    *
    * @throws ClassCastException if the OpenTelemetry API module is not in the classpath
    * @return a {@link TelemetryService} instance
    */
   static TelemetryService create() {
      return INSTANCE;
   }

   void injectSpanContext(HeaderParams header);

   private static TelemetryService createInstance() {
      try {
         Class.forName("io.opentelemetry.api.trace.propagation.W3CTraceContextPropagator", false,
               TelemetryService.class.getClassLoader());
         return new TelemetryServiceImpl();
      } catch (ClassNotFoundException e) {
         // log warning that opentelemetry is not in the classpath
      }
      // return no-op implementation
      return header -> {
         //no-op
      };
   }

}

I don't know, since there is the case of cfg.tracingPropagationEnabled() == false.
In this case I think we can avoid to create it...

wburns

Looks good, just some comments on the levels.

wburns · 2023-09-07T13:23:25Z

client/hotrod-client/src/main/java/org/infinispan/client/hotrod/logging/Log.java

@@ -387,9 +387,9 @@ public interface Log extends BasicLogger {
   @Message(value = "Native IOUring transport not available, using NIO instead: %s", id = 4108)
   void ioUringNotAvailable(String cause);

-   @LogMessage(level = DEBUG)
+   @LogMessage(level = TRACE)


DEBUG for this is okay now that it is only logged once and without a stack trace.

wburns · 2023-09-07T13:25:37Z

client/hotrod-client/src/main/java/org/infinispan/client/hotrod/logging/Log.java

@@ -399,4 +399,8 @@ public interface Log extends BasicLogger {
   @Message(value = "OpenTelemetry API is present in the classpath, but the tracing propagation is not enabled. Client context tracing will not be propagated.", id = 4111)
   void openTelemetryPropagationDisabled();

+   @LogMessage(level = DEBUG)


I wonder if this should be ERROR now? If this exception is encountered the user has open telemetry on the classpath and has explicitly configured trace propagation.

Right this error shouldn't happen, since we've already checked that the OpenTelemetry is present on the classpath.
It looks like a very runtime exception...

Looking at the code that is executed by the current OpenTelemetry version, it should be safe to call W3CTraceContextPropagator.getInstance().

Anyway we don't have control over this library, that's the reason I introduced the check.
In general implementing tracing I usually write code that is usually more defensive, since in any case tracing should not affect the main behavior of the application.

Anyway it is OK for me to remove this check.

Oh I am not saying to remove it. Whether we let it propagate or log the exception is up to you, you know more issues that may cause this to happen. I was only proposing it be higher priority log level.

Sure, makes sense

wburns · 2023-09-07T13:26:52Z

client/hotrod-client/src/main/java/org/infinispan/client/hotrod/logging/Log.java

@@ -399,4 +399,8 @@ public interface Log extends BasicLogger {
   @Message(value = "OpenTelemetry API is present in the classpath, but the tracing propagation is not enabled. Client context tracing will not be propagated.", id = 4111)
   void openTelemetryPropagationDisabled();


This and openTelemetryPropagationEnabled may want to be TRACE since they are logged for every cache that is used when telemetry is on the classpath. DEBUG may be fine, just want to make sure this spot is considered for evaluation.

pruivo · 2023-09-07T13:28:46Z

I don't know, since there is the case of cfg.tracingPropagationEnabled() == false. In this case I think we can avoid to create it...

What is your concern exactly?
You replace the TelemetryService field being allocated per operation (every Hot Rod operation has a field that is not required anymore) with a single lambda instantiation at startup.

fax4ever · 2023-09-07T15:36:22Z

I don't know, since there is the case of cfg.tracingPropagationEnabled() == false. In this case I think we can avoid to create it...

What is your concern exactly? You replace the TelemetryService field being allocated per operation (every Hot Rod operation has a field that is not required anymore) with a single lambda instantiation at startup.

I wanted to make the TelemetryService creation lazy. But since this instance is very simple, we can have it eager as well.

fax4ever · 2023-09-07T16:25:00Z

Thank you @pruivo and @wburns for the review.
I tried to apply your ideas here.
Let me know if it is fine.

fax4ever · 2023-09-12T09:56:07Z

Hi @pruivo @wburns,

anything else we can improve/fix here?
Thanks

pruivo

LGTM. Personally, if we trying to avoid spam debug messages, I would just remove them instead of changing them to trace. Just my 2cents.

fax4ever · 2023-09-13T08:24:40Z

LGTM. Personally, if we trying to avoid spam debug messages, I would just remove them instead of changing them to trace. Just my 2cents.

You're right. We can expect we don't have the OpenTelemetry library on the client VM most of the time. With the last push I set the last debug log to trace.

When OpenTelemetry is not found on the client

wburns

LGTM, just one last question though. Is there a reason the client/hotrod-client module logs if the telemetry API is present or not and client/hotrod doesn't? It looks like there is no way to disable or enable it per cache with the new module?

fax4ever · 2023-09-13T14:40:37Z

Thank for the review @wburns

Is there a reason the client/hotrod-client module logs if the telemetry API is present or not and client/hotrod doesn't?

I'm not really sure that the latter doesn't.

It looks like there is no way to disable or enable it per cache with the new module?

Enabling / disabling tracing on cache basis is part of Tracing 2.0 targeting Infinispan 15. I'm finishing these days https://github.com/fax4ever/infinispan/tree/ISPN-14974.

wburns · 2023-09-13T14:53:22Z

I'm not really sure that the latter doesn't.

I was taking that from the diff in that the following code only exists in client/hotrod-client module.

      if (cfg.tracingPropagationEnabled()) {
         telemetryService = TelemetryService.INSTANCE;
         log.openTelemetryPropagationEnabled();
      } else {
         log.openTelemetryPropagationDisabled();
      }

Enabling / disabling tracing on cache basis is part of Tracing 2.0 targeting Infinispan 15. I'm finishing these days https://github.com/fax4ever/infinispan/tree/ISPN-14974.

Sorry, didn't realize it was a global configuration not per cache.

fax4ever · 2023-09-13T15:03:36Z

On the client/hotrod in the init of CacheOperationsFactory I think we have:

TelemetryService telemetryService = TelemetryService.INSTANCE;

the first access to the interface should initialize the singleton if i don't get wrong:

TelemetryService INSTANCE = createInstance();

static TelemetryService createInstance() {
   try {
      Class.forName("io.opentelemetry.api.trace.propagation.W3CTraceContextPropagator", false,
            TelemetryService.class.getClassLoader());
   } catch (ClassNotFoundException e) {
      log.noOpenTelemetryAPI();
      return null;
   }

   try {
      return new TelemetryServiceImpl();
   } catch (Throwable e) {
      log.errorCreatingPropagationContext(e);
      return null;
   }
}

fax4ever · 2023-09-13T15:09:15Z

Sorry @wburns I just realized that you asked for the enable / disable propagation log and not for the main log.
The property tracingPropagationEnabled is not currently handled by the new module.

wburns · 2023-10-02T16:02:19Z

Integrated into main, thanks @fax4ever !

fax4ever · 2023-10-02T17:36:33Z

Thank you @wburns!

fax4ever force-pushed the ISPN-15156 branch from 17157c7 to 8bcf5ac Compare September 7, 2023 09:31

fax4ever requested a review from pruivo September 7, 2023 09:32

fax4ever added the 14.0.x Annotate a PR with this label if you want it to be backported to the 14.0.x branch label Sep 7, 2023

wburns reviewed Sep 7, 2023

View reviewed changes

fax4ever force-pushed the ISPN-15156 branch from 8bcf5ac to 15601b8 Compare September 7, 2023 16:23

github-actions bot added the Needs Rebase label Sep 12, 2023

fax4ever force-pushed the ISPN-15156 branch from 15601b8 to 96f40d2 Compare September 13, 2023 04:43

fax4ever removed the Needs Rebase label Sep 13, 2023

fax4ever force-pushed the ISPN-15156 branch from 96f40d2 to 86ea641 Compare September 13, 2023 05:22

pruivo approved these changes Sep 13, 2023

View reviewed changes

fax4ever force-pushed the ISPN-15156 branch from 86ea641 to ff56668 Compare September 13, 2023 08:22

github-actions bot added the Needs Rebase label Sep 13, 2023

fax4ever force-pushed the ISPN-15156 branch from ff56668 to 0400919 Compare September 13, 2023 09:51

fax4ever removed the Needs Rebase label Sep 13, 2023

ISPN-15156 Avoid to spam DEBUG log

deb4423

When OpenTelemetry is not found on the client

fax4ever force-pushed the ISPN-15156 branch from 0400919 to deb4423 Compare September 13, 2023 10:19

wburns approved these changes Sep 13, 2023

View reviewed changes

wburns merged commit 024bcf2 into infinispan:main Oct 2, 2023
3 of 4 checks passed

github-actions bot mentioned this pull request Oct 2, 2023

[14.0.x] ISPN-15156 Avoid to spam DEBUG log when OpenTelemetry is not found on the client #11344

Merged

fax4ever deleted the ISPN-15156 branch October 2, 2023 17:36

fax4ever mentioned this pull request Nov 8, 2023

[14.0.x] ISPN-15156 Fix logging of tracing enabled #11464

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ISPN-15156 Avoid to spam DEBUG log when OpenTelemetry is not found on the client #11272

ISPN-15156 Avoid to spam DEBUG log when OpenTelemetry is not found on the client #11272

fax4ever commented Sep 7, 2023

pruivo commented Sep 7, 2023

fax4ever commented Sep 7, 2023

wburns left a comment

wburns Sep 7, 2023

wburns Sep 7, 2023

fax4ever Sep 7, 2023 •

edited

wburns Sep 7, 2023 •

edited

fax4ever Sep 7, 2023

wburns Sep 7, 2023

pruivo commented Sep 7, 2023

fax4ever commented Sep 7, 2023

fax4ever commented Sep 7, 2023

fax4ever commented Sep 12, 2023

pruivo left a comment

fax4ever commented Sep 13, 2023

wburns left a comment •

edited

fax4ever commented Sep 13, 2023 •

edited

wburns commented Sep 13, 2023

fax4ever commented Sep 13, 2023 •

edited

fax4ever commented Sep 13, 2023 •

edited

wburns commented Oct 2, 2023

fax4ever commented Oct 2, 2023

		@@ -399,4 +399,8 @@ public interface Log extends BasicLogger {
		@Message(value = "OpenTelemetry API is present in the classpath, but the tracing propagation is not enabled. Client context tracing will not be propagated.", id = 4111)
		void openTelemetryPropagationDisabled();

ISPN-15156 Avoid to spam DEBUG log when OpenTelemetry is not found on the client #11272

ISPN-15156 Avoid to spam DEBUG log when OpenTelemetry is not found on the client #11272

Conversation

fax4ever commented Sep 7, 2023

pruivo commented Sep 7, 2023

fax4ever commented Sep 7, 2023

wburns left a comment

Choose a reason for hiding this comment

wburns Sep 7, 2023

Choose a reason for hiding this comment

wburns Sep 7, 2023

Choose a reason for hiding this comment

fax4ever Sep 7, 2023 • edited

Choose a reason for hiding this comment

wburns Sep 7, 2023 • edited

Choose a reason for hiding this comment

fax4ever Sep 7, 2023

Choose a reason for hiding this comment

wburns Sep 7, 2023

Choose a reason for hiding this comment

pruivo commented Sep 7, 2023

fax4ever commented Sep 7, 2023

fax4ever commented Sep 7, 2023

fax4ever commented Sep 12, 2023

pruivo left a comment

Choose a reason for hiding this comment

fax4ever commented Sep 13, 2023

wburns left a comment • edited

Choose a reason for hiding this comment

fax4ever commented Sep 13, 2023 • edited

wburns commented Sep 13, 2023

fax4ever commented Sep 13, 2023 • edited

fax4ever commented Sep 13, 2023 • edited

wburns commented Oct 2, 2023

fax4ever commented Oct 2, 2023

fax4ever Sep 7, 2023 •

edited

wburns Sep 7, 2023 •

edited

wburns left a comment •

edited

fax4ever commented Sep 13, 2023 •

edited

fax4ever commented Sep 13, 2023 •

edited

fax4ever commented Sep 13, 2023 •

edited