Project

General

Profile

Task #5624

Task #5582: TTS-NG failing tests

TTS-NG hangs

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago. Updated over 1 year ago.

Status:
Closed
Priority:
Normal
Start date:
Due date:
2017-06-09
% Done:

100%

Estimated time:

Description

From time to time TTS-NG hangs on WebSocket-related tests and the only way to fix it is to kill it. As a result, we are losing results of this run and other tasks within our build queue are locked.

signature.asc (455 Bytes) signature.asc Wojciech Kapcia, 2017-06-07 02:52 PM

Associated revisions

Revision e35c14f8 (diff)
Added by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

#5624: fixed possible lock if Jaxmpp::login() method throws an exception and login(true) was called

History

#1 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

  • Status changed from New to In QA
  • Assignee changed from Andrzej Wójcik to Wojciech Kapcia
  • % Done changed from 0 to 100

I tried to replicate this issue locally and were unable to do so. As it is rather important to fix it, I reviewed the source code of a test case and Jaxmpp and found a possible race condition in Jaxmpp which could lead to the thread being locked during synchronous login to XMPP server.

Adding small deal within this code I was able to confirm that Jaxmpp may lead to thread locks in this case during test cases, so I fixed this race condition. Now I was not able to replicate this issue, even with introduced time delay.

In my opinion, this issue is fixed and should not occur anymore. We need to wait for a few runs on Jenkins jobs to confirm that this issue is fixed.

#2 Updated by Wojciech Kapcia TigaseTeam over 1 year ago

  • % Done changed from 100 to 80

#3 Updated by Wojciech Kapcia TigaseTeam over 1 year ago

  • Due date set to 2017-06-09
  • Status changed from In QA to Feedback
  • Assignee changed from Wojciech Kapcia to Andrzej Wójcik

It always (from my observation) gets stuck on one test class: tigase.tests.server.TestWebSocketConnectivity and it happende again: http://build.tigase.org/jenkins/job/private-TTS-NG-tests-runner/34/console

Below is the test log with ST and list of processes at that time (as Jenkins should terminate stuck process after timeout)

tigase.jaxmpp.core.client.Connector$DisconnectedHandler$DisconnectedEvent@1a9276ca
2017-06-06 01:39:54 | tigase.jaxmpp.core.client.JaxmppCore$LoggedOutHandler$LoggedOutEvent@75b7cf87
2017-06-06 01:39:54 | null / [TestClass name=class tigase.tests.server.TestWebSocketConnectivity]
2017-06-06 01:39:54 | ------------------------------------
2017-06-06 04:55:40
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.66-b17 mixed mode):

"Thread-6" #90 prio=5 os_prio=0 tid=0x00007f2e3a0ab000 nid=0x1dea runnable [0x00007f2dfc38d000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    - locked <0x0000000739bb25d8> (a java.lang.UNIXProcess$ProcessPipeInputStream)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x0000000739bb25c0> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.readLine(BufferedReader.java:324)
    - locked <0x0000000739bb25c0> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:389)
    at org.apache.maven.surefire.shade.org.apache.maven.shared.utils.cli.StreamPumper.run(StreamPumper.java:66)

"Thread-5" #89 prio=5 os_prio=0 tid=0x00007f2e3a0aa000 nid=0x1de8 runnable [0x00007f2dfc48e000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    - locked <0x0000000739daa248> (a java.lang.UNIXProcess$ProcessPipeInputStream)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x0000000739daa230> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.readLine(BufferedReader.java:324)
    - locked <0x0000000739daa230> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:389)
    at org.apache.maven.surefire.shade.org.apache.maven.shared.utils.cli.StreamPumper.run(StreamPumper.java:66)

"ThreadedStreamConsumer" #88 prio=5 os_prio=0 tid=0x00007f2e3a061000 nid=0x1de6 waiting on condition [0x00007f2e181c5000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000000739bb6fd8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:68)
    at java.lang.Thread.run(Thread.java:745)

"Java2D Disposer" #87 daemon prio=10 os_prio=0 tid=0x00007f2e39c66800 nid=0x1ddf in Object.wait() [0x00007f2e18f87000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0000000739f50110> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x0000000739f50110> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at sun.java2d.Disposer.run(Disposer.java:148)
    at java.lang.Thread.run(Thread.java:745)

