Gradle Test Executor X finished with non-zero exit value 143


(James) #1

We are using Gradle to build and run tests in Jenkins for CI. In many builds we see build failures with the following text:

Execution failed for task ':myTests'.\n > Process 'Gradle Test Executor 79' finished with non-zero exit value 143\n This problem might be caused by incorrect test process configuration.\n Please refer to the test execution section in the user guide at https://docs.gradle.org/4.6/userguide/java_plugin.html#sec:test_execution\n \n * Try:\n Run with --stacktrace option to get the stack trace. Run with --info or --debug option to get more log output. Run with --scan to get full insights.\n \n * Get more help at https://help.gradle.org\n \n Deprecated Gradle features were used in this build, making it incompatible with Gradle 5.0.\n See https://docs.gradle.org/4.6/userguide/command_line_interface.html#sec:command_line_warnings\n \n BUILD FAILED in 15m 35s\n 4 actionable tasks: 4 executed\n }\n Xvfb stopping\n // wrap\n }\n // dir\n echo\n hudson.AbortException: script returned exit code 1

We are using Gradle 4.6 and this usually happens when we are executing tests with a command similar to

./gradlew myTests --no-daemon -Dgeb.env=mygebenv

A couple other notes:

This does not happen in every build, but it happens very often. Maybe 1/4 of our builds.

If I run with the --debug flag the build log grows so large that it wont load in my browser (~300 MB). I tried turning on --debug for just one group of tests but the log was still very large and it seemed as if it turned on debugging for everything anyway (I could be wrong). Also, the group of tests that fails with this error is always different, so only having --debug on for one group of tests isn’t likely to catch the error.

The tests groups are running in parallel across Jenkins nodes. Each test group, however is NOT run with --parallel.

According to what I’ve seen elsewhere online - exit value 143 usually means some other process is trying to terminate your process. I was unable to find something that confirmed that is what Gradle means by that exit value.

So, anyone know why this is happening? Let me know if there is more information I can provide. Thanks!


(Bo Zhang) #2

Hi James, Exit code 143 corresponds to SIGTERM , which is the signal sent by default when you run kill <pid> . Is it possible that another process or user is killing the application? Perhaps the heap memory is too low and the process is killed by OS.


(James) #3

I increased the memory to 2Gb from whatever the default is through the gradle-wrapper.properties jvmargs, but I still see the issue. Any other ideas to troubleshoot?


(Bo Zhang) #4

I’m afraid you need to put that configuration in gradle.properties, not gradle-wrapper.properties. See https://docs.gradle.org/current/userguide/build_environment.html


(James) #5

Ok. What is the purpose of gradle-wrapper.properties? Anytime we run gradle we use gradlew. We don’t have any gradle.properties files but I can add them.

Alternatively, can I specify from the command line? Is this the right syntax?

./gradlew myTestTask -Xmx2g


(Bo Zhang) #6

gradle-wrapper.properties specifies the properties needed when downloading distributions.

Alternatively, can I specify from the command line? Is this the right syntax?

./gradlew myTestTask -Dorg.gradle.jvmargs=-Xmx2g

But usually we write it in gradle.properties.


(James) #7

I appreciate your time.


(James) #8

I made this change and could verify that Gradle was started with Xmx2g and thats great. The issue hasn’t come back yet (but it is intermittent, so we’ll see), however, this change seems to have created a new problem. After changing to Xmx2g I am seeing builds hang and run forever.

The new gradle calls look like this:

./gradlew myTests --no-daemon -Dorg.gradle.jvmargs=-Xmx2g

Any idea why this is happening? My thoughts are that the daemon isn’t ending at the end of the tests or that the tests aren’t reporting when they’re done. Why would increasing max memory cause this?


(Bo Zhang) #9

When you see a hanging JVM process (no matter with or without Gradle), you should run jstack on it to see where it hangs. Try to find out the test process (Test Executor X) and run jstack on it.


(James) #10

Ok, back to this problem. We finally were able to get the --debug and --stacktrace logs and can see exactly where Gradle fails. Could someone help us decipher this? It appears there is trouble communicating to with some socket. Any idea why? Again this is an intermittent issue, but happens many times per day.

