Skip to content

Building components in Future causes strange errors#918

Merged
xerial merged 2 commits intowvlet:masterfrom
takezoe:build-in-future-test
Mar 27, 2020
Merged

Building components in Future causes strange errors#918
xerial merged 2 commits intowvlet:masterfrom
takezoe:build-in-future-test

Conversation

@takezoe
Copy link
Copy Markdown
Member

@takezoe takezoe commented Feb 1, 2020 •
edited
Loading

This test fails as follows. I believe that it had been working at some points of the previous versions of Airframe.

BuildInFutureTest:
2020-02-01 14:18:55.355+0900  info [LifeCycleManager] [session:43ed165b] Starting a new lifecycle ...  - (LifeCycleManager.scala:260)
2020-02-01 14:18:55.361+0900  info [LifeCycleManager] [session:43ed165b] ======== STARTED ========  - (LifeCycleManager.scala:264)
2020-02-01 14:18:55.402+0900  info [LifeCycleManager] [session:43ed165b] Stopping the lifecycle ...  - (LifeCycleManager.scala:268)
2020-02-01 14:18:55.406+0900  info [LifeCycleManager] [session:43ed165b] The lifecycle has stopped.  - (LifeCycleManager.scala:272)
 - Building in Future causes MISSING_DEPENDENCY 61.89ms << error: [MISSING_DEPENDENCY] Binding for Int at BuildInFutureTest.scala:29 is not found: Int <- Object

[MISSING_DEPENDENCY] Binding for Int at BuildInFutureTest.scala:29 is not found: Int <- Object
  | => wat wvlet.airframe.AirframeSession.buildInstance(AirframeSession.scala:425)
        at wvlet.airframe.AirframeSession.$anonfun$buildInstance$4(AirframeSession.scala:409)
        at scala.Option.getOrElse(Option.scala:189)
        at wvlet.airframe.AirframeSession.buildInstance(AirframeSession.scala:407)
        at wvlet.airframe.AirframeSession.$anonfun$getInstance$7(AirframeSession.scala:367)
        at scala.Option.getOrElse(Option.scala:189)
        at wvlet.airframe.AirframeSession.getInstance(AirframeSession.scala:355)
        at wvlet.airframe.AirframeSession.$anonfun$buildInstance$5(AirframeSession.scala:440)
        at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:238)
        at scala.collection.Iterator.foreach(Iterator.scala:941)
        at scala.collection.Iterator.foreach$(Iterator.scala:941)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1429)
        at scala.collection.IterableLike.foreach(IterableLike.scala:74)
        at scala.collection.IterableLike.foreach$(IterableLike.scala:73)
        at scala.collection.AbstractIterable.foreach(Iterable.scala:56)
        at scala.collection.TraversableLike.map(TraversableLike.scala:238)
        at scala.collection.TraversableLike.map$(TraversableLike.scala:231)
        at scala.collection.AbstractTraversable.map(Traversable.scala:108)
        at wvlet.airframe.AirframeSession.buildInstance(AirframeSession.scala:430)
        at wvlet.airframe.AirframeSession.$anonfun$buildInstance$4(AirframeSession.scala:409)
        at scala.Option.getOrElse(Option.scala:189)
        at wvlet.airframe.AirframeSession.buildInstance(AirframeSession.scala:407)
        at wvlet.airframe.AirframeSession.$anonfun$getInstance$8(AirframeSession.scala:376)
        at scala.collection.concurrent.Map.getOrElseUpdate(Map.scala:97)
        at scala.collection.concurrent.Map.getOrElseUpdate$(Map.scala:94)
        at scala.collection.convert.Wrappers$JConcurrentMapWrapper.getOrElseUpdate(Wrappers.scala:333)
        at wvlet.airframe.AirframeSession.$anonfun$getInstance$7(AirframeSession.scala:373)
        at scala.Option.getOrElse(Option.scala:189)
        at wvlet.airframe.AirframeSession.getInstance(AirframeSession.scala:355)
        at wvlet.airframe.AirframeSession.get(AirframeSession.scala:169)
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020MISSING_DEPENDENCY$4(BuildInFutureTest.scala:29)
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020MISSING_DEPENDENCY$3(BuildInFutureTest.scala:29)
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020MISSING_DEPENDENCY$3$adapted(BuildInFutureTest.scala:29)
        at wvlet.airframe.Design.runWithSession(Design.scala:289)
        at wvlet.airframe.Design.withSession(Design.scala:302)
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020MISSING_DEPENDENCY$1(BuildInFutureTest.scala:29)
        at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:659)
        at scala.util.Success.$anonfun$map$1(Try.scala:255)
        at scala.util.Success.map(Try.scala:213)
        at scala.concurrent.Future.$anonfun$map$1(Future.scala:292)
        at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
        at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
        at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
        at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
