Skip to content
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.

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

Sporadic IllegalStateException while initializing build #2239

Closed
eriwen opened this issue Jun 2, 2017 · 15 comments
Closed

Sporadic IllegalStateException while initializing build #2239

eriwen opened this issue Jun 2, 2017 · 15 comments

Comments

@eriwen
Copy link
Contributor

eriwen commented Jun 2, 2017

Expected Behavior

Build initialization should complete successfully when configured properly

Current Behavior

Some projects encounter this frequently:

This operation (org.gradle.internal.progress.BuildProgressLogger - Initializing build) has already been completed.

Context

Discussion at https://discuss.gradle.org/t/gradle-4-unexpected-initialization-error/22851

Stacktrace
java.lang.IllegalStateException: This operation (org.gradle.internal.progress.BuildProgressLogger - 
Initializing build) has already been completed.
    at org.gradle.internal.logging.progress.DefaultProgressLoggerFactory$ProgressLoggerImpl.assertRunning(DefaultProgressLoggerFactory.java:183)
    at org.gradle.internal.logging.progress.DefaultProgressLoggerFactory$ProgressLoggerImpl.completed(DefaultProgressLoggerFactory.java:159)
    at org.gradle.internal.progress.BuildProgressLogger.beforeComplete(BuildProgressLogger.java:87)
    at org.gradle.internal.progress.BuildProgressFilter.beforeComplete(BuildProgressFilter.java:107)

Steps to Reproduce (for bugs)

Seems to occur sometimes when invoking gradle --stop as well.

Your Environment

  • Build scan URL:
@eriwen eriwen added this to the 4.0 RC2 milestone Jun 2, 2017
@eriwen eriwen self-assigned this Jun 2, 2017
@eriwen eriwen changed the title Sporadic IllegalStateException while initializing build Sporadic IllegalStateException when using GradleBuild tasks Jun 2, 2017
@eriwen eriwen changed the title Sporadic IllegalStateException when using GradleBuild tasks Sporadic IllegalStateException while initializing build Jun 2, 2017
@eriwen eriwen removed this from the 4.0 RC2 milestone Jun 5, 2017
@gastonlagaf
Copy link

Step for reproduction:

  • Override buildDir property in gradle.properties file or in command line and run the build

@ThiporKong
Copy link

Using the steps given by @gastonlagaf I can reproduce this problem as well

@jjohannes jjohannes self-assigned this Jun 19, 2017
@jjohannes
Copy link
Contributor

jjohannes commented Jun 20, 2017

There are two issues here:

  1. A certain state change, from which Gradle determines the current process logger, is not done in a finally { } block. If an error occurs during settings evaluation, the state change does not happen and Gradle attempts to close the wrong progress logger (which was already closed before). That also explains while stopping the daemon can cause this issue, because daemon stop will also throw an exception, which, with bad timing, would also omit the state change.
  2. The actual error, which is a 4.0 regression that was hidden is an java.lang.IllegalArgumentException: argument type mismatch which is caused by this change:
    Add missing type safe buildDir setter on Project
    It is attempting to set the buildDir using buildDir(File) rather than buildDir(Object). From that we get a type mismatch (String vs File)

Fix for (1): #2331

@eskatos can you check what we could do about (2)? Is reverting (at least for a 4.0.1 release) an option?
It is not always reproducible. I think it has something to do with the daemon state. Maybe a class loading thing.

@jjohannes
Copy link
Contributor

jjohannes commented Jun 20, 2017

