sbt main thread problem when running a project with nohup

[Luke Alford]

Hello! To get right to it, I am trying to build an autonomous environment where I can provide the benefits of sbt's auto-reloading without needing to actually run interactively. At this point I have a setup that does exactly what I want with the exception of the sbt main thread going crazy and eating 100% cpu. I am unsure of why this is the case, but because this is an unusual way of doing things I wanted to discuss it here before filing a bug.

First, some system information.

- CentOS release 6.5 (Final)

- java version "1.7.0_51"

Java(TM) SE Runtime Environment (build 1.7.0_51-b13)

Java HotSpot(TM) 64-Bit Server VM (build 24.51-b03, mixed mode)

- sbt (launched with 0.13.0, but the project then runs under 0.12.4)

I am orchestrating this system using chef, the script that kicks everything off will be run as root and here is what the constructed command for a particular project looks like. If this command is decomposed and run as hubuser without background and nohup, i.e. the normal way as an interactive shell, everything works exactly as would be expected.

su - hubuser -c "cd /home/hubuser/projects/cruise/tsttravel_synced; nohup java -Xms512M -Xss1M -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=1024M -Xmx4096M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/hubuser/projects/cruise -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=9054 -Dnet.tstllc.rmi.agent.port=9104 -javaagent:/opt/tst/jmx/jmx-agent.jar -jar /home/hubuser/projects/sbt-launch.jar 'project cruise-web' ';compile;run -Dhttp.port=9004 -Dap.credentials.file=/home/hubuser/projects/credentials.cfg -Dap.config.file=/home/hubuser/projects/app.cfg -Dlogger.file=/home/hubuser/projects/cruise/cruise-logback.xml' &>> /home/hubuser/projects/cruise/console.log &"

However, run this way the sbt main thread goes crazy. Here's how I came to that conclusion. I have not yet dug into the sbt codebase, but my blind stab in the dark is that screwing with signals and the shell like this somehow causes bizarre behavior. Any sbt devs have a better educated guess?

1) last lines in the console.log, pretty standard stuff.

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

(Server started, use Ctrl+D to stop and go back to the console...)

2) top showing processes, nothing is happening but the cpu load never goes away.

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

14037 hubuser   20   0 8540m 1.6g  25m S 100.0 10.5   3:39.94 java

3) top showing native threads from the same run.

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

14044 hubuser   20   0 8540m 1.6g  25m R 100.0 10.5  15:14.45 java

4) finally, the salient part of the thread dump. 0x36dc = 14044

kill -3 14037

"main" prio=10 tid=0x00007fdbb400a800 nid=0x36dc runnable [0x00007fdbbaf76000]

   java.lang.Thread.State: RUNNABLE

at java.io.FileInputStream.read0(Native Method)

at java.io.FileInputStream.read(FileInputStream.java:210)

at jline.Terminal.readCharacter(Terminal.java:99)

at jline.UnixTerminal.readVirtualKey(UnixTerminal.java:122)

at jline.ConsoleReader.readVirtualKey(ConsoleReader.java:1606)

at play.PlayConsoleInteractionMode$.waitEOF$1(PlayInteractionMode.scala:29)

at play.PlayConsoleInteractionMode$$anonfun$waitForKey$1.apply$mcV$sp(PlayInteractionMode.scala:36)

at play.PlayConsoleInteractionMode$.doWithoutEcho(PlayInteractionMode.scala:41)

at play.PlayConsoleInteractionMode$.waitForKey(PlayInteractionMode.scala:36)

at play.PlayConsoleInteractionMode$.waitForCancel(PlayInteractionMode.scala:45)

at sbt.PlayCommands$$anonfun$createPlayRunCommand$1$$anonfun$57.apply(PlayCommands.scala:671)

at sbt.PlayCommands$$anonfun$createPlayRunCommand$1$$anonfun$57.apply(PlayCommands.scala:523)

at scala.Either$RightProjection.map(Either.scala:533)

at sbt.PlayCommands$$anonfun$createPlayRunCommand$1.apply(PlayCommands.scala:523)

at sbt.PlayCommands$$anonfun$createPlayRunCommand$1.apply(PlayCommands.scala:497)

at sbt.Command$$anonfun$sbt$Command$$apply1$1$$anonfun$apply$6.apply(Command.scala:72)