"resolver-5" #84 daemon prio=5 os_prio=0 tid=0x00007f2e38c1f800 nid=0x1ddd waiting on condition [0x00007f2e1be53000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000005c9454360> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"resolver-4" #83 daemon prio=5 os_prio=0 tid=0x00007f2e38c1e800 nid=0x1ddc waiting on condition [0x00007f2e1bf54000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000005c9454360> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"resolver-3" #82 daemon prio=5 os_prio=0 tid=0x00007f2e38c1d800 nid=0x1ddb waiting on condition [0x00007f2e21100000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000005c9454360> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"resolver-2" #81 daemon prio=5 os_prio=0 tid=0x00007f2e38c1d000 nid=0x1dda waiting on condition [0x00007f2e20366000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000005c9454360> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"resolver-1" #80 daemon prio=5 os_prio=0 tid=0x00007f2e38c1c000 nid=0x1dd9 waiting on condition [0x00007f2e21201000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000005c9454360> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

"process reaper" #75 daemon prio=10 os_prio=0 tid=0x00007f2e389e1800 nid=0x1dd2 runnable [0x00007f2e1bffe000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.UNIXProcess.waitForProcessExit(Native Method)
    at java.lang.UNIXProcess.lambda$initStreams$275(UNIXProcess.java:290)
    at java.lang.UNIXProcess$$Lambda$8/1956746660.run(Unknown Source)
    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:745)

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007f2e380ca800 nid=0x1d8d runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f2e380bd800 nid=0x1d8c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f2e380bb800 nid=0x1d8b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f2e380b8800 nid=0x1d8a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f2e380b7000 nid=0x1d89 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f2e3807f000 nid=0x1d88 in Object.wait() [0x00007f2e22648000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000005c92f22e0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000005c92f22e0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f2e3807d000 nid=0x1d87 in Object.wait() [0x00007f2e22749000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000005c9339578> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x00000005c9339578> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x00007f2e3800a000 nid=0x1d81 in Object.wait() [0x00007f2e41482000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0000000739ecde20> (a java.lang.UNIXProcess)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.UNIXProcess.waitFor(UNIXProcess.java:396)
    - locked <0x0000000739ecde20> (a java.lang.UNIXProcess)
    at org.apache.maven.surefire.shade.org.apache.maven.shared.utils.cli.CommandLineUtils$1.call(CommandLineUtils.java:202)
    at org.apache.maven.surefire.shade.org.apache.maven.shared.utils.cli.CommandLineUtils.executeCommandLine(CommandLineUtils.java:141)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:469)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:378)
    at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:165)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1019)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:853)
    at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:751)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

"VM Thread" os_prio=0 tid=0x00007f2e38078000 nid=0x1d86 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f2e3801f800 nid=0x1d82 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f2e38021000 nid=0x1d83 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f2e38023000 nid=0x1d84 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f2e38024800 nid=0x1d85 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f2e380cd800 nid=0x1d8e waiting on condition 

JNI global references: 280

Heap
 PSYoungGen      total 585728K, used 35457K [0x0000000718600000, 0x000000074f080000, 0x00000007c0000000)
  eden space 545792K, 1% used [0x0000000718600000,0x0000000718e57b18,0x0000000739b00000)
  from space 39936K, 67% used [0x0000000739b00000,0x000000073b548af0,0x000000073c200000)
  to   space 38912K, 0% used [0x000000074ca80000,0x000000074ca80000,0x000000074f080000)
 ParOldGen       total 444416K, used 57382K [0x00000005c9200000, 0x00000005e4400000, 0x0000000718600000)
  object space 444416K, 12% used [0x00000005c9200000,0x00000005cca09bb8,0x00000005e4400000)
 Metaspace       used 73562K, capacity 74434K, committed 75008K, reserved 1114112K
  class space    used 10087K, capacity 10402K, committed 10496K, reserved 1048576K
