search

kamon-io / sbt-aspectj-runner

sbt plugin for running aspectj weaver
Other
34 stars 16 forks source link

Classpath issues in dev mode #22

Open jsw opened 6 years ago

jsw commented 6 years ago

I expect to be able to set the play config resource via command-line argument. I have tried several different ways.

sbt -Dconfig.resource=application.local.conf run

Relevant output

--- (Running the application, auto-reloading is enabled) ---

[error] com.typesafe.config.ConfigException$IO: application.local.conf: java.io.IOException: resource not found on classpath: application.local.conf
[error]     at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:188)
[error]     at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:174)
[error]     at com.typesafe.config.impl.Parseable.parse(Parseable.java:299)
[error]     at com.typesafe.config.ConfigFactory.parseResources(ConfigFactory.java:957)
[error]     at com.typesafe.config.ConfigFactory.parseResources(ConfigFactory.java:885)
[error]     at com.typesafe.config.DefaultConfigLoadingStrategy.parseApplicationConfig(DefaultConfigLoadingStrategy.java:49)
[error]     at com.typesafe.config.ConfigFactory.defaultApplication(ConfigFactory.java:473)
[error]     at com.typesafe.config.ConfigFactory$1.call(ConfigFactory.java:259)
[error]     at com.typesafe.config.ConfigFactory$1.call(ConfigFactory.java:256)
[error]     at com.typesafe.config.impl.ConfigImpl$LoaderCache.getOrElseUpdate(ConfigImpl.java:65)
[error]     at com.typesafe.config.impl.ConfigImpl.computeCachedConfig(ConfigImpl.java:92)
[error]     at com.typesafe.config.ConfigFactory.load(ConfigFactory.java:256)
[error]     at com.typesafe.config.ConfigFactory.load(ConfigFactory.java:232)
[error]     at kamon.Kamon$.<init>(Kamon.scala:35)
[error]     at kamon.Kamon$.<clinit>(Kamon.scala)
[error]     at kamon.context.HasContext$.fromCurrentContext(Mixin.scala:44)
[error]     at kamon.scala.instrumentation.FutureInstrumentation.mixinTraceContextAwareToFutureRelatedRunnable(FutureInstrumentation.scala:29)
[error]     at scala.concurrent.impl.CallbackRunnable.context(Promise.scala:1)
[error]     at kamon.scala.instrumentation.FutureInstrumentation.afterCreation(FutureInstrumentation.scala:37)
[error]     at scala.concurrent.impl.CallbackRunnable.<init>(Promise.scala:54)
[error]     at scala.concurrent.impl.Promise$DefaultPromise.onComplete(Promise.scala:303)
[error]     at akka.actor.ActorSystemImpl$TerminationCallbacks.<init>(ActorSystem.scala:1008)
[error]     at akka.actor.ActorSystemImpl.<init>(ActorSystem.scala:800)
[error]     at akka.actor.ActorSystem$.apply(ActorSystem.scala:246)
[error]     at akka.actor.ActorSystem$.apply(ActorSystem.scala:289)
[error]     at akka.actor.ActorSystem$.apply(ActorSystem.scala:264)
[error]     at play.core.server.DevServerStart$.$anonfun$mainDev$1(DevServerStart.scala:224)
[error]     at play.utils.Threads$.withContextClassLoader(Threads.scala:21)
[error]     at play.core.server.DevServerStart$.mainDev(DevServerStart.scala:59)
[error]     at play.core.server.DevServerStart$.mainDevHttpMode(DevServerStart.scala:49)
[error]     at play.core.server.DevServerStart.mainDevHttpMode(DevServerStart.scala)
[error]     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[error]     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[error]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[error]     at java.lang.reflect.Method.invoke(Method.java:498)
[error]     at kamon.aspectj.sbt.play.AspectJReloader$.startDevMode(AspectJReloader.scala:221)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.devModeServer$lzycompute$1(AspectJPlayRun.scala:60)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.devModeServer$1(AspectJPlayRun.scala:44)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.$anonfun$playRunTask$3(AspectJPlayRun.scala:67)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.$anonfun$playRunTask$3$adapted(AspectJPlayRun.scala:30)
[error]     at scala.Function1.$anonfun$compose$1(Function1.scala:44)
[error]     at sbt.internal.util.$tilde$greater.$anonfun$$u2219$1(TypeFunctions.scala:39)
[error]     at sbt.std.Transform$$anon$4.work(System.scala:66)
[error]     at sbt.Execute.$anonfun$submit$2(Execute.scala:262)
[error]     at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:16)
[error]     at sbt.Execute.work(Execute.scala:271)
[error]     at sbt.Execute.$anonfun$submit$1(Execute.scala:262)
[error]     at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:174)
[error]     at sbt.CompletionService$$anon$2.call(CompletionService.scala:36)
[error]     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[error]     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[error]     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[error]     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[error]     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[error]     at java.lang.Thread.run(Thread.java:748)
[error] Caused by: java.io.IOException: resource not found on classpath: application.local.conf
[error]     at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:735)
[error]     at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:710)
[error]     at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:180)
[error]     at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:174)
[error]     at com.typesafe.config.impl.Parseable.parse(Parseable.java:299)
[error]     at com.typesafe.config.ConfigFactory.parseResources(ConfigFactory.java:957)
[error]     at com.typesafe.config.ConfigFactory.parseResources(ConfigFactory.java:885)
[error]     at com.typesafe.config.DefaultConfigLoadingStrategy.parseApplicationConfig(DefaultConfigLoadingStrategy.java:49)
[error]     at com.typesafe.config.ConfigFactory.defaultApplication(ConfigFactory.java:473)
[error]     at com.typesafe.config.ConfigFactory$1.call(ConfigFactory.java:259)
[error]     at com.typesafe.config.ConfigFactory$1.call(ConfigFactory.java:256)
[error]     at com.typesafe.config.impl.ConfigImpl$LoaderCache.getOrElseUpdate(ConfigImpl.java:65)
[error]     at com.typesafe.config.impl.ConfigImpl.computeCachedConfig(ConfigImpl.java:92)
[error]     at com.typesafe.config.ConfigFactory.load(ConfigFactory.java:256)
[error]     at com.typesafe.config.ConfigFactory.load(ConfigFactory.java:232)
[error]     at kamon.Kamon$.<init>(Kamon.scala:35)
[error]     at kamon.Kamon$.<clinit>(Kamon.scala)
[error]     at kamon.context.HasContext$.fromCurrentContext(Mixin.scala:44)
[error]     at kamon.scala.instrumentation.FutureInstrumentation.mixinTraceContextAwareToFutureRelatedRunnable(FutureInstrumentation.scala:29)
[error]     at scala.concurrent.impl.CallbackRunnable.context(Promise.scala:1)
[error]     at kamon.scala.instrumentation.FutureInstrumentation.afterCreation(FutureInstrumentation.scala:37)
[error]     at scala.concurrent.impl.CallbackRunnable.<init>(Promise.scala:54)
[error]     at scala.concurrent.impl.Promise$DefaultPromise.onComplete(Promise.scala:303)
[error]     at akka.actor.ActorSystemImpl$TerminationCallbacks.<init>(ActorSystem.scala:1008)
[error]     at akka.actor.ActorSystemImpl.<init>(ActorSystem.scala:800)
[error]     at akka.actor.ActorSystem$.apply(ActorSystem.scala:246)
[error]     at akka.actor.ActorSystem$.apply(ActorSystem.scala:289)
[error]     at akka.actor.ActorSystem$.apply(ActorSystem.scala:264)
[error]     at play.core.server.DevServerStart$.$anonfun$mainDev$1(DevServerStart.scala:224)
[error]     at play.utils.Threads$.withContextClassLoader(Threads.scala:21)
[error]     at play.core.server.DevServerStart$.mainDev(DevServerStart.scala:59)
[error]     at play.core.server.DevServerStart$.mainDevHttpMode(DevServerStart.scala:49)
[error]     at play.core.server.DevServerStart.mainDevHttpMode(DevServerStart.scala)
[error]     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[error]     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[error]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[error]     at java.lang.reflect.Method.invoke(Method.java:498)
[error]     at kamon.aspectj.sbt.play.AspectJReloader$.startDevMode(AspectJReloader.scala:221)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.devModeServer$lzycompute$1(AspectJPlayRun.scala:60)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.devModeServer$1(AspectJPlayRun.scala:44)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.$anonfun$playRunTask$3(AspectJPlayRun.scala:67)
[error]     at kamon.aspectj.sbt.play.AspectJPlayRun$.$anonfun$playRunTask$3$adapted(AspectJPlayRun.scala:30)
[error]     at scala.Function1.$anonfun$compose$1(Function1.scala:44)
[error]     at sbt.internal.util.$tilde$greater.$anonfun$$u2219$1(TypeFunctions.scala:39)
[error]     at sbt.std.Transform$$anon$4.work(System.scala:66)
[error]     at sbt.Execute.$anonfun$submit$2(Execute.scala:262)
[error]     at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:16)
[error]     at sbt.Execute.work(Execute.scala:271)
[error]     at sbt.Execute.$anonfun$submit$1(Execute.scala:262)
[error]     at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:174)
[error]     at sbt.CompletionService$$anon$2.call(CompletionService.scala:36)
[error]     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[error]     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[error]     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[error]     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[error]     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[error]     at java.lang.Thread.run(Thread.java:748)

