search

jaliss / securesocial

A module that provides OAuth, OAuth2 and OpenID authentication for Play Framework applications
http://www.securesocial.ws
Apache License 2.0
1.19k stars 511 forks source link

Cannot exit console #268

Closed rvangsgaard closed 11 years ago

rvangsgaard commented 11 years ago

After enabling SecureSocial in my Play 2.1.3 app, I cannot quit the Play console using CTRL+D or typing "exit" - it just hangs.

Of course it can be my combination of plugins, but have you experienced similar behaviour?

jaliss commented 11 years ago

I have not seen that happening. It might help to get a thread dump to get a clue of what might be preventing the JVM from exiting.

rvangsgaard commented 11 years ago

Yes, I understand - would first check if it was a known bug.

Can you identify if the session "cleaner" i hanging here?

Full thread dump OpenJDK 64-Bit Server VM (23.7-b01 mixed mode):

"play-scheduler-1" prio=10 tid=0x00007fd95c69a800 nid=0x1819 waiting on condition [0x00007fd9649da000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at akka.util.internal.HashedWheelTimer$Worker.waitForNextTick(HashedWheelTimer.java:404)
    at akka.util.internal.HashedWheelTimer$Worker.run(HashedWheelTimer.java:309)
    at java.lang.Thread.run(Thread.java:724)

"play-akka.actor.default-dispatcher-2" prio=10 tid=0x00007fd95c695000 nid=0x1816 waiting on condition [0x00007fd964cdd000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e20436c8> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
    at scala.concurrent.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:1594)
    at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478)
    at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104)

"application-scheduler-1" prio=10 tid=0x00007fd95c690800 nid=0x1815 waiting on condition [0x00007fd964dde000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at akka.util.internal.HashedWheelTimer$Worker.waitForNextTick(HashedWheelTimer.java:404)
    at akka.util.internal.HashedWheelTimer$Worker.run(HashedWheelTimer.java:309)
    at java.lang.Thread.run(Thread.java:724)

"application-akka.actor.default-dispatcher-4" prio=10 tid=0x00007fd95c67d800 nid=0x1812 waiting on condition [0x00007fd9650e1000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e156b2a8> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
    at scala.concurrent.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:1594)
    at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478)
    at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104)