Looks like we have an issue with supporting two setters for the same property with different types (see #1866). We need to fix this:

public static PropertyMutator writeablePropertyIfExists(Class<?> target, String property) throws NoSuchPropertyException {
String setterName = toMethodName("set", property);
for (final Method method : target.getMethods()) {
if (!method.getName().equals(setterName) || PropertyAccessorType.of(method) != PropertyAccessorType.SETTER) {
continue;
}
return new MethodBackedPropertyMutator(property, method);
}
return null;
}

At the moment depends on the order in which methods are iterated if we grep the right one. That explains why it is difficult to reproduce.

Here is a test that fails sometimes, but not always:

def "can always change buildDir in properties file"() {
    when:
    file('gradle.properties') << """
        buildDir=otherBuild
    """
    then:
    succeeds ':help'
}

@jjohannes
Copy link
Contributor

jjohannes commented Jun 20, 2017

A possible fix: #2332
Not sure about performance implications. Running it through CI: https://builds.gradle.org/viewQueued.html?itemId=3379138

@jjohannes
Copy link
Contributor

First issue fixed and merged.

Follow up for second issue: #2385

@dbyron0
Copy link

dbyron0 commented Jul 18, 2017

I'm running into this, or something similar to this with gradle 4.0.1. It's an IllegalStateException in a gradle execution involving a GradleBuild task in a plugin. It happens during spock tests that invoke gradle with a GradleRunner, when gradle itself and the GradleRunner both use a daemon, as well as when neither do (by invoking gradlew with --no-daemon, and using withDebug(true) in the spock test).

A couple of notes:

  • the spock output doesn't include the stack trace. The last line of output is the last log message. Only the 'regular' report output has the stack trace. I'm using com.athaydes:spock-reports:1.3.1.
  • the tasks element BuildResult return value has a null element in its tasks. Put another way, with code like this:
def result = runner
     .withArguments('release', '--debug', '--stacktrace')
     .buildAndFail()

result.task(':release') is null, where I'd expect it to be a BuildTask object where the outcome is FAILED, and the output contains the output.

Here's a stack trace using a daemon:

10:09:11.091 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] 1 actionable task: 1 executed
10:09:11.091 [DEBUG] [org.gradle.internal.work.DefaultWorkerLeaseService] Worker lease root.1 completed (0 worker(s) in use)
10:09:11.091 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Daemon worker: released lock on root.1
10:09:11.091 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Run build'
10:09:11.091 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation 'Run build' completed
10:09:11.091 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for task history cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit1845398001582771360/.gradle/4.0.1/taskHistory)
10:09:11.091 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on task history cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit1845398001582771360/.gradle/4.0.1/taskHistory).
10:09:11.092 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.CachedStoreFactory] Resolution result cache closed. Cache reads: 0, disk reads: 0 (avg: 0.0 secs, total: 0.0 secs)
10:09:11.092 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.CachedStoreFactory] Resolution result cache closed. Cache reads: 0, disk reads: 0 (avg: 0.0 secs, total: 0.0 secs)
10:09:11.092 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.ResolutionResultsStoreFactory] Deleted 2 resolution results binary files in 0.0 secs
10:09:11.092 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache Plugin Resolution Cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/4.0.1/plugin-resolution) was closed 0 times.
10:09:11.092 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for Artifact transforms cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/transforms-1)
10:09:11.092 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on Artifact transforms cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/transforms-1).
10:09:11.092 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for file hash cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit1845398001582771360/.gradle/4.0.1/fileHashes)
10:09:11.092 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache fileHashes.bin (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit1845398001582771360/.gradle/4.0.1/fileHashes/fileHashes.bin)
10:09:11.092 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on file hash cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit1845398001582771360/.gradle/4.0.1/fileHashes).
10:09:11.092 [DEBUG] [org.gradle.deployment.internal.DefaultDeploymentRegistry] Stopping 0 deployment handles
10:09:11.092 [DEBUG] [org.gradle.deployment.internal.DefaultDeploymentRegistry] Stopped deployment handles
10:09:11.092 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache Generated Gradle JARs cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/4.0.1/generated-gradle-jars) was closed 0 times.
10:09:11.093 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache artifact cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/modules-2) was closed 0 times.
10:09:11.093 [DEBUG] [org.gradle.launcher.daemon.server.exec.ExecuteBuild] The daemon has finished executing the build. (last line of spock output)

	at org.gradle.testkit.runner.internal.ToolingApiGradleExecutor.run(ToolingApiGradleExecutor.java:150)
	at org.gradle.testkit.runner.internal.DefaultGradleRunner.run(DefaultGradleRunner.java:270)
	at org.gradle.testkit.runner.internal.DefaultGradleRunner.build(DefaultGradleRunner.java:219)
	at com.locationlabs.plugins.leanjava.TestReleaseTask.configureReleasePublication takes effect during release/buildAndPublishTasks(TestReleaseTask.groovy:607)