at sbt.Command$.process(Command.scala:90)

at sbt.MainLoop$$anonfun$next$1$$anonfun$apply$1.apply(MainLoop.scala:71)

at sbt.MainLoop$$anonfun$next$1$$anonfun$apply$1.apply(MainLoop.scala:71)

at sbt.State$$anon$2.process(State.scala:171)

at sbt.MainLoop$$anonfun$next$1.apply(MainLoop.scala:71)

at sbt.MainLoop$$anonfun$next$1.apply(MainLoop.scala:71)

at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:18)

at sbt.MainLoop$.next(MainLoop.scala:71)

at sbt.MainLoop$.run(MainLoop.scala:64)

at sbt.MainLoop$$anonfun$runWithNewLog$1.apply(MainLoop.scala:53)

at sbt.MainLoop$$anonfun$runWithNewLog$1.apply(MainLoop.scala:50)

at sbt.Using.apply(Using.scala:25)

at sbt.MainLoop$.runWithNewLog(MainLoop.scala:50)

at sbt.MainLoop$.runAndClearLast(MainLoop.scala:33)

at sbt.MainLoop$.runLoggedLoop(MainLoop.scala:17)

at sbt.MainLoop$.runLogged(MainLoop.scala:13)

at sbt.xMain.run(Main.scala:26)

at xsbt.boot.Launch$$anonfun$run$1.apply(Launch.scala:57)

at xsbt.boot.Launch$.withContextLoader(Launch.scala:77)

at xsbt.boot.Launch$.run(Launch.scala:57)

at xsbt.boot.Launch$$anonfun$explicit$1.apply(Launch.scala:45)

at xsbt.boot.Launch$.launch(Launch.scala:65)

at xsbt.boot.Launch$.apply(Launch.scala:16)

at xsbt.boot.Boot$.runImpl(Boot.scala:32)

at xsbt.boot.Boot$.main(Boot.scala:21)

at xsbt.boot.Boot.main(Boot.scala)

[Josh Suereth]

Answers inline:

On Thu, May 1, 2014 at 3:48 PM, Luke Alford <laa...@gmail.com> wrote:

Hello! To get right to it, I am trying to build an autonomous environment where I can provide the benefits of sbt's auto-reloading without needing to actually run interactively. At this point I have a setup that does exactly what I want with the exception of the sbt main thread going crazy and eating 100% cpu. I am unsure of why this is the case, but because this is an unusual way of doing things I wanted to discuss it here before filing a bug.

First, some system information.

- CentOS release 6.5 (Final)

- java version "1.7.0_51"

Java(TM) SE Runtime Environment (build 1.7.0_51-b13)

Java HotSpot(TM) 64-Bit Server VM (build 24.51-b03, mixed mode)

- sbt (launched with 0.13.0, but the project then runs under 0.12.4)

I am orchestrating this system using chef, the script that kicks everything off will be run as root and here is what the constructed command for a particular project looks like. If this command is decomposed and run as hubuser without background and nohup, i.e. the normal way as an interactive shell, everything works exactly as would be expected.

su - hubuser -c "cd /home/hubuser/projects/cruise/tsttravel_synced; nohup java -Xms512M -Xss1M -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=1024M -Xmx4096M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/hubuser/projects/cruise -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=9054 -Dnet.tstllc.rmi.agent.port=9104 -javaagent:/opt/tst/jmx/jmx-agent.jar -jar /home/hubuser/projects/sbt-launch.jar 'project cruise-web' ';compile;run -Dhttp.port=9004 -Dap.credentials.file=/home/hubuser/projects/credentials.cfg -Dap.config.file=/home/hubuser/projects/app.cfg -Dlogger.file=/home/hubuser/projects/cruise/cruise-logback.xml' &>> /home/hubuser/projects/cruise/console.log &"

However, run this way the sbt main thread goes crazy. Here's how I came to that conclusion. I have not yet dug into the sbt codebase, but my blind stab in the dark is that screwing with signals and the shell like this somehow causes bizarre behavior. Any sbt devs have a better educated guess?

1) last lines in the console.log, pretty standard stuff.

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

(Server started, use Ctrl+D to stop and go back to the console...)