02:22:07.586 [DEBUG] [org.gradle.process.internal.worker.DefaultWorkerProcessBuilder] Creating Gradle Test Executor 75
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.586 [DEBUG] [org.gradle.process.internal.worker.DefaultWorkerProcessBuilder] Using application classpath [/home/ubuntu/workspace/Build_Debug_Gradle-IGDWOPJQDWCT3VHVNF6RJSCKRDAEFIW5RCHX6OP4Q6I36EPVNDXA/bind-fta/build/classes/java/test, /home/ubuntu/workspace/Build_Debug_Gradle-IGDWOPJQDWCT3VHVNF6RJSCKRDAEFIW5RCHX6OP4Q6I36EPVN
...
<more log entries describing the classpath>
...
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.586 [DEBUG] [org.gradle.process.internal.worker.DefaultWorkerProcessBuilder] Using implementation classpath [file:/home/ubuntu/.gradle/wrapper/dists/gradle-4.6-all/bcst21l2brirad8k2ben1letg/gradle-4.6/lib/gradle-core-api-4.6.jar, file:/home/ubuntu/.gradle/wrapper/dists/gradle-4.6-all/bcst21l2brirad8k2ben1letg/gradle-4.6/lib/gradle-core-
...
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.586 [DEBUG] [org.gradle.process.internal.worker.child.WorkerProcessClassPathProvider] Using worker process classpath: [/home/ubuntu/.gradle/caches/4.6/workerMain/gradle-worker.jar]
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.587 [INFO] [org.gradle.process.internal.DefaultExecHandle] Starting process 'Gradle Test Executor 75'. Working directory: /home/ubuntu/workspace/Build_Debug_Gradle-IGDWOPJQDWCT3VHVNF6RJSCKRDAEFIW5RCHX6OP4Q6I36EPVNDXA/<redacted> Command: /home/ubuntu/tools/hudson.model.JDK/JDK_8u121/bin/java -Dawt.toolkit=sun.awt.X11.XToolkit -Dfile.
Oct 19 02:22:07 ip-10-10-11-236 myTests: d64:/usr/lib64:/lib64:/lib:/usr/lib -Djava.runtime.name=Java(TM) SE Runtime Environment -Djava.runtime.version=1.8.0_121-b13 -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager -Djava.specification.name=Java Platform API Specification -Djava.specification.vendor=Oracle Corporation -Djava.specification
Oct 19 02:22:07 ip-10-10-11-236 myTests: -Dorg.gradle.appname=gradlew -Dorg.gradle.native=false -Dos.arch=amd64 -Dos.name=Linux -Dos.version=4.4.0-1063-aws -Dpath.separator=: -Dspock.configuration=ServiceAPISpockConfig.groovy -Dsun.arch.data.model=64 -Dsun.boot.class.path=/home/ubuntu/tools/hudson.model.JDK/JDK_8u121/jre/lib/resources.jar:/home/ubuntu/tools/hudson.model.JDK/JDK_8u121/
Oct 19 02:22:07 ip-10-10-11-236 myTests: d --no-daemon -Dgeb.env=dev -Dsun.java.launcher=SUN_STANDARD -Dsun.jnu.encoding=UTF-8 -Dsun.management.compiler=HotSpot 64-Bit Tiered Compilers -Dsun.os.patch.level=unknown -Duser.dir=/home/ubuntu/workspace/Build_Debug_Gradle-IGDWOPJQDWCT3VHVNF6RJSCKRDAEFIW5RCHX6OP4Q6I36EPVNDXA/bind-fta -Duser.home=/home/ubuntu -Duser.name=ubuntu -Duse
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.587 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Environment for process 'Gradle Test Executor 75': {PATH=/home/ubuntu/tools/hudson.model.JDK/JDK_8u121/bin:/home/ubuntu/tools/jenkins.plugins.nodejs.tools.NodeJSInstallation/NodeJS_8.9.0/bin:/home/ubuntu/tools/hudson.model.JDK/JDK_8u121/bin:/home/ubuntu/tools/jenkins.plugins.no
...
Oct 19 02:22:07 ip-10-10-11-236 myTests: , HUDSON_HOME=/jenkins, RUN_CHANGES_DISPLAY_URL=https://jenkins.dev-bind.com/job/Build/job/FTA-Debug_Gradlew5/16/display/redirect?page=changes, JOB_URL=https://jenkins.dev-bind.com/job/Build/job/FTA-Debug_Gradlew5/, NODE_HOME_TOOL=NodeJS 8.9.0, HUDSON_COOKIE=1fe59ddd-6146-4aca-a43a-57aa2c205e14, XFILESEARCHPATH=/usr/dt/app-defaults/%L/Dt, BUILD_
...
Oct 19 02:22:07 ip-10-10-11-236 myTests: ava, GIT_COMMIT=7bc6bba, SHELL=/bin/bash, BUILD_TAG=topic-7bc6bba, STAGE_NAME=Service API Tests, resource=dev, JAVA_HOME_TOOL=JDK 8u151, EXECUTOR_NUMBER=0, HUDSON_SERVER_COOKIE=705f6e335b0fa828, SSH_CLIENT=10.10.11.46 50302 22, OLDPWD=/home/ubuntu/workspace/Build_Debug_Gradle-IGDWOPJQDWCT3VHVNF6RJSCKRDAEFIW5RCHX6OP4Q6I36EPVNDXA/bind-ft
...
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.587 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Changing state to: STARTING
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.587 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Waiting until process started: Gradle Test Executor 75.
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.588 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Changing state to: STARTED
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.588 [INFO] [org.gradle.process.internal.DefaultExecHandle] Successfully started process 'Gradle Test Executor 75'
Oct 19 02:22:07 ip-10-10-11-236 myTests: 02:22:07.588 [DEBUG] [org.gradle.process.internal.ExecHandleRunner] waiting until streams are handled...
Oct 19 02:22:08 ip-10-10-11-236 myTests: 02:22:08.073 [DEBUG] [org.gradle.internal.remote.internal.inet.TcpIncomingConnector] Accepted connection from /0:0:0:0:0:0:0:1:40434 to /0:0:0:0:0:0:0:1:45673.
Oct 19 02:22:08 ip-10-10-11-236 myTests: 02:22:08.073 [DEBUG] [org.gradle.process.internal.worker.DefaultWorkerProcess] Received connection org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection@7f1d3a23 from Gradle Test Executor 75
Oct 19 02:22:08 ip-10-10-11-236 myTests: 02:22:08.155 [DEBUG] [org.gradle.internal.remote.internal.inet.SocketConnection] Discarding EOFException: java.io.EOFException
Oct 19 02:22:08 ip-10-10-11-236 myTests: 02:22:08.156 [ERROR] [org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection] Unexpected exception thrown.
Oct 19 02:22:08 ip-10-10-11-236 myTests: org.gradle.internal.remote.internal.MessageIOException: Could not write '/0:0:0:0:0:0:0:1:40434'.
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.remote.internal.inet.SocketConnection.flush(SocketConnection.java:134)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.remote.internal.hub.MessageHub$ConnectionDispatch.run(MessageHub.java:325)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at java.lang.Thread.run(Thread.java:745)
Oct 19 02:22:08 ip-10-10-11-236 myTests: Caused by: java.io.IOException: Broken pipe
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at sun.nio.ch.IOUtil.write(IOUtil.java:51)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.remote.internal.inet.SocketConnection$SocketOutputStream.writeWithNonBlockingRetry(SocketConnection.java:272)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.remote.internal.inet.SocketConnection$SocketOutputStream.writeBufferToChannel(SocketConnection.java:260)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.remote.internal.inet.SocketConnection$SocketOutputStream.flush(SocketConnection.java:254)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011at org.gradle.internal.remote.internal.inet.SocketConnection.flush(SocketConnection.java:132)
Oct 19 02:22:08 ip-10-10-11-236 myTests: #011... 7 more
Oct 19 02:22:08 ip-10-10-11-236 myTests: 02:22:08.157 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Changing state to: FAILED
Oct 19 02:22:08 ip-10-10-11-236 myTests: 02:22:08.157 [DEBUG] [org.gradle.process.internal.DefaultExecHandle] Process 'Gradle Test Executor 75' finished with exit value 143 (state: FAILED)

(Gary Hale) #11

The network connection errors are likely a symptom and not the cause. Basically, these are from the build daemon detecting that the network connection with the test worker closed abruptly (i.e. not during normal test worker shutdown). The return code (143) is coming from the test worker jvm (Gradle is not setting this return code explicitly). This is a good explanation of how to interpret the value. Basically, 143 indicates it exited because of an external signal: 15 (SIGTERM). By all appearances, it looks like something is sending it a kill signal.