jenkins@build:~$ ps aux | grep java
jenkins   1963  0.5  2.5 4136660 854728 ?      Sl   Mar30 544:38 java -Dappserver.home=. -Dappserver.base=. -Djetty.logs=./logs -Djava.io.tmpdir=./temp -DAsyncLoggerConfig.WaitStrategy=Block -Darchiva.repositorySessionFactory.id=jcr -Darchiva.cassandra.configuration.file=./conf/archiva-cassandra.properties -XX:MaxPermSize=128m -Xms512m -Xmx512m -Djava.library.path=lib -classpath lib/wrapper.jar:lib/archiva-jetty-2.2.1.pom:lib/jetty-server-8.1.14.v20131031.jar:lib/javax.servlet-3.0.0.v201112011016.jar:lib/jetty-continuation-8.1.14.v20131031.jar:lib/jetty-http-8.1.14.v20131031.jar:lib/jetty-io-8.1.14.v20131031.jar:lib/jetty-jndi-8.1.14.v20131031.jar:lib/javax.mail.glassfish-1.4.1.v201005082020.jar:lib/javax.activation-1.1.0.v201105071233.jar:lib/jetty-start-8.1.14.v20131031.jar:lib/jetty-plus-8.1.14.v20131031.jar:lib/javax.transaction-1.1.1.v201105210645.jar:lib/jetty-webapp-8.1.14.v20131031.jar:lib/jetty-servlet-8.1.14.v20131031.jar:lib/jetty-security-8.1.14.v20131031.jar:lib/jetty-deploy-8.1.14.v20131031.jar:lib/jetty-xml-8.1.14.v20131031.jar:lib/jetty-util-8.1.14.v20131031.jar:lib/derby-10.10.1.1.jar:lib/mail-1.4.jar:lib/activation-1.1.jar:lib/ant-1.8.3.jar:lib/ant-launcher-1.8.3.jar:lib/tomcat-jdbc-7.0.54.jar:lib/tomcat-juli-7.0.54.jar -Dwrapper.key=AbDfHMhccuq6BnzA -Dwrapper.port=32000 -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 -Dwrapper.pid=1903 -Dwrapper.version=3.2.3 -Dwrapper.native_library=wrapper -Dwrapper.service=TRUE -Dwrapper.cpu.timeout=10 -Dwrapper.jvmid=1 org.tanukisoftware.wrapper.WrapperSimpleApp org.eclipse.jetty.start.Main ./conf/jetty.xml
jenkins   6718  1.0  1.8 5312132 597928 ?      Sl   01:33   2:05 /var/lib/jenkins/tools/hudson.model.JDK/oracle-jdk8-auto/bin/java -Dfile.encoding=UTF-8 -Dsun.jnu.encoding=UTF-8 -Djdbc.drivers=com.mysql.jdbc.Driver -Dderby.system.home=/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng -Dtigase.cache=off -server -Xms100M -Xmx1000M -Dlogback.configurationFile=/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/etc/logback.xml -cp /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/activation.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/apns.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/commons-codec.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/commons-httpclient.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/commons-logging.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/derby.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/derbytools.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/groovy-all.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/hamcrest-core.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jackson-annotations.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jackson-core.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jackson-databind.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/javax.mail.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/javax.servlet-api.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jaxmpp-core.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jaxmpp-j2se.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jdmkrt.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jetty-http.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jetty-io.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jetty-security.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jetty-server.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jetty-servlet.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jetty-util.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jstun.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jtds.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/jul-to-slf4j.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/licence-lib.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/logback-classic.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/logback-core.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/mongo-java-driver.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/mysql-connector-java.jar:/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/tmp/tigase-server/jars/org.apache.felix.bundlerepository.jar:/var/l
jenkins   7540  0.5  2.7 11599300 907188 ?     Sl   01:35   1:02 /var/lib/jenkins/tools/hudson.model.JDK/oracle-jdk8-auto/bin/java -XX:MaxPermSize=256m -classpath /usr/share/apache-maven/boot/plexus-classworlds-2.5.2.jar -Dclassworlds.conf=/usr/share/apache-maven/bin/m2.conf -Dmaven.home=/usr/share/apache-maven -Dmaven.multiModuleProjectDirectory=/var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng org.codehaus.plexus.classworlds.launcher.Launcher clean test -Dserver.cluster.nodes=127.0.0.1
jenkins   7655  0.0  0.0   4400   600 ?        S    01:35   0:00 /bin/sh -c cd /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng && /var/lib/jenkins/tools/hudson.model.JDK/oracle-jdk8-auto/jre/bin/java -jar /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/target/surefire/surefirebooter1983078821015371014.jar /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/target/surefire/surefire6425503787567840813tmp /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/target/surefire/surefire_0963527592252041125tmp
jenkins   7657  0.1  0.7 12219176 257984 ?     Sl   01:35   0:20 /var/lib/jenkins/tools/hudson.model.JDK/oracle-jdk8-auto/jre/bin/java -jar /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/target/surefire/surefirebooter1983078821015371014.jar /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/target/surefire/surefire6425503787567840813tmp /var/lib/jenkins/jobs/private-TTS-NG-tests-runner/workspace/tigase-tts-ng/target/surefire/surefire_0963527592252041125tmp
eric     12664  0.1  0.2 11193904 95364 ?      Sl   03:01   0:12 /usr/lib/jvm/jdk1.8.0_20/bin/java -classpath /home/jenkins/groovy-2.4.11/lib/groovy-2.4.11.jar -Dscript.name=/usr/bin/groovy -Dprogram.name=groovy -Dgroovy.starter.conf=/home/jenkins/groovy-2.4.11/conf/groovy-starter.conf -Dgroovy.home=/home/jenkins/groovy-2.4.11 -Dtools.jar=/usr/lib/jvm/jdk1.8.0_20/lib/tools.jar org.codehaus.groovy.tools.GroovyStarter --main groovy.ui.GroovyMain --conf /home/jenkins/groovy-2.4.11/conf/groovy-starter.conf --classpath . StatsDumper.groovy c01.xmpp-test.net admin admin_pass_c01 c01.stats
eric     12676  0.1  0.3 11193904 102016 ?     Sl   03:01   0:13 /usr/lib/jvm/jdk1.8.0_20/bin/java -classpath /home/jenkins/groovy-2.4.11/lib/groovy-2.4.11.jar -Dscript.name=/usr/bin/groovy -Dprogram.name=groovy -Dgroovy.starter.conf=/home/jenkins/groovy-2.4.11/conf/groovy-starter.conf -Dgroovy.home=/home/jenkins/groovy-2.4.11 -Dtools.jar=/usr/lib/jvm/jdk1.8.0_20/lib/tools.jar org.codehaus.groovy.tools.GroovyStarter --main groovy.ui.GroovyMain --conf /home/jenkins/groovy-2.4.11/conf/groovy-starter.conf --classpath . StatsDumper.groovy c02.xmpp-test.net admin admin_pass_c02 c02.stats
eric     12697  0.1  0.3 11193904 99632 ?      Sl   03:01   0:12 /usr/lib/jvm/jdk1.8.0_20/bin/java -classpath /home/jenkins/groovy-2.4.11/lib/groovy-2.4.11.jar -Dscript.name=/usr/bin/groovy -Dprogram.name=groovy -Dgroovy.starter.conf=/home/jenkins/groovy-2.4.11/conf/groovy-starter.conf -Dgroovy.home=/home/jenkins/groovy-2.4.11 -Dtools.jar=/usr/lib/jvm/jdk1.8.0_20/lib/tools.jar org.codehaus.groovy.tools.GroovyStarter --main groovy.ui.GroovyMain --conf /home/jenkins/groovy-2.4.11/conf/groovy-starter.conf --classpath . StatsDumper.groovy c03.xmpp-test.net admin admin_pass_c03 c03.stats
eric     12720  0.1  0.3 11193904 105248 ?     Sl   03:01   0:13 /usr/lib/jvm/jdk1.8.0_20/bin/java -classpath /home/jenkins/groovy-2.4.11/lib/groovy-2.4.11.jar -Dscript.name=/usr/bin/groovy -Dprogram.name=groovy -Dgroovy.starter.conf=/home/jenkins/groovy-2.4.11/conf/groovy-starter.conf -Dgroovy.home=/home/jenkins/groovy-2.4.11 -Dtools.jar=/usr/lib/jvm/jdk1.8.0_20/lib/tools.jar org.codehaus.groovy.tools.GroovyStarter --main groovy.ui.GroovyMain --conf /home/jenkins/groovy-2.4.11/conf/groovy-starter.conf --classpath . StatsDumper.groovy c04.xmpp-test.net admin admin_pass_c04 c04.stats
jenkins  16787  0.0  0.0  20012   348 ?        S    Apr19   0:02 /usr/bin/daemon --name=jenkins --inherit --env=JENKINS_HOME=/var/lib/jenkins --output=/var/log/jenkins/jenkins.log --pidfile=/var/run/jenkins/jenkins.pid -- /usr/bin/java -XX:+OptimizeStringConcat -XX:+DoEscapeAnalysis -XX:+UseNUMA -Djava.util.logging.loglevel=FINEST -Dhudson.plugins.git.GitSCM.verbose=true -server -Xms512M -Xmx768M -XX:PermSize=32m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Dmail.smtp.starttls.enable=true -Dorg.apache.commons.jelly.tags.fmt.timeZone=Europe/Warsaw -jar /usr/share/jenkins/jenkins.war --webroot=/var/cache/jenkins/war --httpPort=8080 --ajp13Port=-1 --prefix=/jenkins
jenkins  16789  1.8  4.6 4968552 1536404 ?     Sl   May26 281:07 /usr/bin/java -XX:+OptimizeStringConcat -XX:+DoEscapeAnalysis -XX:+UseNUMA -Djava.util.logging.loglevel=FINEST -Dhudson.plugins.git.GitSCM.verbose=true -server -Xms512M -Xmx768M -XX:PermSize=32m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Dmail.smtp.starttls.enable=true -Dorg.apache.commons.jelly.tags.fmt.timeZone=Europe/Warsaw -jar /usr/share/jenkins/jenkins.war --webroot=/var/cache/jenkins/war --httpPort=8080 --ajp13Port=-1 --prefix=/jenkins
jenkins  23794  0.0  0.0   9388   884 pts/0    S+   04:55   0:00 grep --color=auto java
jenkins@build:~$ kill -3 1963
jenkins@build:~$ kill -3 6718
jenkins@build:~$ kill -3 7540
jenkins@build:~$ kill -3 7655
jenkins@build:~$ kill -3 12664
-su: kill: (12664) - Operation not permitted
jenkins@build:~$ kill -3 12676
-su: kill: (12676) - Operation not permitted
jenkins@build:~$

