Skip to content

[1.9.x] Fix dead lock between LoggerContext and Terminal #7191

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
Merged
merged 1 commit into from
Mar 28, 2023
Merged

[1.9.x] Fix dead lock between LoggerContext and Terminal #7191

merged 1 commit into from
Mar 28, 2023

Conversation

adpi2
Copy link
Member

@adpi2 adpi2 commented Mar 28, 2023

Using sbtn I found a deadlock between LoggerContext and Terminal:
The main thread locks the list of consoleAppenders in LoggerContext then it tries to lock the Terminal to write to it.
The sbt-task-progress-report-thread locks the Terminal to compute the progress report. When computing the progress report it tries to log something using the consoleAppenders in LoggerContext.

To fix this deadlock we can use a AtomicReference[scala.Vector[???]] instead of java.util.Vector[???].

Here the thread dump of the deadlock:

Found one Java-level deadlock:
=============================
"main":
  waiting to lock monitor 0x00007f6b05f16500 (object 0x000000072f39b378, a java.lang.Object),
  which is held by "sbt-task-progress-report-thread"
"sbt-task-progress-report-thread":
  waiting to lock monitor 0x00007f6a2036bb00 (object 0x000000072f392410, a java.util.Vector),
  which is held by "main"

Java stack information for the threads listed above:
===================================================
"main":
        at sbt.internal.util.Terminal$.withWriteLock(Terminal.scala:196)
        - waiting to lock <0x000000072f39b378> (a java.lang.Object)
        at sbt.internal.util.Terminal$LinePrintStream.println(Terminal.scala:474)
        at sbt.internal.util.ConsoleOut$$anon$1.println(ConsoleOut.scala:70)
        - locked <0x000000072dd302e0> (a sbt.internal.util.ConsoleOut$$anon$1)
        at sbt.internal.util.ConsoleOut$$anon$1.println(ConsoleOut.scala:65)
        - locked <0x000000072dd302e0> (a sbt.internal.util.ConsoleOut$$anon$1)
        at sbt.internal.util.ConsoleOut$Proxy$.println(ConsoleOut.scala:41)
        at sbt.internal.util.Appender.write(ConsoleAppender.scala:514)
        at sbt.internal.util.Appender.$anonfun$appendLog$1(ConsoleAppender.scala:492)
        at sbt.internal.util.Appender.$anonfun$appendLog$1$adapted(ConsoleAppender.scala:478)
        at sbt.internal.util.Appender$$Lambda$15564/0x0000000803c3f840.apply(Unknown Source)
        at scala.collection.Iterator.foreach(Iterator.scala:943)
        at scala.collection.Iterator.foreach$(Iterator.scala:943)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1431)
        at sbt.internal.util.Appender.appendLog(ConsoleAppender.scala:478)
        at sbt.internal.util.Appender.success(ConsoleAppender.scala:499)
        at sbt.internal.util.Appender.success$(ConsoleAppender.scala:498)
        at sbt.internal.util.ConsoleAppender.success(ConsoleAppender.scala:349)
        at sbt.internal.util.Appender.$anonfun$appendMessageContent$1(ConsoleAppender.scala:553)
        at sbt.internal.util.Appender.$anonfun$appendMessageContent$1$adapted(ConsoleAppender.scala:553)
        at sbt.internal.util.Appender$$Lambda$23225/0x00000008057b4840.apply(Unknown Source)
        at scala.collection.Iterator.foreach(Iterator.scala:943)
        at scala.collection.Iterator.foreach$(Iterator.scala:943)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1431)
        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 sbt.internal.util.Appender.appendEvent$1(ConsoleAppender.scala:553)
        at sbt.internal.util.Appender.appendMessageContent(ConsoleAppender.scala:566)
        at sbt.internal.util.Appender.appendObjectEvent(ConsoleAppender.scala:571)
        at sbt.internal.util.Appender.appendObjectEvent$(ConsoleAppender.scala:570)
        at sbt.internal.util.ConsoleAppender.appendObjectEvent(ConsoleAppender.scala:349)
        at sbt.util.LoggerContext$LoggerContextImpl$Log.$anonfun$log$4(LoggerContext.scala:129)
        at sbt.util.LoggerContext$LoggerContextImpl$Log$$Lambda$23222/0x00000008057b3040.accept(Unknown Source)
        at java.util.Vector.forEach(java.base@11.0.18/Vector.java:1394)
        - locked <0x000000072f392410> (a java.util.Vector)
        at sbt.util.LoggerContext$LoggerContextImpl$Log.log(LoggerContext.scala:127)
        at sbt.internal.util.ManagedLogger.logEvent(ManagedLogger.scala:92)
        at sbt.internal.util.ManagedLogger.infoEvent(ManagedLogger.scala:79)
        at sbt.internal.util.ManagedLogger.success(ManagedLogger.scala:48)
        at sbt.internal.Aggregation$.printSuccess(Aggregation.scala:137)
        at sbt.internal.Aggregation$.showRun(Aggregation.scala:83)
        at sbt.internal.Aggregation$.runTasks(Aggregation.scala:116)
        at sbt.internal.Aggregation$.$anonfun$applyDynamicTasks$4(Aggregation.scala:184)
        at sbt.internal.Aggregation$$$Lambda$23236/0x00000008057bb840.apply(Unknown Source)
        at sbt.Command$.$anonfun$applyEffect$2(Command.scala:145)
        at sbt.Command$$$Lambda$15735/0x0000000803cf5840.apply(Unknown Source)
        at sbt.internal.Act$.$anonfun$actParser0$8(Act.scala:499)
        at sbt.internal.Act$$$Lambda$23110/0x0000000805751840.apply(Unknown Source)
        at sbt.Command$.process(Command.scala:189)
        at sbt.MainLoop$.$anonfun$processCommand$5(MainLoop.scala:245)
        at sbt.MainLoop$$$Lambda$15621/0x0000000803c95840.apply(Unknown Source)
        at scala.Option.getOrElse(Option.scala:189)
        at sbt.MainLoop$.process$1(MainLoop.scala:245)
        at sbt.MainLoop$.processCommand(MainLoop.scala:276)
        at sbt.MainLoop$.$anonfun$next$5(MainLoop.scala:163)
        at sbt.MainLoop$$$Lambda$15558/0x0000000803c3c040.apply(Unknown Source)
        at sbt.State$StateOpsImpl$.runCmd$1(State.scala:289)
        at sbt.State$StateOpsImpl$.process$extension(State.scala:325)
        at sbt.MainLoop$.$anonfun$next$4(MainLoop.scala:163)
        at sbt.MainLoop$$$Lambda$15557/0x0000000803c3b840.apply(Unknown Source)
        at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:23)
        at sbt.MainLoop$.next(MainLoop.scala:163)
        at sbt.MainLoop$.run(MainLoop.scala:144)
        at sbt.MainLoop$.$anonfun$runWithNewLog$1(MainLoop.scala:119)
        at sbt.MainLoop$$$Lambda$15474/0x0000000803bdd040.apply(Unknown Source)
        at sbt.io.Using.apply(Using.scala:27)
        at sbt.MainLoop$.runWithNewLog(MainLoop.scala:112)
        at sbt.MainLoop$.runAndClearLast(MainLoop.scala:66)
        at sbt.MainLoop$.runLoggedLoop(MainLoop.scala:51)
        at sbt.MainLoop$.runLogged(MainLoop.scala:42)
        at sbt.StandardMain$.runManaged(Main.scala:223)
        at sbt.xMain$.$anonfun$run$11(Main.scala:133)
        at sbt.xMain$$$Lambda$15144/0x00000008036d2440.apply(Unknown Source)
        at scala.util.DynamicVariable.withValue(DynamicVariable.scala:62)
        at scala.Console$.withIn(Console.scala:230)
        at sbt.internal.util.Terminal$.withIn(Terminal.scala:578)
        at sbt.internal.util.Terminal$.$anonfun$withStreams$1(Terminal.scala:358)
        at sbt.internal.util.Terminal$$$Lambda$15252/0x0000000803acd440.apply(Unknown Source)
        at scala.util.DynamicVariable.withValue(DynamicVariable.scala:62)
        at scala.Console$.withOut(Console.scala:167)
        at sbt.internal.util.Terminal$.$anonfun$withOut$2(Terminal.scala:568)
        at sbt.internal.util.Terminal$$$Lambda$15253/0x0000000803ace040.apply(Unknown Source)
        at scala.util.DynamicVariable.withValue(DynamicVariable.scala:62)
        at scala.Console$.withErr(Console.scala:196)
        at sbt.internal.util.Terminal$.withOut(Terminal.scala:568)
        at sbt.internal.util.Terminal$.withStreams(Terminal.scala:358)
        at sbt.xMain$.withStreams$1(Main.scala:87)
        at sbt.xMain$.run(Main.scala:121)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.18/Native Method)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.18/NativeMethodAccessorImpl.java:62)
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.18/DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(java.base@11.0.18/Method.java:566)
        at sbt.internal.XMainConfiguration.run(XMainConfiguration.java:57)
        at sbt.xMain.run(Main.scala:46)
        at xsbt.boot.Launch$.$anonfun$run$1(Launch.scala:149)
        at xsbt.boot.Launch$$$Lambda$104/0x000000080011f440.apply(Unknown Source)
        at xsbt.boot.Launch$.withContextLoader(Launch.scala:176)
        at xsbt.boot.Launch$.run(Launch.scala:149)
        at xsbt.boot.Launch$.$anonfun$apply$1(Launch.scala:44)
        at xsbt.boot.Launch$$$Lambda$76/0x00000008000f8040.apply(Unknown Source)
        at xsbt.boot.Launch$.launch(Launch.scala:159)
        at xsbt.boot.Launch$.apply(Launch.scala:44)
        at xsbt.boot.Launch$.apply(Launch.scala:21)
        at xsbt.boot.Boot$.runImpl(Boot.scala:78)
        at xsbt.boot.Boot$.run(Boot.scala:73)
        at xsbt.boot.Boot$.main(Boot.scala:21)
        at xsbt.boot.Boot.main(Boot.scala)