Also tried sbt -Dconfig.file=conf/application.local.conf run

Relevant output

--- (Running the application, auto-reloading is enabled) ---

[error] k.c.Codecs - Failed to initialize codec for key [request-id]
java.lang.ClassNotFoundException: util.RequestIdCodec
    at org.aspectj.weaver.bcel.ExtensibleURLClassLoader.findClass(ExtensibleURLClassLoader.java:56)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:348)
    at kamon.util.DynamicAccess.$anonfun$getClassFor$1(DynamicAccess.scala:35)
    at scala.util.Try$.apply(Try.scala:209)
    at kamon.util.DynamicAccess.getClassFor(DynamicAccess.scala:34)
    at kamon.util.DynamicAccess.createInstanceFor(DynamicAccess.scala:52)
    at kamon.context.Codecs.$anonfun$readEntryCodecs$1(Codecs.scala:65)
[error] k.c.Codecs - Failed to initialize codec for key [span]
java.lang.ClassNotFoundException: util.NoopCodec
    at org.aspectj.weaver.bcel.ExtensibleURLClassLoader.findClass(ExtensibleURLClassLoader.java:56)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:348)
    at kamon.util.DynamicAccess.$anonfun$getClassFor$1(DynamicAccess.scala:35)
    at scala.util.Try$.apply(Try.scala:209)
    at kamon.util.DynamicAccess.getClassFor(DynamicAccess.scala:34)
    at kamon.util.DynamicAccess.createInstanceFor(DynamicAccess.scala:52)
    at kamon.context.Codecs.$anonfun$readEntryCodecs$1(Codecs.scala:65)