2020-02-01 14:18:55.444+0900  info [LifeCycleManager] [session:7b81a73b] Starting a new lifecycle ...  - (LifeCycleManager.scala:260)
2020-02-01 14:18:55.444+0900  info [LifeCycleManager] [session:7b81a73b] ======== STARTED ========  - (LifeCycleManager.scala:264)
2020-02-01 14:18:55.445+0900  info [LifeCycleManager] [session:7b81a73b] Stopping the lifecycle ...  - (LifeCycleManager.scala:268)
2020-02-01 14:18:55.445+0900  info [LifeCycleManager] [session:7b81a73b] The lifecycle has stopped.  - (LifeCycleManager.scala:272)
 - Building in Future causes java.lang.ClassCastException 26.69ms << error: wvlet.airframe.Config2 cannot be cast to wvlet.airframe.Config1

java.lang.ClassCastException: wvlet.airframe.Config2 cannot be cast to wvlet.airframe.Config1
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020java$u002Elang$u002EClassCastException$6(BuildInFutureTest.scala:39)
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020java$u002Elang$u002EClassCastException$5(BuildInFutureTest.scala:39)
  | => wat wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020java$u002Elang$u002EClassCastException$5$adapted(BuildInFutureTest.scala:39)
        at wvlet.airframe.Design.runWithSession(Design.scala:289)
        at wvlet.airframe.Design.withSession(Design.scala:302)
        at wvlet.airframe.BuildInFutureTest.$anonfun$Building$u0020in$u0020Future$u0020causes$u0020java$u002Elang$u002EClassCastException$1(BuildInFutureTest.scala:39)
        at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:659)
        at scala.util.Success.$anonfun$map$1(Try.scala:255)
        at scala.util.Success.map(Try.scala:213)
        at scala.concurrent.Future.$anonfun$map$1(Future.scala:292)
        at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:33)
        at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:33)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
        at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
        at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
[error] Error: Total 2, Failed 0, Errors 2, Passed 0
[error] Error during tests:
[error]         wvlet.airframe.BuildInFutureTest

@takezoe takezoe force-pushed the build-in-future-test branch from cfc8756 to 4eeb193 Compare February 1, 2020 05:31
@takezoe takezoe changed the title Building components in Future causes error Building components in Future causes strange errors Feb 1, 2020
@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020

Trace log shows Surfaces of Config1, 2 objects are Surface.of[Object]. It looks like a bug of Surface.of[X]:

