setup @Loggable method instrumentation

[JR-Utily]

Hello,

This is more about Kanela than Kamon, but as there is no Discussion section in kanela github, I suppose I'd post here. This will be cross post on stackoverflow too.

I want to setup a Loggable instrumentation in our applications in the same idea as https://aspects.jcabi.com/apidocs-0.22.6/com/jcabi/aspects/Loggable.html
As my team is about to use Kamon and Kanela to propagate context in our codebase anyway, it would be far simpler for us if the same agent would do all the instrumentation.
So I thought I would go DIY and started a new project in our mono repo to have a kamon-loggable module. I've looked at kamon-annotation and kamon-annotation-api code to get inspiration on how to do that. The only doc I found (http://kamon-io.github.io/kanela/interceptors.html) is not very useful and I have close to zero knowledge of ByteBudy... but cameleon coding should be enough at start :)

I arrived at a point that seems good, compile, but when running, there is no log, and the code doesn't seem to be executed. The break point in the code is never reached, but it may be normal, I'm not sure if the class are actually instantiated after an instrumentation, or if the code is copied inline in other classes.

Any advice (no pun intented) on how to setup the project, or something missing, would be greatly appreciated. I suppose this is something to do with my build.sbt or my conf files, but I'm stucked for now...

build.sbt

// scala_common project contains the @com.company.logging.Loggable annotation declaration

// java project (but compiled as scala ?) 
// nothing in the assembly, because no Main to be executed
lazy val loggable = (project in file("common/scala-kamon-loggable"))
    .enablePlugins(JavaAgent)
    .assembly("", "scala-kamon-loggable.jar")
    .dependsOn(scala_common)
    .settings(
      javaAgents := Seq("io.kamon"              %  "kanela-agent"    % "1.0.7" % "runtime")
    )
    .settings(
      libraryDependencies ++= Seq(
        "io.kamon"              %% "kamon-core" % "2.1.4",
        "io.kamon"              %% "kamon-annotation" % "2.1.4"
      )
    )

// the main I execute to test
lazy val logging_poc = (project in file("applications/logging-poc"))
    .assembly("com.company.logging.Poc", "logging-poc.jar")
    .dependsOn(scala_common, loggable)
    .settings(
      libraryDependencies ++= Seq(
        "io.kamon" %% "kamon-core" % "2.1.4",
        "io.kamon" %% "kamon-scala-future" % "2.1.4",
        "io.kamon" %% "kamon-logback" % "2.1.4"
      )
    )

scala-common

• com.company.logging.Loggable

import java.lang.annotation.*;

/**
 * When instrumentation is activated, log all entry / return / throw of the annotated method
 */
@Documented
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface Loggable {}

scala-kamon-loggable

• reference.conf

kanela.modules {
  loggable {
    enabled = true
    name = "Loggable Annotation Instrumentation"
    description = "Provides an annotation to create tracing Logs of annotated methods"

    instrumentations = [
      "com.company.logging.Instrumentation"
    ]
  }
}

• com.company.logging.Instrumentation

public final class Instrumentation extends InstrumentationBuilder {

  private static final String Loggable = "com.company.logging.Loggable";

  public Instrumentation() {
    onTypesWithMethodsAnnotatedWith(Loggable)
        .advise(isAnnotatedWith(named(Loggable)), LoggableAdvisor.class);

  }
}

• com.company.logging.advisor.LoggableAdvisor

public final class LoggableAdvisor {

  public final static ExecutionContext CallingThreadEC = CallingThreadExecutionContext$.MODULE$;

  @Advice.OnMethodEnter()
  public static void onEnter(
      @Advice.This(optional = true) Object obj,
      @Advice.Origin Class<?> clazz,
      @Advice.Origin Method method,
      @Advice.Origin("#t") String className,
      @Advice.Origin("#m") String methodName,
      @Advice.Origin("#s") String signatureName,
      @Advice.AllArguments Object[] allArguments
  ) {
// I'd put a Logger after, for now, just for testing instrumentation, println is enough
    System.out.println("INSIDE INSTRUMENTATION");
  }
}

logging_poc

• application.conf

kamon {
  trace {
    tick-interval = 2 seconds
    sampler = "always"
  }
  enabled: true
}

• com.company.logging.Poc

object Poc extends App with LazyLogging {

  val config = ConfigFactory.load()
  if (config.getBoolean("kamon.enabled")) {
    Kamon.loadModules()
  }