[info] p.c.s.AkkaHttpServer - Listening for HTTP on /0:0:0:0:0:0:0:0:9000

(Server started, use Enter to stop and go back to the console...)

prod mode via sbt -Dconfig.resource=application.local.conf runProd does not produce an error at startup, but the configuration setting is not respected, which can be observed by hitting localhost:9000 and seeing that b3 headers are propagated, whereas they should not be based on the config file.

Repro via https://github.com/jsw/play-2.6-with-kamon/tree/78c5c32e20807477df3d5d675a980d0eb0cd873a

jsw commented 6 years ago

Some additional debugging information, gathered via -Dconfig.trace=loads...

If the sbt-aspectj-runner-play-2.6 plugin is removed from the project, the app loads normally. Once the first request is made, the resource is loaded. Relevant output:

sbt -Dconfig.resource=application.local.conf -Dconfig.trace=loads run
...
Loading config from resource 'application.local.conf' URL file:/Users/jswhite/code/play-2.6-with-kamon/target/scala-2.12/classes/application.local.conf from class loader ReloadableClassLoader(v1){file:/Users/jswhite/code/play-2.6-with-kamon/target/scala-2.12/classes/}
Loading config from a URL: file:/Users/jswhite/code/play-2.6-with-kamon/target/scala-2.12/classes/application.local.conf