#4 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

  • Assignee changed from Andrzej Wójcik to Wojciech Kapcia

I've looked over this thread dump and there is no lock or mention of our class. Maybe we have thread dump of a wrong process? I'm asking as mvn test runs a tests but may be configured to execute tests as separate processes and in this case it would explain why we can see:

"process reaper" #75 daemon prio=10 os_prio=0 tid=0x00007f2e389e1800 nid=0x1dd2 runnable [0x00007f2e1bffe000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.UNIXProcess.waitForProcessExit(Native Method)
    at java.lang.UNIXProcess.lambda$initStreams$275(UNIXProcess.java:290)
    at java.lang.UNIXProcess$$Lambda$8/1956746660.run(Unknown Source)
    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:745)

I cannot tell or fix this issue as I cannot find a root cause of it.

#5 Updated by Wojciech Kapcia TigaseTeam over 1 year ago

  • Assignee changed from Wojciech Kapcia to Andrzej Wójcik

Andrzej Wójcik wrote:

I've looked over this thread dump and there is no lock or mention of our class. Maybe we have thread dump of a wrong process? I'm asking as mvn test runs a tests but may be configured to execute tests as separate processes and in this case it would explain why we can see:

[...]

I cannot tell or fix this issue as I cannot find a root cause of it.

Well, by default maven forks test execution to separate process (default options: forkCount=1, reuseForks=true), but still I think the output of both should be included in jenkins log, and I forced thread-dump on all available processes (most important being 7540, 7655 and 7657).

