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

NullPointerException in DefaultPersistentDirectoryStore when reading/writing from build cache #4216

Closed
adrian-baker opened this issue Jan 31, 2018 · 9 comments

Comments

@adrian-baker
Copy link

adrian-baker commented Jan 31, 2018

We're seeing a number of NullPointerExceptions while populating the build cache.

We're using composite builds, so I can't attach a build scan.

This is using Gradle 4.5, with both org.gradle.parallel and org.gradle.configureondemand set to true.

I don't believe the errors are impacting the results of the build, however they are likely hurting the effectiveness of the cache.

Failed to store cache entry df0ce2b67434b3baa11047ea6dbbe708 for task ':sdk:nz.co.tvnz.frame.commons:test'
java.lang.NullPointerException
        at org.gradle.cache.internal.DefaultPersistentDirectoryStore.withFileLock(DefaultPersistentDirectoryStore.java:163)
        at org.gradle.cache.internal.DefaultCacheFactory$ReferenceTrackingCache.withFileLock(DefaultCacheFactory.java:192)
        at org.gradle.caching.local.internal.DirectoryBuildCacheService.withTempFile(DirectoryBuildCacheService.java:176)
        at org.gradle.caching.internal.controller.DefaultBuildCacheController.store(DefaultBuildCacheController.java:208)
        at org.gradle.caching.internal.controller.RootBuildCacheControllerRef$CloseShieldBuildCacheController.store(RootBuildCacheControllerRef.java:59)
        at org.gradle.api.internal.tasks.execution.SkipCachedTaskExecuter.execute(SkipCachedTaskExecuter.java:111)
        at org.gradle.api.internal.tasks.execution.SkipUpToDateTaskExecuter.execute(SkipUpToDateTaskExecuter.java:59)
        at org.gradle.api.internal.tasks.execution.ResolveTaskOutputCachingStateExecuter.execute(ResolveTaskOutputCachingStateExecuter.java:54)
        at org.gradle.api.internal.tasks.execution.ResolveBuildCacheKeyExecuter.execute(ResolveBuildCacheKeyExecuter.java:63)
        at org.gradle.api.internal.tasks.execution.ValidatingTaskExecuter.execute(ValidatingTaskExecuter.java:59)
        at org.gradle.api.internal.tasks.execution.SkipEmptySourceFilesTaskExecuter.execute(SkipEmptySourceFilesTaskExecuter.java:101)
        at org.gradle.api.internal.tasks.execution.FinalizeInputFilePropertiesTaskExecuter.execute(FinalizeInputFilePropertiesTaskExecuter.java:44)
        at org.gradle.api.internal.tasks.execution.CleanupStaleOutputsExecuter.execute(CleanupStaleOutputsExecuter.java:88)
        at org.gradle.api.internal.tasks.execution.ResolveTaskArtifactStateTaskExecuter.execute(ResolveTaskArtifactStateTaskExecuter.java:62)
        at org.gradle.api.internal.tasks.execution.SkipTaskWithNoActionsExecuter.execute(SkipTaskWithNoActionsExecuter.java:52)
        at org.gradle.api.internal.tasks.execution.SkipOnlyIfTaskExecuter.execute(SkipOnlyIfTaskExecuter.java:54)
        at org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter.execute(ExecuteAtMostOnceTaskExecuter.java:43)
        at org.gradle.api.internal.tasks.execution.CatchExceptionTaskExecuter.execute(CatchExceptionTaskExecuter.java:34)
        at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker$1.run(DefaultTaskGraphExecuter.java:248)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:336)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:328)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:199)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:110)
        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:123)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.access$200(DefaultTaskPlanExecutor.java:79)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:104)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:98)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.execute(DefaultTaskExecutionPlan.java:623)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.executeWithTask(DefaultTaskExecutionPlan.java:578)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.run(DefaultTaskPlanExecutor.java:98)
        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)
@adrian-baker adrian-baker changed the title NullPointerException in DefaultPersistentDirectoryStore when storing NullPointerException in DefaultPersistentDirectoryStore when pushing into build cache Jan 31, 2018
@blindpirate
Copy link
Collaborator