  import scala.concurrent.ExecutionContext.Implicits.global
  @com.company.logging.Loggable
  def asyncLog(param: Integer): Future[String] = {
    Kamon.runWithSpan(Kamon.spanBuilder("Level 3").start(), finishSpan = true) {
      Future {
        blocking {
            assert(param < 5, "Param is too big")
            Thread.sleep(param * 1000)
            logger.info(s"Some info logs ! ($param)")
            "Ok"          
        }
      }
    }
  }

  Await.ready( asyncLog(0) , Duration.Inf)
  Await.ready(Kamon.stopModules(), Duration.Inf)
}

And here is the trace I get in console (the other instrumentation work, as we see SpanId in the MDC).
I would have expect to get an "INSIDE INSTRUMENTATION" line before the "Some info logs! "

 _  __                _        ______
| |/ /               | |       \ \ \ \
| ' / __ _ _ __   ___| | __ _   \ \ \ \
|  < / _` | '_ \ / _ \ |/ _` |   ) ) ) )
| . \ (_| | | | |  __/ | (_| |  / / / /
|_|\_\__,_|_| |_|\___|_|\__,_| /_/_/_/
                              
==============================
Running with Kanela, the Kamon Instrumentation Agent ::

scala-execution-context-global-18 10:53:14.582 [INFO ] com.company.logging.Poc$ - Some info logs ! (0) - MDC[kamonSpanId=0b64e07a7ec37656, kamonTraceId=c347442849cccd86, kamonSpanName=Level 3]

Process finished with exit code 0

[SimunKaracic]

Hey, I gave this a look and you appear to be missing a within block in your reference.conf, telling kamon where to apply the instrumentation.
Something like this:
https://github.com/kamon-io/Kamon/blob/master/instrumentation/kamon-executors/src/main/resources/reference.conf#L56

The rest of it looks solid, great work 🎉

[JR-Utily]

Thanks !
But there is no wihin in kamon-annotation:
https://github.com/kamon-io/Kamon/blob/master/instrumentation/kamon-annotation/src/main/resources/reference.conf
So I thought it would be like everywhere per default.
Is it ok to put within=[*] ?

[ivantopo]

Hey @JR-Utily! There is no within in the module because the bigger the search scope for instrumentable classes, the longer it will take for applications to start. The recommended solution here is to manually tell Kamon in which packages to search for annotated methods. It should look like this:

kanela.modules.annotation {
  within += "my.company.*"
}

Also, I would recommend to always use += when the value of a configuration key is an array, otherwise you might end up replacing or missing parts of the array, depending on the order in which config files get loaded.

[SimunKaracic]

Hey, let us know when you try out the config changes, I'm curious to see if it's working now

[JR-Utily]

I'll try it next week, then I keep you informed :) Thanks ! ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ Le jeudi, novembre 12, 2020 2:12 PM, SimunKaracic <notifications@github.com> a écrit :

…

Hey, let us know when you try out the config changes, I'm curious to see if it's working now — You are receiving this because you were mentioned. Reply to this email directly, [view it on GitHub](#883 (comment)), or [unsubscribe](https://github.com/notifications/unsubscribe-auth/AAKPCJM5J2XFF7O3HYDTUC3SPPNNBANCNFSM4TEY66ZQ).

[JR-Utily]

Ok, it works fine by adding to application.conf

kanela.modules.loggable {
  within += "com.company.*"
}

Thanks a lot @ivantopo @SimunKaracic !

Would you be interested by a PR to integrate that directly into kamon-annotation ? I will still work on it for now, but at some point I think it could be useful for someone else too.

[SimunKaracic]

Do you mean the configuration change or the entire module?

In any case, open up a PR and we'll take the discussion there!

[JR-Utily]

I mean the entire @loggable annotation / implementation ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ Le lundi, novembre 23, 2020 1:51 PM, SimunKaracic <notifications@github.com> a écrit :

…

Do you mean the configuration change or the entire module? In any case, open up a PR and we'll take the discussion there! — You are receiving this because you were mentioned. Reply to this email directly, [view it on GitHub](#883 (reply in thread)), or [unsubscribe](https://github.com/notifications/unsubscribe-auth/AAKPCJMH5MPSH2QZEWKKPVLSRJLD5ANCNFSM4TEY66ZQ).

[SimunKaracic]

Thanks for the suggestion, but I don't think we'll merge something like that to Kamon. We're all about instrumenting specific libraries here ;)

I would like to continue helping you finish this though! Let me know if you have any more questions

[JR-Utily]

For now it works like a charm.
If I get more trouble, I'll contact you again on this thread.
And if I have the time, I'd post a Gist with the full implementation in a near future :)