We have a remote build cache set up (the web UI is working properly) but it is always empty, even after adjusting the gradle.properties and settings.gradle as described in the instructions. Note that we are not using Gradle Enterprise.
Am I doing something wrong? Aren’t things from the Java plugin supposed to be pushed to the build cache?
I run this gradle command:
./gradlew -Pgradle.cache.push=true --rerun-tasks compileJava -d --no-daemon &> gradle_use_cache.out
Selected data from Gradle process log:
11:16:45.141 [INFO] [org.gradle.internal.nativeintegration.services.NativeServices] Initialized native services in: /home_bunch/gmregression/gradle_cache_remote_gen/native
11:16:45.829 [INFO] [org.gradle.internal.work.DefaultWorkerLeaseService] Using 48 worker leases.
11:16:45.884 [INFO] [org.gradle.cache.internal.DefaultCacheAccess] Creating new cache for fileHashes, path /home_bunch/gmregression/gradle_cache_remote_gen/caches/4.3.1/fileHashes/fileHashes.bin, access org.gradle.cache.internal.DefaultCacheAccess@7fc6de5b
11:16:45.893 [DEBUG] [org.gradle.api.internal.changedetection.state.InMemoryCacheDecoratorFactory] Creating in-memory store for cache /home_bunch/gmregression/gradle_cache_remote_gen/caches/4.3.1/fileHashes/fileHashes.bin (max size: 14292100)
<<>>
11:16:45.982 [INFO] [org.gradle.cache.internal.DefaultCacheAccess] Creating new cache for resourceHashesCache, path /home_bunch/gmregression/gradle_cache_remote_gen/caches/4.3.1/fileHashes/resourceHashesCache.bin, access org.gradle.cache.internal.DefaultCacheAccess@7fc6de5b
11:16:45.982 [DEBUG] [org.gradle.api.internal.changedetection.state.InMemoryCacheDecoratorFactory] Creating in-memory store for cache /home_bunch/gmregression/gradle_cache_remote_gen/caches/4.3.1/fileHashes/resourceHashesCache.bin (max size: 14292100)
<<>>
11:16:46.043 [INFO] [org.gradle.cache.internal.DefaultCacheAccess] Creating new cache for fileHashes, path /home_bunch/gmregression/pgx_cache_build/.gradle/4.3.1/fileHashes/fileHashes.bin, access org.gradle.cache.internal.DefaultCacheAccess@4e517165
11:16:46.043 [DEBUG] [org.gradle.api.internal.changedetection.state.InMemoryCacheDecoratorFactory] Creating in-memory store for cache /home_bunch/gmregression/pgx_cache_build/.gradle/4.3.1/fileHashes/fileHashes.bin (max size: 14292100)
<<>>
11:16:46.086 [INFO] [org.gradle.cache.internal.DefaultCacheAccess] Creating new cache for plugin-use-metadata, path /home_bunch/gmregression/gradle_cache_remote_gen/caches/4.3.1/plugin-resolution/plugin-use-metadata.bin, access org.gradle.cache.internal.DefaultCacheAccess@3e2943ab
<<>>
11:16:46.087 [INFO] [org.gradle.cache.internal.DefaultCacheAccess] Creating new cache for client-status, path /home_bunch/gmregression/gradle_cache_remote_gen/caches/4.3.1/plugin-resolution/client-status.bin, access org.gradle.cache.internal.DefaultCacheAccess@3e2943ab
11:16:46.304 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Run build’ started
<<>>
11:16:47.020 [DEBUG] [org.gradle.caching.configuration.internal.DefaultBuildCacheConfiguration] Found class org.gradle.caching.local.internal.DirectoryBuildCacheServiceFactory registered for class org.gradle.caching.local.DirectoryBuildCache
11:16:47.054 [DEBUG] [org.gradle.caching.configuration.internal.DefaultBuildCacheConfiguration] Found class org.gradle.caching.http.internal.DefaultHttpBuildCacheServiceFactory registered for class org.gradle.caching.http.HttpBuildCache
11:16:47.071 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Apply script settings.gradle to settings ‘pgx_cache_build’'
11:16:47.072 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Apply script settings.gradle to settings ‘pgx_cache_build’’ completed
11:16:47.073 [DEBUG] [org.gradle.initialization.ScriptEvaluatingSettingsProcessor] Timing: Processing settings took: 0.75 secs
11:16:47.074 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Evaluate settings’
11:16:47.074 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Evaluate settings’ completed
11:16:47.078 [INFO] [org.gradle.internal.buildevents.BuildLogger] Settings evaluated using settings file ‘/home_bunch/gmregression/pgx_cache_build/settings.gradle’.
11:16:47.078 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Load build’
11:16:47.078 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Load build’ completed
11:16:47.079 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Configure build’ started
11:16:47.080 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Load projects’ started
<<>>
11:16:47.564 [DEBUG] [org.gradle.initialization.ProjectPropertySettingBuildLoader] Looking for project properties from: /home_bunch/gmregression/pgx_cache_build/gradle.properties
11:16:47.565 [DEBUG] [org.gradle.initialization.ProjectPropertySettingBuildLoader] Adding project properties (if not overwritten by user properties): [systemProp.http.proxyPort, org.gradle.daemon, org.gradle.parallel, org.gradle.caching, systemProp.https.proxyHost, org.gradle.configureondemand, systemProp.http.nonProxyHosts, systemProp.http.proxyHost, systemProp.https.proxyPort, systemProp.https.nonProxyHosts]
<<<Output Abbreviated; much later…>>>
11:17:10.280 [WARN] [org.gradle.util.DeprecationLogger] Build cache is an incubating feature.
11:17:10.282 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Finalize build cache configuration’ started
11:17:10.283 [DEBUG] [org.gradle.caching.configuration.internal.DefaultBuildCacheConfiguration] Found class org.gradle.caching.http.internal.DefaultHttpBuildCacheServiceFactory registered for class org.gradle.caching.http.HttpBuildCache
11:17:10.288 [INFO] [org.gradle.caching.internal.controller.BuildCacheControllerFactory] Using remote HTTP build cache for the root build (allowUntrustedServer = false, authenticated = true, url = http://-build-cache.us..com/).
11:17:10.293 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Completing Build operation 'Finalize build cache configuration’
11:17:10.293 [DEBUG] [org.gradle.internal.progress.DefaultBuildOperationExecutor] Build operation ‘Finalize build cache configuration’ completed
11:17:10.300 [DEBUG] [org.gradle.execution.taskgraph.DefaultTaskPlanExecutor] Using 48 parallel executor threads
<<>>
11:18:23.901 [LIFECYCLE] [org.gradle.internal.buildevents.BuildResultLogger] 11 actionable tasks: 11 executed
11:18:23.902 [DEBUG] [org.gradle.caching.internal.controller.service.OpFiringBuildCacheServiceHandle] Closing remote build cache
11:18:23.902 [DEBUG] [org.gradle.caching.internal.controller.service.OpFiringBuildCacheServiceHandle] Closing remote build cache
11:18:23.902 [DEBUG] [org.gradle.internal.work.DefaultWorkerLeaseService] Worker lease root.1 completed (0 worker(s) in use)
<<>>
The logs for the cache server just contain a bunch of entries like this:
2018-01-04 19:13:51,687 INFO r.request {executionId=gwov5k5fwv7u7i5yhfkdi2efa4, requestId=8b3eb790-0d52-14d4-e2ce-cb982e89a787} 127.0.0.1 - - [04/Jan/2018:19:13:51 +0000] “GET /status HTTP/1.1” 200 - id=8b3eb790-0d52-14d4-e2ce-cb982e89a787
2018-01-04 19:13:54,683 INFO r.request {executionId=bk3c6vagdz5bwhjfacmcbgeate, requestId=edb2b640-9f0e-f72a-5611-8b4d1428d156} 127.0.0.1 - - [04/Jan/2018:19:13:54 +0000] “GET /snapshot HTTP/1.1” 200 - id=edb2b640-9f0e-f72a-5611-8b4d1428d156
2018-01-04 19:13:54,686 INFO r.request {executionId=tmm4z2xjurmcgzoe5r32syxl5q, requestId=4abb5de8-70cb-4158-1e81-b50080e01ecb} 127.0.0.1 - - [04/Jan/2018:19:13:54 +0000] “GET /status HTTP/1.1” 200 - id=4abb5de8-70cb-4158-1e81-b50080e01ecb
2018-01-04 19:13:57,680 INFO r.request {executionId=rf75ggefwlnki5q7dtdxqhuela, requestId=7402c834-a360-aa55-212f-b1d6f5dc4c34} 127.0.0.1 - - [04/Jan/2018:19:13:57 +0000] “GET /snapshot HTTP/1.1” 200 - id=7402c834-a360-aa55-212f-b1d6f5dc4c34
2018-01-04 19:13:57,681 INFO r.request {executionId=i2og2w66pj5rdv44kslxoawqaq, requestId=76febdd8-6208-805e-e3a0-de707b69f433} 127.0.0.1 - - [04/Jan/2018:19:13:57 +0000] “GET /status HTTP/1.1” 200 - id=76febdd8-6208-805e-e3a0-de707b69f433
2018-01-04 19:14:00,663 INFO r.request {executionId=lakjten2h7ff646pyc6ndtrmee, requestId=0a63684b-452d-0ef1-47f8-c6f91580502b} 127.0.0.1 - - [04/Jan/2018:19:14:00 +0000] “GET /snapshot HTTP/1.1” 200 - id=0a63684b-452d-0ef1-47f8-c6f91580502b
2018-01-04 19:14:00,664 INFO r.request {executionId=tq6qhtxwdpcoilbbcp4ypddfqq, requestId=feccdc0f-956b-47c6-959a-6abc829ccefa} 127.0.0.1 - - [04/Jan/2018:19:14:00 +0000] “GET /status HTTP/1.1” 200 - id=feccdc0f-956b-47c6-959a-6abc829ccefa
2018-01-04 19:14:03,678 INFO r.request {executionId=afio6exvbhozoxhw73rjbxfib4, requestId=c878de76-3c4c-a4fc-cdcd-0004d2c7035b} 127.0.0.1 - - [04/Jan/2018:19:14:03 +0000] “GET /snapshot HTTP/1.1” 200 - id=c878de76-3c4c-a4fc-cdcd-0004d2c7035b
2018-01-04 19:14:03,680 INFO r.request {executionId=tzdxw4ttxdn2q3a6vl4s4iki4q, requestId=9436b8d9-8bfd-ad27-48a5-ed234fcdeab1} 127.0.0.1 - - [04/Jan/2018:19:14:03 +0000] “GET /status HTTP/1.1” 200 - id=9436b8d9-8bfd-ad27-48a5-ed234fcdeab1
2018-01-04 19:14:06,670 INFO r.request {executionId=c6kbn4p7ji3rveonh7ju2tla7q, requestId=bccb3aea-1884-ee37-7f29-58823fa79fac} 127.0.0.1 - - [04/Jan/2018:19:14:06 +0000] “GET /snapshot HTTP/1.1” 200 - id=bccb3aea-1884-ee37-7f29-58823fa79fac
2018-01-04 19:14:06,671 INFO r.request {executionId=exnranxxyk2va233wwllr22r34, requestId=faad512b-6210-a642-84b7-de08eb3228f6} 127.0.0.1 - - [04/Jan/2018:19:14:06 +0000] “GET /status HTTP/1.1” 200 - id=faad512b-6210-a642-84b7-de08eb3228f6
2018-01-04 19:14:09,689 INFO r.request {executionId=yy4cescxjsedoqe7q5ohg6qfbm, requestId=d83a8a80-f4d2-963e-8c1b-8650ce9bf5ba} 127.0.0.1 - - [04/Jan/2018:19:14:09 +0000] “GET /snapshot HTTP/1.1” 200 - id=d83a8a80-f4d2-963e-8c1b-8650ce9bf5ba
2018-01-04 19:14:09,693 INFO r.request {executionId=czfcaxlzbxizmuvsft5wp5usai, requestId=e185508a-854f-5153-ab68-ad8f1c5de17a} 127.0.0.1 - - [04/Jan/2018:19:14:09 +0000] “GET /status HTTP/1.1” 200 - id=e185508a-854f-5153-ab68-ad8f1c5de17a
2018-01-04 19:14:12,672 INFO r.request {executionId=yws22uirry43idly7magmhcxza, requestId=0fedcf4b-4c0f-0e43-8836-669310cb7217} 127.0.0.1 - - [04/Jan/2018:19:14:12 +0000] “GET /snapshot HTTP/1.1” 200 - id=0fedcf4b-4c0f-0e43-8836-669310cb7217
2018-01-04 19:14:12,673 INFO r.request {executionId=mwczfhwnniuyypcx2wl7zqdmzy, requestId=31eafddf-aed5-f19b-0174-dfd9c906afc3} 127.0.0.1 - - [04/Jan/2018:19:14:12 +0000] “GET /status HTTP/1.1” 200 - id=31eafddf-aed5-f19b-0174-dfd9c906afc3
2018-01-04 19:14:15,670 INFO r.request {executionId=f3qooskzkcpn4zeufjtjxxarie, requestId=e3b10193-9b85-cd76-d331-13842f8c2e76} 127.0.0.1 - - [04/Jan/2018:19:14:15 +0000] “GET /snapshot HTTP/1.1” 200 - id=e3b10193-9b85-cd76-d331-13842f8c2e76
2018-01-04 19:14:15,673 INFO r.request {executionId=3harz7unzjyiuksjpled3cmgym, requestId=69aa758d-1042-f94b-6cf2-0de6131fdaea} 127.0.0.1 - - [04/Jan/2018:19:14:15 +0000] “GET /status HTTP/1.1” 200 - id=69aa758d-1042-f94b-6cf2-0de6131fdaea
Also, I’ve noticed that the time zone is wrong in the cache server logs (even though the time is correct within the Docker container).