When the same command is run with the aspectj runner in place, there is an attempt to load the resource before the first request, and it doesn't look like the ReloadableClassLoader is in that set, so there's a fail-fast.

This should provide some additional clues. I'll keep digging.

jsw commented 6 years ago

Getting more information via IntelliJ debugger.

When the config is not specified as a JVM parameter, the ReloadableClassLoader is used (target/scala-2.12/classes) to find application.conf

at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:731)
      at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:710)
      at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:180)
      at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:174)
      at com.typesafe.config.impl.Parseable.parse(Parseable.java:152)
      at com.typesafe.config.impl.SimpleIncluder.fromBasename(SimpleIncluder.java:185)
      at com.typesafe.config.impl.ConfigImpl.parseResourcesAnySyntax(ConfigImpl.java:132)
      at com.typesafe.config.ConfigFactory.parseResourcesAnySyntax(ConfigFactory.java:979)
      at com.typesafe.config.DefaultConfigLoadingStrategy.parseApplicationConfig(DefaultConfigLoadingStrategy.java:36)
      at com.typesafe.config.ConfigFactory.defaultApplication(ConfigFactory.java:473)
      at play.api.Configuration$.$anonfun$load$5(Configuration.scala:74)
      at play.api.Configuration$$$Lambda$3395.285389917.apply(Unknown Source:-1)
      at scala.Option.getOrElse(Option.scala:121)
      at play.api.Configuration$.load(Configuration.scala:70)
      at play.api.Configuration$.load(Configuration.scala:110)
      at play.api.ApplicationLoader$.createContext(ApplicationLoader.scala:113)
      at play.core.server.DevServerStart$$anon$1.$anonfun$reload$3(DevServerStart.scala:172)
      at play.core.server.DevServerStart$$anon$1$$Lambda$5823.844870249.apply(Unknown Source:-1)
      at play.utils.Threads$.withContextClassLoader(Threads.scala:21)
      at play.core.server.DevServerStart$$anon$1.reload(DevServerStart.scala:171)
      at play.core.server.DevServerStart$$anon$1.get(DevServerStart.scala:124)
      - locked <0x53ad> (a play.core.server.DevServerStart$$anon$1)
      at play.core.server.AkkaHttpServer.handleRequest_aroundBody0(AkkaHttpServer.scala:189)
      at play.core.server.AkkaHttpServer$AjcClosure1.run(AkkaHttpServer.scala:1)
      at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:149)
      at kamon.play.instrumentation.RequestHandlerInstrumentation.$anonfun$routeRequestNumberTwo$1(RequestHandlerInstrumentation.scala:47)
      at kamon.play.instrumentation.RequestHandlerInstrumentation$$Lambda$3962.819075163.apply(Unknown Source:-1)
      at kamon.Kamon$.withContext(Kamon.scala:120)
      at kamon.play.instrumentation.RequestHandlerInstrumentation.routeRequestNumberTwo(RequestHandlerInstrumentation.scala:47)
      at play.core.server.AkkaHttpServer.handleRequest(AkkaHttpServer.scala:186)
      at play.core.server.AkkaHttpServer.$anonfun$createServerBinding$1(AkkaHttpServer.scala:106)
      at play.core.server.AkkaHttpServer$$Lambda$3793.403343240.apply(Unknown Source:-1)
      at akka.stream.impl.fusing.MapAsync$$anon$25.onPush(Ops.scala:1194)
      at akka.stream.impl.fusing.GraphInterpreter.processPush(GraphInterpreter.scala:519)
      at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:482)
      at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:378)
      at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:585)
      at akka.stream.impl.fusing.GraphInterpreterShell$AsyncInput.execute(ActorGraphInterpreter.scala:469)
      at akka.stream.impl.fusing.GraphInterpreterShell.processEvent(ActorGraphInterpreter.scala:560)
      at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:742)
      at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:757)
      at akka.actor.Actor.aroundReceive(Actor.scala:517)
      at akka.actor.Actor.aroundReceive$(Actor.scala:515)
      at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:667)
      at akka.actor.ActorCell.receiveMessage(ActorCell.scala:590)
      at akka.actor.ActorCell.invoke(ActorCell.scala:559)
      at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
      at akka.dispatch.Mailbox.run(Mailbox.scala:224)
      at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
      at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
      at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
      at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
      at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