2020-01-31 21:59:36.193-0800  info [LifeCycleManager] [session:14e6df06] ======== STARTED ========  - (LifeCycleManager.scala:264)
2020-01-31 21:59:36.203-0800 debug [AirframeSession] [session:14e6df06] Get dependency [Object] at BuildInFutureTest.scala:30  - (AirframeSession.scala:168).FactoryBindingTest 0s
2020-01-31 21:59:36.204-0800 trace [AirframeSession] [session:14e6df06] Search bindings for Object, dependencies:[]  - (AirframeSession.scala:280)
2020-01-31 21:59:36.206-0800 trace [AirframeSession] [session:14e6df06] Search parent for Object  - (AirframeSession.scala:292)
2020-01-31 21:59:36.207-0800 trace [AirframeSession] [session:14e6df06] No binding is found for Object. Building the instance. create = false  - (AirframeSession.scala:361)
2020-01-31 21:59:36.208-0800 trace [AirframeSession] [session:14e6df06] No binding is found for Object  - (AirframeSession.scala:408)
2020-01-31 21:59:36.208-0800 trace [AirframeSession] [session:14e6df06] buildInstance Object, dependencies:[Object]  - (AirframeSession.scala:422)
2020-01-31 21:59:36.208-0800 trace [AirframeSession] Using the default constructor for building Object at BuildInFutureTest.scala:30  - (AirframeSession.scala:429)
2020-01-31 21:59:36.210-0800 trace [AirframeSession] [session:14e6df06] Search bindings for Int, dependencies:[Object]  - (AirframeSession.scala:280)
2020-01-31 21:59:36.211-0800 trace [AirframeSession] [session:14e6df06] Search parent for Int  - (AirframeSession.scala:292)
2020-01-31 21:59:36.211-0800 trace [AirframeSession] [session:14e6df06] No binding is found for Int. Building the instance. create = true  - (AirframeSession.scala:361)
2020-01-31 21:59:36.211-0800 trace [AirframeSession] [session:14e6df06] No binding is found for Int  - (AirframeSession.scala:408)
2020-01-31 21:59:36.211-0800 trace [AirframeSession] [session:14e6df06] buildInstance Int, dependencies:[Int <- Object]  - (AirframeSession.scala:422)```

@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020

A minimization is:

Future{
   Surface.of[Config1]  // wrongly returns Surface.of[Object]. 
}

@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020

A recent big change around Surface is #878. Let me check the cause.

@xerial xerial self-assigned this Feb 1, 2020
@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020 •
edited
Loading

@takezoe The cause is the global execution context of the Future, which cannot find Config1 class. This might be caused by sbt's layered class loader. For example, if we use our own execution context, all tests will pass:

//import scala.concurrent.ExecutionContext.Implicits.global

  private val ex               = Executors.newFixedThreadPool(1)
  private implicit val context = ExecutionContext.fromExecutor(ex)

@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020 •
edited
Loading

class loader hierarchy inside the test code (or using our own ExecutionContext):

-class sbt.internal.LayeredClassLoader
 -class sbt.internal.classpath.WrappedLoader
  -class sbt.internal.ScalaReflectClassLoader
   -class sbt.internal.classpath.WrappedLoader
    -class sbt.State$UncloseableURLLoader
     -class xsbt.boot.LibraryClassLoader 0s
      -class xsbt.boot.Launch$TestInterfaceLoader$3
       -class xsbt.boot.BootFilteredLoaders
        -class jdk.internal.loader.ClassLoaders$AppClassLoader
         -class jdk.internal.loader.ClassLoaders$PlatformClassLoader

Class loader hierarchy within Future when using the global context:

-class java.net.URLClassLoader
 -class java.net.URLClassLoader
  -class xsbt.boot.LibraryClassLoader
   -class xsbt.boot.Launch$TestInterfaceLoader
    -class xsbt.boot.BootFilteredLoader
     -class jdk.internal.loader.ClassLoaders$AppClassLoader
      -class jdk.internal.loader.ClassLoaders$PlatformClassLoader

@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020

@takezoe This is a bug of sbt's layered classloader, which might be initializing Future's global context by using a non-application class loader.

A workaround is adding this configuration:

  Test / classLoaderLayeringStrategy := ClassLoaderLayeringStrategy.Flat

@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020

Filed a bug ticket to sbt sbt/sbt#5410

@xerial
Copy link
Copy Markdown
Member

xerial commented Feb 1, 2020

@takezoe Although, it's a bug of sbt's layered class loader, we should define our own ExecutionContext when using Future like this:

  private val ex               = Executors.newCachedThreadPool()
  private implicit val context = ExecutionContext.fromExecutor(ex)

or using DI:

 private implicit val context = bind[ExecutionContextExecutor]

@xerial xerial mentioned this pull request Feb 2, 2020
Open
@takezoe
Copy link
Copy Markdown
Member Author

takezoe commented Feb 3, 2020

I see. Thanks for investigation!

@xerial
Copy link
Copy Markdown
Member

xerial commented Mar 3, 2020

Let me close this PR as we've found the root cause (sbt's class loader).

@xerial xerial closed this Mar 3, 2020
@xerial
Copy link
Copy Markdown
Member

xerial commented Mar 27, 2020

#1014 might be a fix for this issue.

@xerial xerial reopened this Mar 27, 2020
@codecov
Copy link
Copy Markdown

codecov Bot commented Mar 27, 2020 •
edited
Loading

Codecov Report

Merging #918 into master will not change coverage by %.
The diff coverage is n/a.

Impacted file tree graph

@@           Coverage Diff           @@
##           master     #918   +/-   ##
=======================================
  Coverage   81.96%   81.96%           
=======================================
  Files         269      269           
  Lines       10118    10118           
  Branches      692      692           
=======================================
  Hits         8293     8293           
  Misses       1825     1825

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 0e37977...0b8c2cc. Read the comment docs.

@xerial
Copy link
Copy Markdown
Member

xerial commented Mar 27, 2020 •
edited
Loading

After #1014, the error message has been changed like this:

- Building in Future causes java.lang.ClassCastException 13.86ms << error: class wvlet.airframe.Config1 cannot be cast to class wvlet.airframe.Config1 (wvlet.airframe.Config1 is in unnamed module of loader sbt.internal.LayeredClassLoader @f297f96; wvlet.airframe.Config1 is in unnamed module of loader sbt.internal.LayeredClassLoader @4cb9bb4d)

java.lang.ClassCastException: class wvlet.airframe.Config1 cannot be cast to class wvlet.airframe.Config1 (wvlet.airframe.Config1 is in unnamed module of loader sbt.internal.LayeredClassLoader @f297f96; wvlet.airframe.Config1 is in unnamed module of loader sbt.internal.LayeredClassLoader @4cb9bb4d)

This error means, Config1 is loaded by different classloaders and two instances of Config1 has been generated. I'll add a note about a workaround for avoiding such an issue.

@xerial xerial force-pushed the build-in-future-test branch from 612edab to 1eb78d0 Compare March 27, 2020 18:59
@xerial xerial merged commit a51b9ad into wvlet:master Mar 27, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

@xerial xerial

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@takezoe @xerial