By the way - you said that you enabled parall test execution a while back? How and where?

#6 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

I was working on a parallel execution of a tests as I was changing account creation mechanisms, etc. but finally (as I checked) it was not enabled.

It can be enabled with parallel attribute on a <suite/> element (in XML) with a proper value. I do not remember why it was not enabled.

#7 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

  • Status changed from Feedback to In QA

#8 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

There is not enough data to find a cause of this issue. We need to wait for a next occurrence.

#9 Updated by Wojciech Kapcia TigaseTeam over 1 year ago

I've disabled "Abort the build if it's stuck" so it won't kill stuck job.

#10 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

I've found a possible cause by getting a thread dump and a heap dump out of hanged TTS-NG. It was possible that login(true) method of Jaxmpp was throwing an exception but in finally block it was waiting for a connection, which resulted in infinite wait time.

This is not fixed and I'm waiting for a next run of TTS-NG.

#11 Updated by Andrzej Wójcik IoT 1 CloudTigaseTeam over 1 year ago

  • Assignee changed from Andrzej Wójcik to Wojciech Kapcia
  • % Done changed from 80 to 100

It looks like this change fixed issues with TTS-NG hanging during some tests.

#12 Updated by Wojciech Kapcia TigaseTeam over 1 year ago

  • Status changed from In QA to Closed

It seems fixed.

Also available in: Atom PDF