When the config is specified on the command-line the DependenciesClassLoader is used (all the jars) to attempt to find application.local.conf, but obviously that's the wrong one.

at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:730)
      at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:710)
      at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:180)
      at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:174)
      at com.typesafe.config.impl.Parseable.parse(Parseable.java:152)
      at com.typesafe.config.impl.SimpleIncluder.fromBasename(SimpleIncluder.java:185)
      at com.typesafe.config.impl.ConfigImpl.parseResourcesAnySyntax(ConfigImpl.java:132)
      at com.typesafe.config.ConfigFactory.parseResourcesAnySyntax(ConfigFactory.java:979)
      at com.typesafe.config.DefaultConfigLoadingStrategy.parseApplicationConfig(DefaultConfigLoadingStrategy.java:36)
      at com.typesafe.config.ConfigFactory.defaultApplication(ConfigFactory.java:473)
      at play.api.Configuration$.$anonfun$load$5(Configuration.scala:74)
      at play.api.Configuration$$$Lambda$3380.989164591.apply(Unknown Source:-1)
      at scala.Option.getOrElse(Option.scala:121)
      at play.api.Configuration$.load(Configuration.scala:70)
      at play.core.server.DevServerStart$.$anonfun$mainDev$1(DevServerStart.scala:205)
      at play.core.server.DevServerStart$$$Lambda$3355.2043158498.apply(Unknown Source:-1)
      at play.utils.Threads$.withContextClassLoader(Threads.scala:21)
      at play.core.server.DevServerStart$.mainDev(DevServerStart.scala:59)
      at play.core.server.DevServerStart$.mainDevHttpMode(DevServerStart.scala:49)
      at play.core.server.DevServerStart.mainDevHttpMode(DevServerStart.scala:-1)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:498)
      at kamon.aspectj.sbt.play.AspectJReloader$.startDevMode(AspectJReloader.scala:221)
      at kamon.aspectj.sbt.play.AspectJPlayRun$.devModeServer$lzycompute$1(AspectJPlayRun.scala:60)
      - locked <0x2dc6> (a scala.runtime.LazyRef)
      at kamon.aspectj.sbt.play.AspectJPlayRun$.devModeServer$1(AspectJPlayRun.scala:44)
      at kamon.aspectj.sbt.play.AspectJPlayRun$.$anonfun$playRunTask$3(AspectJPlayRun.scala:67)
      at kamon.aspectj.sbt.play.AspectJPlayRun$.$anonfun$playRunTask$3$adapted(AspectJPlayRun.scala:30)
      at kamon.aspectj.sbt.play.AspectJPlayRun$$$Lambda$3302.895329692.apply(Unknown Source:-1)
      at scala.Function1.$anonfun$compose$1(Function1.scala:44)
      at scala.Function1$$Lambda$594.1374115041.apply(Unknown Source:-1)
      at sbt.internal.util.$tilde$greater.$anonfun$$u2219$1(TypeFunctions.scala:39)
      at sbt.internal.util.$tilde$greater$$Lambda$1811.943051773.apply(Unknown Source:-1)
      at sbt.std.Transform$$anon$4.work(System.scala:66)
      at sbt.Execute.$anonfun$submit$2(Execute.scala:262)
      at sbt.Execute$$Lambda$1828.1216623919.apply(Unknown Source:-1)
      at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:16)
      at sbt.Execute.work(Execute.scala:271)
      at sbt.Execute.$anonfun$submit$1(Execute.scala:262)
      at sbt.Execute$$Lambda$1819.738867238.apply(Unknown Source:-1)
      at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:174)
      at sbt.ConcurrentRestrictions$$anon$4$$Lambda$1826.1180504901.apply(Unknown Source:-1)
      at sbt.CompletionService$$anon$2.call(CompletionService.scala:36)
      at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
      at java.util.concurrent.FutureTask.run(FutureTask.java:-1)
      at java.util.concurrent.Executors$RunnableAdapter.call$$$capture(Executors.java:511)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:-1)
      at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266)
      at java.util.concurrent.FutureTask.run(FutureTask.java:-1)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      at java.lang.Thread.run(Thread.java:748)