"sbt-task-progress-report-thread":
        at java.util.Vector.iterator(java.base@11.0.18/Vector.java:1264)
        - waiting to lock <0x000000072f392410> (a java.util.Vector)
        at scala.collection.convert.Wrappers$JListWrapper.iterator(Wrappers.scala:99)
        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.filterImpl(TraversableLike.scala:303)
        at scala.collection.TraversableLike.filterImpl$(TraversableLike.scala:297)
        at scala.collection.AbstractTraversable.filterImpl(Traversable.scala:108)
        at scala.collection.TraversableLike.filter(TraversableLike.scala:395)
        at scala.collection.TraversableLike.filter$(TraversableLike.scala:395)
        at scala.collection.AbstractTraversable.filter(Traversable.scala:108)
        at sbt.util.LoggerContext$LoggerContextImpl$Log.log(LoggerContext.scala:120)
        at sbt.internal.util.ManagedLogger.log(ManagedLogger.scala:41)
        at sbt.util.Logger.debug(Logger.scala:25)
        at sbt.internal.server.NetworkChannel.jsonRpcRequest(NetworkChannel.scala:628)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.$anonfun$getProperties$3(NetworkChannel.scala:747)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.$anonfun$getProperties$3$adapted(NetworkChannel.scala:747)
        at sbt.internal.server.NetworkChannel$NetworkTerminal$$Lambda$22691/0x0000000805697440.apply(Unknown Source)
        at sbt.internal.server.VirtualTerminal$.sendTerminalPropertiesQuery(VirtualTerminal.scala:73)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.getProperties(NetworkChannel.scala:747)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.$anonfun$getProperty$1(NetworkChannel.scala:780)
        at sbt.internal.server.NetworkChannel$NetworkTerminal$$Lambda$22701/0x000000080569c840.apply(Unknown Source)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.withThread(NetworkChannel.scala:771)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.getProperty(NetworkChannel.scala:782)
        at sbt.internal.server.NetworkChannel$NetworkTerminal.getWidth(NetworkChannel.scala:801)
        at sbt.internal.util.ProgressState$.$anonfun$updateProgressState$6(ProgressState.scala:193)
        at sbt.internal.util.ProgressState$$$Lambda$23126/0x000000080575c840.apply(Unknown Source)
        at scala.collection.immutable.List.flatMap(List.scala:366)
        at sbt.internal.util.ProgressState$.$anonfun$updateProgressState$2(ProgressState.scala:192)
        at sbt.internal.util.ProgressState$.$anonfun$updateProgressState$2$adapted(ProgressState.scala:180)
        at sbt.internal.util.ProgressState$$$Lambda$22719/0x00000008056a6840.apply(Unknown Source)
        at sbt.internal.util.Terminal$TerminalImpl.withPrintStream(Terminal.scala:995)
        - locked <0x000000072f39b378> (a java.lang.Object)
        at sbt.internal.util.ProgressState$.updateProgressState(ProgressState.scala:180)
        at sbt.internal.CommandExchange.$anonfun$updateProgress$5(CommandExchange.scala:408)
        at sbt.internal.CommandExchange.$anonfun$updateProgress$5$adapted(CommandExchange.scala:408)
        at sbt.internal.CommandExchange$$Lambda$17606/0x0000000804392840.apply(Unknown Source)
        at scala.collection.immutable.List.foreach(List.scala:431)
        at sbt.internal.CommandExchange.updateProgress(CommandExchange.scala:408)
        at sbt.internal.TaskProgress.appendProgress(TaskProgress.scala:159)
        at sbt.internal.TaskProgress.report(TaskProgress.scala:185)
        at sbt.internal.TaskProgress.$anonfun$doReport$1(TaskProgress.scala:86)
        at sbt.internal.TaskProgress$$Lambda$17943/0x0000000804498c40.run(Unknown Source)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.18/Executors.java:515)
        at java.util.concurrent.FutureTask.run(java.base@11.0.18/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.18/ThreadPoolExecutor.java:1128)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.18/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11.0.18/Thread.java:829)

Found 1 deadlock.

@adpi2 adpi2 requested a review from eed3si9n March 28, 2023 12:18
eed3si9n
eed3si9n approved these changes Mar 28, 2023
View reviewed changes
Copy link
Member

@eed3si9n eed3si9n left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks!

@SethTisue
Copy link
Member

SethTisue commented Mar 28, 2023 •
edited
Loading

I will make a fresh attempt to turn myself into an sbtn user once 1.9.0-RC1 is available.

@adpi2 adpi2 merged commit 60ea2a5 into sbt:1.9.x Mar 28, 2023
@alexklibisz alexklibisz mentioned this pull request Jun 9, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@eed3si9n eed3si9n eed3si9n approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@adpi2 @SethTisue @eed3si9n