So this is play application?  Your hint there is "Ctrl+D" waiting.  Play has its own "Wait for Ctrl+D" code which I suspect is causing some of the issues here.  Specifically ConsoleReader.readVirtualKey call you see in #4.   Likely this is your cause of woe, as you have no real STDIN, and jline may not handle that case correctly.   Play is not designed for non-interactive mode by default, but we added a hook for Activator:

https://github.com/playframework/playframework/blob/master/framework/src/sbt-plugin/src/main/scala/play/PlayInteractionMode.scala#L9-L24

If you look at the default implementation (which you can mostly blame me for) we may not be detecting nohup correctly.   You can override that implementation with a setting:  https://github.com/playframework/playframework/blob/master/framework/src/sbt-plugin/src/main/scala/PlaySettings.scala#L183

Write your own and get it right, then give us a pull request!

 

2) top showing processes, nothing is happening but the cpu load never goes away.

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

14037 hubuser   20   0 8540m 1.6g  25m S 100.0 10.5   3:39.94 java

Yeah, this looks super bad.  I wonder why it busywaits on nohup....

 

--
You received this message because you are subscribed to the Google Groups "sbt-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sbt-dev+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/sbt-dev/38752d8a-08b3-4ab4-a6a8-28e0910ada0a%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Luke Alford]

Thanks for the feedback Josh, very useful information about the PlayInteractionMode and settings hook. You are definitely correct that we are running play applications, the github links you sent were on master but the hook also looks to be present in the 2.1.x branch (our projects are still on 2.1.5, the 2.2 upgrade has been on hold with the need to port an sbt/grunt plugin to 0.13.x and getting everyone on board with the new results model). I will experiment with overriding that mode and if I can get something to work I will certainly send in a pull request.

Thanks!

[Luke Alford]

From Josh's pointers I've made some progress on solving my particular problem, though not in a particularly good style. When running something as nohup, stdin will no longer be a terminal device and as such this seems to make the jline ConsoleReader no longer wait on input. Since none was ever going to come anyway this doesn't much matter, I just needed to slow down the loop. To test this, I overrode the hook as mentioned and simply shoved a sleep into the key reader. However, as a side effect of this hack I no longer seem to be able to run some asset compilation commands directly.

No longer works:

";npm install;bower install;grunt;compile;run ..."

Still works, and without any busy waiting cpu consumption (when the npm, bower, and grunt commands have been rolled into an sbt plugin, which still seems to be able to execute them successfully):

";compile;run ..."

Here's the hack I threw into my BuildSettings.scala file to override the hook with. I'll keep kicking around ideas for a better solution to the problem, particularly since I still need to be able to run asset compilation in our legacy manner until all of our projects have been ported to the sbt grunt plugin.

import play.PlayInteractionMode

object DirtyNoInteractionMode extends PlayInteractionMode {

  private val consoleReader = new jline.ConsoleReader

  private def waitForKey(): Unit = {

    def waitEOF(): Unit = {

      Thread.sleep(1000) // force slowness since consoleReader does not seem to block anymore once nohup removes the stdin terminal device

      consoleReader.readVirtualKey() match {

        case 4 => // STOP

        case 11 => consoleReader.clearScreen(); waitEOF()

        case 10 => println(); waitEOF()

        case _ => waitEOF()

      }

    }

    doWithoutEcho(waitEOF())

  }

  override def doWithoutEcho(f: => Unit): Unit = {

    consoleReader.getTerminal.disableEcho()

    try f

    finally consoleReader.getTerminal.enableEcho()

  }

  override def waitForCancel(): Unit = waitForKey()

  override def toString = "Console Interaction Mode"

}

On Thursday, May 1, 2014 10:15:58 PM UTC-4, Josh Suereth wrote:

[Luke Alford]

To close the loop on this one, I settled on a cleaner hack to get around the problem of wanting to keep the command in interactive mode running even though the console is gone. The underlying problem is that jline's ConsoleReader returns -1 (or ConsoleOptions.MOVE_TO_BEG) without even trying to read the stream when eof is set (which it is because stdin has been closed by nohup). The default implementation of PlayInteractionMode in play's sbt plugin hits the catch all in the match and keeps the loop running with no pause (thus the 100% cpu consumption and infinite loop).