Note that even if you specify the default config file. e.g. -Dconfig.resource=application.conf, the unexpected behavior is the same. It seems to come down to a timing issue of when the resource is loaded that determines which stack, and hence, ClassLoader, will ultimately load the config.

Also note that that in the working case, the thread is an Akka thread (e.g. play-dev-mode-akka.actor.default-dispatcher-4), and therefore probably owned by Play and has the appropriate ClassLoader set, whereas in the failure case, it's a regular pooled thread (e.g. pool-x-thread-y).

jsw commented 6 years ago

More digging.. The issue is more fundamental than providing config overrides. A config override signals to typesafe-config that the file must be found, or it will fail fast. With no override, it's actually a silent failure and Kamon is not picking up config from application.conf when run via sbt run. The issue seems to be related to https://github.com/kamon-io/sbt-aspectj-runner/issues/5

The workaround of starting via sbt -Dconfig.file=conf/application.conf works, though because my config references a codec, again, the wrong ClassLoader is used and it can't be loaded. So the workaround would also have to include putting the codec classes in a dependency jar.

jsw commented 6 years ago

I believe the root cause is the kamon future instrumentation is kicking in before the Play server has started, or more specifically the AspectJReloader.currentApplicationClassLoader has been initialized, which doesn't occur until the first request and reload is called.

I verified a few hacks which somewhat alleviate the issue, but none are likely ideal.

1) Add the following after the reloader is defined in AspectJReloader.scala. This makes the user resources available, but not the user classes, since the DelegatingClassLoader only delegates to the applicationClassLoaderProvider for resources, and not classes.

reloader.reload
reloader.forceReloadNextTime = true

2) Another approach in Kamon.scala is to initialize _context = ConfigFactory.defaultReference, and then the play application loader can call Kamon.reconfigure(ConfigFactory.load). I don't think this, at least in isolation, is a good solution for general consumption, but just presenting it since it worked for me, and may spark other ideas.

3) Another approach is to move the kamon config to a separate file kamon.conf, and then in the application loader call Kamon.reconfigure(ConfigFactory.load("kamon.conf")). This works for finding the resource. Any configured codecs that are user classes will not load unless the following change is made to DynamicAccess.scala

//val c = Class.forName(fqcn, false, classLoader).asInstanceOf[Class[_ <: T]]
val c = Thread.currentThread().getContextClassLoader().loadClass(fqcn).asInstanceOf[Class[_ <: T]]

Note the comments from jroper about not using Class.forName in https://github.com/playframework/playframework/issues/2847

Although there's an unfortunate ordering of events. It looks like the new settings aren't in effect until the 2nd request. The incoming context is decoded before ApplicationLoader.load is called.

4) I guess the cleanest workaround for now is to use a combination of -Dconfig.file instead of -Dconfig.resource and put all codecs in a jar.

So, lot's of things going on here. There may be a combination of small changes to iron out all the individual cases, or there may be a more fundamental approach such as preventing Kamon from initializing until an appropriate time in the Play dev mode flow.