"Play" daemon prio=10 tid=0x00007fd95c590000 nid=0x180b in Object.wait() [0x00007fd9653e4000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f1b6e3e0> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000f1b6e3e0> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

"Attach Listener" daemon prio=10 tid=0x00007fd970001000 nid=0x1806 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"BoneCP-pool-watch-thread" daemon prio=10 tid=0x00007fd95c585000 nid=0x1805 waiting on condition [0x00007fd965c6a000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000f1e55928> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:374)
    at com.jolbox.bonecp.PoolWatchThread.run(PoolWatchThread.java:77)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

"BoneCP-max-alive-scheduler" daemon prio=10 tid=0x00007fd95c583800 nid=0x1804 waiting on condition [0x00007fd965d6b000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000f219d9a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

"BoneCP-keep-alive-scheduler" daemon prio=10 tid=0x00007fd95c582800 nid=0x1803 sleeping[0x00007fd965e6c000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at com.jolbox.bonecp.ConnectionTesterThread.run(ConnectionTesterThread.java:134)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.java:166)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

"com.google.common.base.internal.Finalizer" daemon prio=10 tid=0x00007fd95c50d000 nid=0x1800 in Object.wait() [0x00007fd965f6d000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f1ddfdd8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
    - locked <0x00000000f1ddfdd8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
    at com.google.common.base.internal.Finalizer.run(Finalizer.java:125)
    at java.lang.Thread.run(Thread.java:724)

"Abandoned connection cleanup thread" daemon prio=10 tid=0x00007fd95c414800 nid=0x17ff in Object.wait() [0x00007fd96606e000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000f1c95180> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
    - locked <0x00000000f1c95180> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
    at com.mysql.jdbc.NonRegisteringDriver$1.run(NonRegisteringDriver.java:93)

"pool-17-thread-9" prio=10 tid=0x00007fd99c693000 nid=0x17ec in Object.wait() [0x00007fd966e24000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e2035b28> (a java.lang.Thread)
    at java.lang.Thread.join(Thread.java:1260)
    - locked <0x00000000e2035b28> (a java.lang.Thread)
    at java.lang.Thread.join(Thread.java:1334)
    at sbt.TrapExit$.sbt$TrapExit$$waitOnThread(TrapExit.scala:88)
    at sbt.TrapExit$$anonfun$waitForExit$1.apply(TrapExit.scala:78)
    at sbt.TrapExit$$anonfun$waitForExit$1.apply(TrapExit.scala:74)
    at scala.collection.Iterator$class.foreach(Iterator.scala:772)
    at scala.collection.JavaConversions$JIteratorWrapper.foreach(JavaConversions.scala:573)
    at scala.collection.IterableLike$class.foreach(IterableLike.scala:73)
    at scala.collection.JavaConversions$JSetWrapper.foreach(JavaConversions.scala:661)
    at sbt.TrapExit$.processThreads(TrapExit.scala:138)
    at sbt.TrapExit$.waitForExit(TrapExit.scala:74)
    at sbt.TrapExit$.apply(TrapExit.scala:53)
    at sbt.Run$.executeTrapExit(Run.scala:91)
    at sbt.Console$$anonfun$apply$2.apply(Console.scala:24)
    at sbt.Console$$anonfun$apply$2.apply(Console.scala:24)
    at sbt.JLine$$anonfun$withJLine$1.apply(LineReader.scala:88)
    at sbt.JLine$$anonfun$withJLine$1.apply(LineReader.scala:86)
    at sbt.JLine$.withTerminal(LineReader.scala:70)
    - locked <0x00000000a0500630> (a jline.UnixTerminal)
    - locked <0x00000000a14822c8> (a sbt.JLine$)
    at sbt.JLine$.withJLine(LineReader.scala:86)
    at sbt.Console.apply(Console.scala:24)
    at sbt.Console.apply(Console.scala:19)
    at sbt.Defaults$$anonfun$consoleTask$1.apply(Defaults.scala:566)
    at sbt.Defaults$$anonfun$consoleTask$1.apply(Defaults.scala:564)
    at sbt.Scoped$$anonfun$hf8$1.apply(Structure.scala:584)
    at sbt.Scoped$$anonfun$hf8$1.apply(Structure.scala:584)
    at scala.Function1$$anonfun$compose$1.apply(Function1.scala:49)
    at sbt.Scoped$Reduced$$anonfun$combine$1$$anonfun$apply$12.apply(Structure.scala:311)
    at sbt.Scoped$Reduced$$anonfun$combine$1$$anonfun$apply$12.apply(Structure.scala:311)
    at sbt.$tilde$greater$$anonfun$$u2219$1.apply(TypeFunctions.scala:41)
    at sbt.std.Transform$$anon$5.work(System.scala:71)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:232)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:232)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:18)
    at sbt.Execute.work(Execute.scala:238)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:232)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:232)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:160)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:30)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.java:166)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.java:166)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

"Service Thread" daemon prio=10 tid=0x00007fd99c1db800 nid=0x14e8 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007fd99c1d9000 nid=0x14e7 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007fd99c1d6000 nid=0x14e6 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007fd99c1d4000 nid=0x14e5 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007fd99c179800 nid=0x14e4 in Object.wait() [0x00007fd998dfc000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000a06b2a10> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
    - locked <0x00000000a06b2a10> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:189)