To solve my problem, I just added a pattern match for the -1 response that sleeps and continues. It's still a hack though since I'm really just forcing the interactive program to stay alive even though the means of interacting with it is dead. A better idea might be to support the concept of not being interactive at all, but still running with file watchers and class loaders that make the auto-reloading possible. That I am sure is a much larger effort, and probably not even something most people would find useful.

In the meantime, if you're trying to accomplish the same thing I am you can do so with the following code. Josh, if you think this is a worthwhile addition to the default implementation I'm happy to send in a pull request.

1) override the play settings hook in your build

    play.Project.playInteractionMode := IgnoreClosedConsoleInteractionMode

2) add IgnoreClosedConsoleInteractionMode object to your build

    import play.PlayInteractionMode

    object IgnoreClosedConsoleInteractionMode extends PlayInteractionMode {

      import jline.{ConsoleReader, ConsoleOperations}

      import ConsoleOperations._

    

      private val consoleReader = new ConsoleReader

    

      private def waitForKey(): Unit = {

        def waitEOF(): Unit = {

          val key = consoleReader.readVirtualKey()

          key match {

            case CTRL_D => // STOP

            case CTRL_K => consoleReader.clearScreen(); waitEOF()

            case 10 => println(); waitEOF()

            // When running nohup, jline's ConsoleReader constantly returns EOF since stdin is gone.

            // The interactive shell is dead but trapping this, slowing down the loop, and keeping the thread alive allow the command to cotinue executing.

            case MOVE_TO_BEG => Thread.sleep(500); waitEOF()

            case _ => waitEOF()

          }

        }

        doWithoutEcho(waitEOF())

      }

    

      override def doWithoutEcho(f: => Unit): Unit = {

        consoleReader.getTerminal.disableEcho()

        try f

        finally consoleReader.getTerminal.enableEcho()

      }

    

      override def waitForCancel(): Unit = waitForKey()

    

      override def toString = "Ignore Closed Console Interaction Mode"

    }

[Josh Suereth]

On Mon, May 5, 2014 at 4:12 PM, Luke Alford <laa...@gmail.com> wrote:

To close the loop on this one, I settled on a cleaner hack to get around the problem of wanting to keep the command in interactive mode running even though the console is gone. The underlying problem is that jline's ConsoleReader returns -1 (or ConsoleOptions.MOVE_TO_BEG) without even trying to read the stream when eof is set (which it is because stdin has been closed by nohup). The default implementation of PlayInteractionMode in play's sbt plugin hits the catch all in the match and keeps the loop running with no pause (thus the 100% cpu consumption and infinite loop).

To solve my problem, I just added a pattern match for the -1 response that sleeps and continues. It's still a hack though since I'm really just forcing the interactive program to stay alive even though the means of interacting with it is dead. A better idea might be to support the concept of not being interactive at all, but still running with file watchers and class loaders that make the auto-reloading possible. That I am sure is a much larger effort, and probably not even something most people would find useful.

In the meantime, if you're trying to accomplish the same thing I am you can do so with the following code. Josh, if you think this is a worthwhile addition to the default implementation I'm happy to send in a pull request.

1) override the play settings hook in your build

    play.Project.playInteractionMode := IgnoreClosedConsoleInteractionMode

2) add IgnoreClosedConsoleInteractionMode object to your build

    import play.PlayInteractionMode

    object IgnoreClosedConsoleInteractionMode extends PlayInteractionMode {

      import jline.{ConsoleReader, ConsoleOperations}

      import ConsoleOperations._

    

      private val consoleReader = new ConsoleReader

    

      private def waitForKey(): Unit = {

        def waitEOF(): Unit = {

          val key = consoleReader.readVirtualKey()

          key match {

            case CTRL_D => // STOP

            case CTRL_K => consoleReader.clearScreen(); waitEOF()

            case 10 => println(); waitEOF()

            // When running nohup, jline's ConsoleReader constantly returns EOF since stdin is gone.

            // The interactive shell is dead but trapping this, slowing down the loop, and keeping the thread alive allow the command to cotinue executing.

            case MOVE_TO_BEG => Thread.sleep(500); waitEOF()

Why not, here, register something to capture signals (like sigterm) and then just have the thread "block" (or park) until it receives a signal that it should wake up and be done.

Otherwise great diagnosis and fix!