@lptr Maybe you can take a look at this.

@adrian-baker
Copy link
Author

adrian-baker commented Jan 31, 2018

Actually reviewing the exceptions, it looks like the same null pointer can be hit when reading from the cache as well:

Failed to load cache entry for task ':sdk:nz.co.tvnz.brightcove:compileTestJava', falling back to executing task
org.gradle.api.GradleException: Build cache entry 81980a57206bb7a7a0787423dfcacc53 from local build cache is invalid
        at org.gradle.caching.internal.controller.DefaultBuildCacheController.load(DefaultBuildCacheController.java:106)
        at org.gradle.caching.internal.controller.RootBuildCacheControllerRef$CloseShieldBuildCacheController.load(RootBuildCacheControllerRef.java:54)
        at org.gradle.api.internal.tasks.execution.SkipCachedTaskExecuter.execute(SkipCachedTaskExecuter.java:79)
        at org.gradle.api.internal.tasks.execution.SkipUpToDateTaskExecuter.execute(SkipUpToDateTaskExecuter.java:59)
        at org.gradle.api.internal.tasks.execution.ResolveTaskOutputCachingStateExecuter.execute(ResolveTaskOutputCachingStateExecuter.java:54)
        at org.gradle.api.internal.tasks.execution.ResolveBuildCacheKeyExecuter.execute(ResolveBuildCacheKeyExecuter.java:63)
        at org.gradle.api.internal.tasks.execution.ValidatingTaskExecuter.execute(ValidatingTaskExecuter.java:59)
        at org.gradle.api.internal.tasks.execution.SkipEmptySourceFilesTaskExecuter.execute(SkipEmptySourceFilesTaskExecuter.java:101)
        at org.gradle.api.internal.tasks.execution.FinalizeInputFilePropertiesTaskExecuter.execute(FinalizeInputFilePropertiesTaskExecuter.java:44)
        at org.gradle.api.internal.tasks.execution.CleanupStaleOutputsExecuter.execute(CleanupStaleOutputsExecuter.java:88)
        at org.gradle.api.internal.tasks.execution.ResolveTaskArtifactStateTaskExecuter.execute(ResolveTaskArtifactStateTaskExecuter.java:62)
        at org.gradle.api.internal.tasks.execution.SkipTaskWithNoActionsExecuter.execute(SkipTaskWithNoActionsExecuter.java:52)
        at org.gradle.api.internal.tasks.execution.SkipOnlyIfTaskExecuter.execute(SkipOnlyIfTaskExecuter.java:54)
        at org.gradle.api.internal.tasks.execution.ExecuteAtMostOnceTaskExecuter.execute(ExecuteAtMostOnceTaskExecuter.java:43)
        at org.gradle.api.internal.tasks.execution.CatchExceptionTaskExecuter.execute(CatchExceptionTaskExecuter.java:34)
        at org.gradle.execution.taskgraph.DefaultTaskGraphExecuter$EventFiringTaskWorker$1.run(DefaultTaskGraphExecuter.java:248)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:336)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor$RunnableBuildOperationWorker.execute(DefaultBuildOperationExecutor.java:328)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.execute(DefaultBuildOperationExecutor.java:199)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:110)
        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:123)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.access$200(DefaultTaskPlanExecutor.java:79)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:104)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker$1.execute(DefaultTaskPlanExecutor.java:98)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.execute(DefaultTaskExecutionPlan.java:623)
        at org.gradle.execution.taskgraph.DefaultTaskExecutionPlan.executeWithTask(DefaultTaskExecutionPlan.java:578)
        at org.gradle.execution.taskgraph.DefaultTaskPlanExecutor$TaskExecutorWorker.run(DefaultTaskPlanExecutor.java:98)
        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)
Caused by: java.lang.NullPointerException
        at org.gradle.cache.internal.DefaultPersistentDirectoryStore.withFileLock(DefaultPersistentDirectoryStore.java:163)
        at org.gradle.cache.internal.DefaultCacheFactory$ReferenceTrackingCache.withFileLock(DefaultCacheFactory.java:192)
        at org.gradle.caching.local.internal.DirectoryBuildCacheService.loadLocally(DirectoryBuildCacheService.java:96)
        at org.gradle.caching.internal.controller.service.DefaultLocalBuildCacheServiceHandle.load(DefaultLocalBuildCacheServiceHandle.java:49)
        at org.gradle.caching.internal.controller.DefaultBuildCacheController.load(DefaultBuildCacheController.java:104)
        ... 34 more

@adrian-baker adrian-baker reopened this Jan 31, 2018
@adrian-baker adrian-baker changed the title NullPointerException in DefaultPersistentDirectoryStore when pushing into build cache NullPointerException in DefaultPersistentDirectoryStore when reading/writing from build cache Jan 31, 2018
@wolfs
Copy link
Member

wolfs commented Jan 31, 2018

@adrian-baker Thank you for the report!

I have a lot of questions for you:

Do you see those exceptions every time you run a build?
Do they happen with 4.4, too?
Could you provide a reproducible example?
Do these exceptions go away if you disable configure on demand?

@adrian-baker
Copy link
Author

adrian-baker commented Jan 31, 2018

It's reasonably intermittent - the trigger seems to be making a change in one of the projects in an included composite build, which triggers the issue maybe 75% of the time.

  • The issue still occurs if I disable configure-on-demand
  • I can't trigger it with 4.4.1
  • I can't trigger it if I disable parallel

I've possibly found something that might be causing it - for our build server build, we use an init script which explicitly calls https://docs.gradle.org/current/javadoc/org/gradle/StartParameter.html#setTaskNames to specify the build tasks (this is so we keep our build server config as simple as possible - startParam.setTaskNames(["build", "buildServer"]).

Oddly, when we set the tasks this way, I can see some subsequent logging after the "BUILD SUCCESSFUL" message. I've attached two logs showing this, one without the null pointer, one with.

If remove the task setting from the build script and specify the same tasks on the command line, I don't see the extra logging or null pointers.

with-null-pointer.log
without-null-pointer.log

@adrian-baker
Copy link
Author

Ah, actually checking that log it's actually a different error ("Cannot lock Build cache (C:\Users\ABaker.gradle\caches\build-cache-1) as it has already been locked by this process.").

Here's one with an actual null pointer - really-with-null-pointer.log

@wolfs
Copy link
Member

wolfs commented Feb 1, 2018

I managed to reproduce the issue. It is related to us sharing the build cache configuration for composite builds starting with Gradle 4.5.
This is a regression. I'll look into a fix.

@wolfs
Copy link
Member

wolfs commented Feb 1, 2018

You can avoid the problem if you add a task to your root build which depends on the tasks you want to execute in the composites.
This would make sure that the included builds finish before the root build.

@wolfs wolfs added this to the 4.5.1 milestone Feb 1, 2018
wolfs added a commit that referenced this issue Feb 1, 2018
wolfs added a commit that referenced this issue Feb 1, 2018
Sharing the service causes problems when they are shut down - sometimes
the root service is shut down even if one of the included builds is
still running and using it.

#4216
wolfs added a commit that referenced this issue Feb 1, 2018
Sharing the service causes problems when they are shut down - sometimes
the root service is shut down even if one of the included builds is
still running and using it.

#4216
wolfs added a commit that referenced this issue Feb 2, 2018
wolfs added a commit that referenced this issue Feb 2, 2018
We only did this so that we are able to observe the cleanup build
operations. This should be handled differently: cleanup operations from
caches should be seen as build operations automatically.

By removing the `buildFinished` listener #4216 is fixed.
@wolfs
Copy link
Member

wolfs commented Feb 5, 2018

@adrian-baker I fixed this via #4249. We are going to do a 4.5.1 release. Could you try out a release snapshot to see if the issue is fixed for you: 4.5.1-20180202223039+0000.

@wolfs wolfs closed this as completed Feb 5, 2018
@adrian-baker
Copy link
Author

Working well - thank you.

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

4 participants