"Reference Handler" daemon prio=10 tid=0x00007fd99c177000 nid=0x14e3 in Object.wait() [0x00007fd998efd000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000a06b25c0> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:503)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
    - locked <0x00000000a06b25c0> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00007fd99c009800 nid=0x14dd waiting on condition [0x00007fd9a5e40000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000a1868598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ExecutorCompletionService.take(ExecutorCompletionService.java:193)
    at sbt.ConcurrentRestrictions$$anon$4.take(ConcurrentRestrictions.scala:196)
    at sbt.Execute.next$1(Execute.scala:85)
    at sbt.Execute.processAll(Execute.scala:88)
    at sbt.Execute.runKeep(Execute.scala:68)
    at sbt.EvaluateTask$.run$1(EvaluateTask.scala:162)
    at sbt.EvaluateTask$.runTask(EvaluateTask.scala:177)
    at sbt.Aggregation$$anonfun$4.apply(Aggregation.scala:46)
    at sbt.Aggregation$$anonfun$4.apply(Aggregation.scala:44)
    at sbt.EvaluateTask$.withStreams(EvaluateTask.scala:137)
    at sbt.Aggregation$.runTasksWithResult(Aggregation.scala:44)
    at sbt.Aggregation$.runTasks(Aggregation.scala:59)
    at sbt.Aggregation$$anonfun$applyTasks$1.apply(Aggregation.scala:31)
    at sbt.Aggregation$$anonfun$applyTasks$1.apply(Aggregation.scala:30)
    at sbt.Command$$anonfun$applyEffect$2$$anonfun$apply$3.apply(Command.scala:62)
    at sbt.Command$$anonfun$applyEffect$2$$anonfun$apply$3.apply(Command.scala:62)
    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:170)
    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$.run(Launch.scala:55)
    at xsbt.boot.Launch$$anonfun$explicit$1.apply(Launch.scala:45)
    at xsbt.boot.Launch$.launch(Launch.scala:69)
    at xsbt.boot.Launch$.apply(Launch.scala:16)
    at xsbt.boot.Boot$.runImpl(Boot.scala:31)
    at xsbt.boot.Boot$.main(Boot.scala:20)
    at xsbt.boot.Boot.main(Boot.scala)

"VM Thread" prio=10 tid=0x00007fd99c16f000 nid=0x14e2 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007fd99c017000 nid=0x14de runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007fd99c019000 nid=0x14df runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007fd99c01b000 nid=0x14e0 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007fd99c01c800 nid=0x14e1 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007fd99c1e6000 nid=0x14e9 waiting on condition 

JNI global references: 250

Heap
 PSYoungGen      total 322752K, used 148889K [0x00000000e0000000, 0x00000000f99b0000, 0x0000000100000000)
  eden space 289728K, 39% used [0x00000000e0000000,0x00000000e712b6d8,0x00000000f1af0000)
  from space 33024K, 99% used [0x00000000f1af0000,0x00000000f3b2b020,0x00000000f3b30000)
  to   space 49216K, 0% used [0x00000000f69a0000,0x00000000f69a0000,0x00000000f99b0000)
 ParOldGen       total 410304K, used 222895K [0x00000000a0000000, 0x00000000b90b0000, 0x00000000e0000000)
  object space 410304K, 54% used [0x00000000a0000000,0x00000000ad9abe58,0x00000000b90b0000)
 PSPermGen       total 158464K, used 97431K [0x0000000088000000, 0x0000000091ac0000, 0x00000000a0000000)
  object space 158464K, 61% used [0x0000000088000000,0x000000008df25c98,0x0000000091ac0000)
rvangsgaard commented 11 years ago

Actually, after creating the thread dump, this showed up in the console

2013-08-20 22:14:01,836 - [DEBUG] - from application in play-akka.actor.default-dispatcher-2 
[securesocial] calling deleteExpiredTokens()

It looks like the securesocial thread is not a daemon, or not shutting down correctly?

rvangsgaard commented 11 years ago

The problem has vanished. We are multiple developers on the project and we have no clear indication of what the problem was. And nothing indicates it was related to SecureScocial.

tkawachi commented 10 years ago

I run into the same issue. I think there is some clean up issue with SecureSocial. I'll track down more.

tkawachi commented 10 years ago

Plugging my own UserServicePlugin in made the issue. play-scheduler-1 is sleeping after I call play.api.Play.stop().

I tried with following code from console:

val app = new play.core.StaticApplication(new java.io.File("."))
play.api.Play.stop()
:q # <- console hangs here
tkawachi commented 10 years ago

It might be an issue of Play or Akka. I'm not sure.