Caused by: org.gradle.tooling.ListenerFailedException: Could not execute build using Gradle installation '/Users/david.byron/.gradle/wrapper/dists/gradle-4.0.1-bin/82ajq2mkcvzmyzskx3tahg8op/gradle-4.0.1'.
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:53)
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:29)
	at org.gradle.tooling.internal.consumer.ResultHandlerAdapter.onFailure(ResultHandlerAdapter.java:41)
	at org.gradle.tooling.internal.consumer.async.DefaultAsyncConsumerActionExecutor$1$1.run(DefaultAsyncConsumerActionExecutor.java:57)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:745)
	at org.gradle.tooling.internal.consumer.BlockingResultHandler.getResult(BlockingResultHandler.java:46)
	at org.gradle.tooling.internal.consumer.DefaultBuildLauncher.run(DefaultBuildLauncher.java:77)
	at org.gradle.testkit.runner.internal.ToolingApiGradleExecutor.run(ToolingApiGradleExecutor.java:126)
	... 3 more
Caused by: java.lang.IllegalStateException: Operation org.gradle.tooling.internal.provider.events.DefaultTaskDescriptor@1844af99 already available.
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.addDescriptor(BuildProgressListenerAdapter.java:188)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.taskStartedEvent(BuildProgressListenerAdapter.java:161)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.toTaskProgressEvent(BuildProgressListenerAdapter.java:137)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.broadcastTaskProgressEvent(BuildProgressListenerAdapter.java:112)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.doBroadcast(BuildProgressListenerAdapter.java:85)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.onEvent(BuildProgressListenerAdapter.java:72)
	at org.gradle.tooling.internal.consumer.parameters.FailsafeBuildProgressListenerAdapter.onEvent(FailsafeBuildProgressListenerAdapter.java:39)
	at org.gradle.tooling.internal.consumer.parameters.FailsafeBuildProgressListenerAdapter.onEvent(FailsafeBuildProgressListenerAdapter.java:39)
	at org.gradle.tooling.internal.provider.ProviderConnection$BuildProgressListenerInvokingBuildEventConsumer.dispatch(ProviderConnection.java:238)
	at org.gradle.launcher.daemon.client.DaemonClient.monitorBuild(DaemonClient.java:218)
	at org.gradle.launcher.daemon.client.DaemonClient.executeBuild(DaemonClient.java:178)
	at org.gradle.launcher.daemon.client.DaemonClient.execute(DaemonClient.java:141)
	at org.gradle.launcher.daemon.client.DaemonClient.execute(DaemonClient.java:92)
	at org.gradle.tooling.internal.provider.DaemonBuildActionExecuter.execute(DaemonBuildActionExecuter.java:60)
	at org.gradle.tooling.internal.provider.DaemonBuildActionExecuter.execute(DaemonBuildActionExecuter.java:41)
	at org.gradle.tooling.internal.provider.LoggingBridgingBuildActionExecuter.execute(LoggingBridgingBuildActionExecuter.java:60)
	at org.gradle.tooling.internal.provider.LoggingBridgingBuildActionExecuter.execute(LoggingBridgingBuildActionExecuter.java:34)
	at org.gradle.tooling.internal.provider.ProviderConnection.run(ProviderConnection.java:143)
	at org.gradle.tooling.internal.provider.ProviderConnection.run(ProviderConnection.java:118)
	at org.gradle.tooling.internal.provider.DefaultConnection.getModel(DefaultConnection.java:188)
	at org.gradle.tooling.internal.consumer.connection.CancellableModelBuilderBackedModelProducer.produceModel(CancellableModelBuilderBackedModelProducer.java:53)
	at org.gradle.tooling.internal.consumer.connection.PluginClasspathInjectionSupportedCheckModelProducer.produceModel(PluginClasspathInjectionSupportedCheckModelProducer.java:41)
	at org.gradle.tooling.internal.consumer.connection.AbstractConsumerConnection.run(AbstractConsumerConnection.java:58)
	at org.gradle.tooling.internal.consumer.connection.ParameterValidatingConsumerConnection.run(ParameterValidatingConsumerConnection.java:46)
	at org.gradle.tooling.internal.consumer.DefaultBuildLauncher$1.run(DefaultBuildLauncher.java:89)
	at org.gradle.tooling.internal.consumer.DefaultBuildLauncher$1.run(DefaultBuildLauncher.java:83)
	at org.gradle.tooling.internal.consumer.connection.LazyConsumerActionExecutor.run(LazyConsumerActionExecutor.java:84)
	at org.gradle.tooling.internal.consumer.connection.CancellableConsumerActionExecutor.run(CancellableConsumerActionExecutor.java:45)
	at org.gradle.tooling.internal.consumer.connection.ProgressLoggingConsumerActionExecutor.run(ProgressLoggingConsumerActionExecutor.java:58)
	at org.gradle.tooling.internal.consumer.connection.RethrowingErrorsConsumerActionExecutor.run(RethrowingErrorsConsumerActionExecutor.java:38)
	at org.gradle.tooling.internal.consumer.async.DefaultAsyncConsumerActionExecutor$1$1.run(DefaultAsyncConsumerActionExecutor.java:55)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:745)```

Here's a stack trace with no daemon:

10:27:00.562 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] BUILD SUCCESSFUL in 2s
10:27:00.563 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] 1 actionable task: 1 executed
10:27:00.565 [DEBUG] [org.gradle.internal.work.DefaultWorkerLeaseService] Worker lease root.1 completed (0 worker(s) in use)
10:27:00.565 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Connection worker: released lock on root.1
10:27:00.566 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Run build'
10:27:00.566 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation 'Run build' completed
10:27:00.567 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for task history cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit9015513384899776326/.gradle/4.0.1/taskHistory)
10:27:00.567 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on task history cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit9015513384899776326/.gradle/4.0.1/taskHistory).
10:27:00.567 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.CachedStoreFactory] Resolution result cache closed. Cache reads: 0, disk reads: 0 (avg: 0.0 secs, total: 0.0 secs)
10:27:00.568 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.CachedStoreFactory] Resolution result cache closed. Cache reads: 0, disk reads: 0 (avg: 0.0 secs, total: 0.0 secs)
10:27:00.568 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.ResolutionResultsStoreFactory] Deleted 2 resolution results binary files in 0.001 secs
10:27:00.568 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache Plugin Resolution Cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/4.0.1/plugin-resolution) was closed 0 times.
10:27:00.568 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for Artifact transforms cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/transforms-1)
10:27:00.568 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on Artifact transforms cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/transforms-1).
10:27:00.568 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for file hash cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit9015513384899776326/.gradle/4.0.1/fileHashes)
10:27:00.569 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache fileHashes.bin (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit9015513384899776326/.gradle/4.0.1/fileHashes/fileHashes.bin)
10:27:00.569 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on file hash cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit9015513384899776326/.gradle/4.0.1/fileHashes).
10:27:00.569 [DEBUG] [org.gradle.deployment.internal.DefaultDeploymentRegistry] Stopping 0 deployment handles
10:27:00.569 [DEBUG] [org.gradle.deployment.internal.DefaultDeploymentRegistry] Stopped deployment handles
10:27:00.569 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache Generated Gradle JARs cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/4.0.1/generated-gradle-jars) was closed 0 times.
10:27:00.569 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache artifact cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/modules-2) was closed 0 times.

	at org.gradle.testkit.runner.internal.ToolingApiGradleExecutor.run(ToolingApiGradleExecutor.java:150)
	at org.gradle.testkit.runner.internal.DefaultGradleRunner.run(DefaultGradleRunner.java:270)
	at org.gradle.testkit.runner.internal.DefaultGradleRunner.build(DefaultGradleRunner.java:219)
	at com.locationlabs.plugins.leanjava.TestReleaseTask.configureReleasePublication takes effect during release/buildAndPublishTasks(TestReleaseTask.groovy:607)
Caused by: org.gradle.tooling.ListenerFailedException: Could not execute build using Gradle installation '/Users/david.byron/.gradle/wrapper/dists/gradle-4.0.1-bin/82ajq2mkcvzmyzskx3tahg8op/gradle-4.0.1'.
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:53)
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:29)
	at org.gradle.tooling.internal.consumer.ResultHandlerAdapter.onFailure(ResultHandlerAdapter.java:41)
	at org.gradle.tooling.internal.consumer.async.DefaultAsyncConsumerActionExecutor$1$1.run(DefaultAsyncConsumerActionExecutor.java:57)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:745)
	at org.gradle.tooling.internal.consumer.BlockingResultHandler.getResult(BlockingResultHandler.java:46)
	at org.gradle.tooling.internal.consumer.DefaultBuildLauncher.run(DefaultBuildLauncher.java:77)
	at org.gradle.testkit.runner.internal.ToolingApiGradleExecutor.run(ToolingApiGradleExecutor.java:126)
	... 3 more
Caused by: java.lang.IllegalStateException: Operation org.gradle.tooling.internal.provider.events.DefaultTaskDescriptor@73ce22df already available.
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.addDescriptor(BuildProgressListenerAdapter.java:188)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.taskStartedEvent(BuildProgressListenerAdapter.java:161)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.toTaskProgressEvent(BuildProgressListenerAdapter.java:137)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.broadcastTaskProgressEvent(BuildProgressListenerAdapter.java:112)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.doBroadcast(BuildProgressListenerAdapter.java:85)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.onEvent(BuildProgressListenerAdapter.java:72)
	at org.gradle.tooling.internal.consumer.parameters.FailsafeBuildProgressListenerAdapter.onEvent(FailsafeBuildProgressListenerAdapter.java:39)
	at org.gradle.tooling.internal.consumer.parameters.FailsafeBuildProgressListenerAdapter.onEvent(FailsafeBuildProgressListenerAdapter.java:39)
	at org.gradle.tooling.internal.provider.ProviderConnection$BuildProgressListenerInvokingBuildEventConsumer.dispatch(ProviderConnection.java:238)
	at org.gradle.tooling.internal.provider.ProviderConnection$ProgressListenerConfiguration$SynchronizedConsumer.dispatch(ProviderConnection.java:280)
	at org.gradle.tooling.internal.provider.runner.ClientForwardingTaskOperationListener.started(ClientForwardingTaskOperationListener.java:69)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.event.DefaultListenerManager$ListenerDetails.dispatch(DefaultListenerManager.java:371)
	at org.gradle.internal.event.DefaultListenerManager$ListenerDetails.dispatch(DefaultListenerManager.java:353)
	at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:58)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:341)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:328)
	at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:58)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:341)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:328)
	at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:58)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:341)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast.dispatch(DefaultListenerManager.java:152)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast.dispatch(DefaultListenerManager.java:126)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
	at org.gradle.internal.progress.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:176)
	at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:95)
	at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:235)
	at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:224)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.processTask(DefaultTaskPlanExecutor.java:121)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.access$200(DefaultTaskPlanExecutor.java:77)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:102)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:96)
	at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.execute(DefaultTaskExecutionPlan.java:612)
	at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.executeWithTask(DefaultTaskExecutionPlan.java:567)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.run(DefaultTaskPlanExecutor.java:96)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:745)

Thanks for your help.

@jjohannes
Copy link
Contributor

@dbyron0 thanks for reporting this. Unfortunately I am not sure how to reproduce this.

Can you share a complete reproducible example that includes the build script(s)?

@dbyron0
Copy link

dbyron0 commented Jul 19, 2017

@jjohannes Is there a good way to share it not quite so publicly? Email perhaps?

@eriwen
Copy link
Contributor Author

eriwen commented Jul 19, 2017

@dbyron0 we have used shared Google Drive or Dropbox links in the past for this. You're welcome to also email me eric at gradle dot com if you'd prefer.

@dbyron0
Copy link

dbyron0 commented Jul 20, 2017

Great. I'm getting something together. Thanks.

@eriwen eriwen reopened this Jul 25, 2017
@eriwen eriwen modified the milestones: 4.1 RC2, 4.0.1 Jul 25, 2017
@jjohannes
Copy link
Contributor

@dbyron0 I was able to reproduce and debug the issue now. Thanks for your input. It looks like some TaskFinishEvents do not arrive at the ToolingApiGradleExecutor.TaskExecutionProgressListener of testkit here if the build is failing.

We probably introduced this in 4.0 with some progress logging changes we did. So there might be some connection to the original issue in this ticket. But it is not the same.

Good news is that the issue was already fixed with 45d311d, which is in 4.1 RC1.

Can you confirm that your project works as expected with 4.1 RC1?

@jjohannes
Copy link
Contributor

@dbyron0 Looking at the stacktrace you posted again... I actually did not reproduce that exactly. If 4.1 RC1 still fails for you, can you confirm that you get the same issue or send a new trace. Thanks.

@jjohannes jjohannes removed this from the 4.1 RC2 milestone Jul 28, 2017
@dbyron0
Copy link

dbyron0 commented Jul 28, 2017

Yup, still fails with ./gradlew wrapper --gradle-version=4.1-rc-1:

08:00:08.986 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] BUILD SUCCESSFUL in 2s
08:00:08.986 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] 1 actionable task: 1 executed
08:00:08.988 [DEBUG] [org.gradle.internal.work.DefaultWorkerLeaseService] Worker lease root.1 completed (0 worker(s) in use)
08:00:08.988 [DEBUG] [org.gradle.internal.resources.AbstractTrackedResourceLock] Connection worker: released lock on root.1
08:00:08.988 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Run build'
08:00:08.988 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation 'Run build' completed
08:00:08.989 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for task history cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit2964152462893584254/.gradle/4.1-rc-1/taskHistory)
08:00:08.989 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on task history cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit2964152462893584254/.gradle/4.1-rc-1/taskHistory).
08:00:08.989 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.CachedStoreFactory] Resolution result cache closed. Cache reads: 0, disk reads: 0 (avg: 0.0 secs, total: 0.0 secs)
08:00:08.990 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.CachedStoreFactory] Resolution result cache closed. Cache reads: 0, disk reads: 0 (avg: 0.0 secs, total: 0.0 secs)
08:00:08.990 [DEBUG] [org.gradle.api.internal.artifacts.ivyservice.resolveengine.store.ResolutionResultsStoreFactory] Deleted 2 resolution results binary files in 0.001 secs
08:00:08.990 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache Plugin Resolution Cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/4.1-rc-1/plugin-resolution) was closed 0 times.
08:00:08.990 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for Artifact transforms cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/transforms-1)
08:00:08.990 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on Artifact transforms cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/transforms-1).
08:00:08.990 [DEBUG] [org.gradle.cache.internal.LockOnDemandCrossProcessCacheAccess] Releasing file lock for file hash cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit2964152462893584254/.gradle/4.1-rc-1/fileHashes)
08:00:08.991 [DEBUG] [org.gradle.cache.internal.btree.BTreePersistentIndexedCache] Closing cache fileHashes.bin (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit2964152462893584254/.gradle/4.1-rc-1/fileHashes/fileHashes.bin)
08:00:08.991 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on file hash cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/junit2964152462893584254/.gradle/4.1-rc-1/fileHashes).
08:00:08.991 [DEBUG] [org.gradle.deployment.internal.DefaultDeploymentRegistry] Stopping 0 deployment handles
08:00:08.991 [DEBUG] [org.gradle.deployment.internal.DefaultDeploymentRegistry] Stopped deployment handles
08:00:08.991 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache Generated Gradle JARs cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/4.1-rc-1/generated-gradle-jars) was closed 0 times.
08:00:08.991 [DEBUG] [org.gradle.cache.internal.DefaultCacheAccess] Cache artifact cache (/private/var/folders/dn/0rbsn8cs25l0yzczh63yyw4r0000gp/T/.gradle-test-kit-david.byron/caches/modules-2) was closed 0 times.

	at org.gradle.testkit.runner.internal.ToolingApiGradleExecutor.run(ToolingApiGradleExecutor.java:150)
	at org.gradle.testkit.runner.internal.DefaultGradleRunner.run(DefaultGradleRunner.java:270)
	at org.gradle.testkit.runner.internal.DefaultGradleRunner.build(DefaultGradleRunner.java:219)
	at com.locationlabs.plugins.leanjava.TestReleaseTask.configureReleasePublication takes effect during release/buildAndPublishTasks(TestReleaseTask.groovy:606)
Caused by: org.gradle.tooling.ListenerFailedException: Could not execute build using Gradle installation '/Users/david.byron/.gradle/wrapper/dists/gradle-4.1-rc-1-bin/awi5zdhcqdj0a42lqf3xx6mnp/gradle-4.1-rc-1'.
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:53)
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:29)
	at org.gradle.tooling.internal.consumer.ResultHandlerAdapter.onFailure(ResultHandlerAdapter.java:41)
	at org.gradle.tooling.internal.consumer.async.DefaultAsyncConsumerActionExecutor$1$1.run(DefaultAsyncConsumerActionExecutor.java:57)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:745)
	at org.gradle.tooling.internal.consumer.BlockingResultHandler.getResult(BlockingResultHandler.java:46)
	at org.gradle.tooling.internal.consumer.DefaultBuildLauncher.run(DefaultBuildLauncher.java:77)
	at org.gradle.testkit.runner.internal.ToolingApiGradleExecutor.run(ToolingApiGradleExecutor.java:126)
	... 3 more
Caused by: java.lang.IllegalStateException: Operation org.gradle.tooling.internal.provider.events.DefaultTaskDescriptor@3631a3f already available.
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.addDescriptor(BuildProgressListenerAdapter.java:188)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.taskStartedEvent(BuildProgressListenerAdapter.java:161)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.toTaskProgressEvent(BuildProgressListenerAdapter.java:137)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.broadcastTaskProgressEvent(BuildProgressListenerAdapter.java:112)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.doBroadcast(BuildProgressListenerAdapter.java:85)
	at org.gradle.tooling.internal.consumer.parameters.BuildProgressListenerAdapter.onEvent(BuildProgressListenerAdapter.java:72)
	at org.gradle.tooling.internal.consumer.parameters.FailsafeBuildProgressListenerAdapter.onEvent(FailsafeBuildProgressListenerAdapter.java:39)
	at org.gradle.tooling.internal.consumer.parameters.FailsafeBuildProgressListenerAdapter.onEvent(FailsafeBuildProgressListenerAdapter.java:39)
	at org.gradle.tooling.internal.provider.ProviderConnection$BuildProgressListenerInvokingBuildEventConsumer.dispatch(ProviderConnection.java:238)
	at org.gradle.tooling.internal.provider.ProviderConnection$ProgressListenerConfiguration$SynchronizedConsumer.dispatch(ProviderConnection.java:280)
	at org.gradle.tooling.internal.provider.runner.ClientForwardingTaskOperationListener.started(ClientForwardingTaskOperationListener.java:69)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.event.DefaultListenerManager$ListenerDetails.dispatch(DefaultListenerManager.java:371)
	at org.gradle.internal.event.DefaultListenerManager$ListenerDetails.dispatch(DefaultListenerManager.java:353)
	at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:58)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:341)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:328)
	at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:58)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:341)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:328)
	at org.gradle.internal.event.AbstractBroadcastDispatch.dispatch(AbstractBroadcastDispatch.java:58)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast$ListenerDispatch.dispatch(DefaultListenerManager.java:341)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast.dispatch(DefaultListenerManager.java:152)
	at org.gradle.internal.event.DefaultListenerManager$EventBroadcast.dispatch(DefaultListenerManager.java:126)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
	at org.gradle.internal.progress.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:188)
	at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:107)
	at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:241)
	at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker.execute(DefaultTaskGraphExecuter.java:230)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.processTask(DefaultTaskPlanExecutor.java:124)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.access$200(DefaultTaskPlanExecutor.java:80)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:105)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:99)
	at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.execute(DefaultTaskExecutionPlan.java:625)
	at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.executeWithTask(DefaultTaskExecutionPlan.java:580)
	at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.run(DefaultTaskPlanExecutor.java:99)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:745)

@jjohannes
Copy link
Contributor

I found the problem. Thank you very much for your help @dbyron0. Follow up issue: #2622

@eriwen eriwen added this to the 4.1 RC1 milestone Aug 1, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants