Cache Misses In CentralAnalyzer When Gradle Daemon Is Reused

[mroeppis]

Bug Description

When CentralAnalyzer is enabled caching is meant to work by default. However, repeated executions of ODC result in cache misses. This makes a noticeable difference for projects with many dependencies because each dependency adds about 1 second of runtime.

This issue focuses on caching for the CentalAnalyzer but affects every analyzer using the DataCacheFactory, i.e. implementations of AbstractNpmAnalyzer are concerned as well.

Tests were conducted using version 7.3.2 of the ODC plugin and Gradle 7.1.

Analysis

Cause Description

The DataCacheFactory uses JCS for the underlying caching mechanism. The CompositeCacheManager requested inside JCS#getInstance( ...) is a singleton. After creating its instance it is configured to use an IndexedDiskCache (also called auxiliary cache) which is divided into regions POM, CENTRAL and NODEAUDIT. Since ODC enables caches from the CacheExtension by default these sub-caches create files in the data directory (as set via DataExtension) which are populated while dependency check is running. When ODC finishes it calls JCS#shutdown() that cleans up memory. As a consequence cache values get disposed and aux caches are removed from the map of all caches (CompositeCacheManager#caches). However, CompositeCacheManager#auxiliaryCaches is left untouched which means that the aux caches that were just disposed are still referenced inside the cache manager which is not invalidated as well.

Because Gradle uses the daemon by default since version 3 this has implications for using static state in plugins. If the same daemon is used again for repeated executions of ODC the JCS cache manager (still alive) is also reused. While trying to configure it again the aux cache map containing the regions mentioned above can be retrieved without having to recreate its entries in an AuxiliaryCacheFactory. As a result the aux caches in memory are not connected to their respective files anymore which effectively leads to empty caches being offered by JCS. Therefore, further invocations of CentralAnalyzer will start dowloading POMs again that users have cached on disk.

Repro

See mwe.zip attached for reference.

1. Delete <USER_HOME>\.gradle\dependency-check-data\7.0\cache

2. Switch to myproject

3. gradlew :dependencyCheckAggregate --info

    Instance is null, returning unconfigured instance
   
    thread_pool.default PoolConfiguration = useBoundary = [false] boundarySize = [2000] maximumPoolSize = [150] minimumPoolSize = [4] keepAliveTime = [300000] whenBlockedPolicy = [RUN] startUpSize = [4]
    Setting default auxiliaries to ODC
    setting defaultCompositeCacheAttributes to [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
    setting defaultElementAttributes to [ IS_LATERAL = false, IS_SPOOL = true, IS_REMOTE = false, IS_ETERNAL = false, MaxLifeSeconds = 86400, IdleTime = 1800, CreateTime = 1669485286945, LastAccessTime = 1669485286945, getTimeToLiveSeconds() = 86399, createTime = 1669485286945 ]
    
    [...]
   
    initialized MemoryCache for POM
    Constructed cache with name [POM] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
    No cache event logger defined for auxiliary [jcs.auxiliary.ODC]
    Using standard serializer [org.apache.commons.jcs.utils.serialization.StandardSerializer@60a7c42f] for auxiliary [jcs.auxiliary.ODC]
    Region [POM] Cache file root directory: <USER_HOME>\.gradle\dependency-check-data\7.0\cache
    Region [POM] Set maxKeySize to: '1000000'
    Region [POM] Indexed Disk Cache is alive.
   
    [...]
   
    Parsed regions [CENTRAL, POM, NODEAUDIT]
    Finished configuration in 36 ms.
   

   • notice the creation of a brand new cache manager in the 1st line and the cache "alive" status
   • data directory is created with empty .key and .data files
   • CentralAnalyzer downloads POMs whose model information is saved to the .data files (...this takes some time which is OK for initially building the cache)

    Finished Central Analyzer (98 seconds)
   

   • finally, when ODC ends the .key files get filled:

    Element event queue destroyed: org.apache.commons.jcs.engine.control.event.ElementEventQueue@3d1f6bf0
   
    [...]
    
    No longer waiting for event queue to finish: Pooled Cache Event Queue
    Working = true
    Alive = false
    Empty = true
    Queue Size = 0
    Queue Capacity = 2147483647
    Pool Size = 0
    Maximum Pool Size = 150
    Region [POM] Saving keys to: POM, key count: 105
    Region [POM] Finished saving keys.
    Region [POM] Shutdown complete.
    
    [...]
    
    In DISPOSE, [POM] fromRemote [false]
    In DISPOSE, [POM] auxiliary [POM]
    In DISPOSE, [POM] put 0 into auxiliary POM
    In dispose, destroying event queue.
    In DISPOSE, [POM] disposing of memory cache.
    Memory Cache dispose called.
   

4. Repeat step 3 to validate caching

    thread_pool.default PoolConfiguration = useBoundary = [false] boundarySize = [2000] maximumPoolSize = [150] minimumPoolSize = [4] keepAliveTime = [300000] whenBlockedPolicy = [RUN] startUpSize = [4]
    
    Setting default auxiliaries to ODC
    setting defaultCompositeCacheAttributes to [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
    setting defaultElementAttributes to [ IS_LATERAL = false, IS_SPOOL = true, IS_REMOTE = false, IS_ETERNAL = false, MaxLifeSeconds = 86400, IdleTime = 1800, CreateTime = 1669520238206, LastAccessTime = 1669520238206, getTimeToLiveSeconds() = 86399, createTime = 1669520238206 ]
    
    [...]
   
    initialized MemoryCache for POM
    Constructed cache with name [POM] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
    
    [...]
    
    Parsed regions [CENTRAL, POM, NODEAUDIT]
    Finished configuration in 1 ms.
   

   • IndexedDiskCache isn't mentioned
   • aux cache regions are no longer alive (CacheStatus#DISPOSED) as communicated at DEBUG:

    [...]
   
    [org.apache.commons.jcs.engine.control.CompositeCache] get: key = https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom, localOnly = false
    [org.apache.commons.jcs.engine.memory.AbstractDoubleLinkedListMemoryCache] POM: getting item for key https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.apache.commons.jcs.engine.memory.AbstractDoubleLinkedListMemoryCache] POM: LRUMemoryCache miss for https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    
    [...]
   
    [org.apache.commons.jcs.engine.control.CompositeCache] Attempting to get from aux [POM] which is of type: DISK_CACHE
    [org.apache.commons.jcs.auxiliary.disk.AbstractDiskCache] get was called, but the disk cache is not alive.
    [org.apache.commons.jcs.engine.control.CompositeCache] Got CacheElement: null
    [org.apache.commons.jcs.engine.control.CompositeCache] POM - Miss
    [org.owasp.dependencycheck.analyzer.CentralAnalyzer] Downloading https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
   
    [...]
   

   • CentralAnalyzer takes as much time as before (around 100 seconds)

5. gradlew :dependencyCheckAggregate --info --no-daemon

   • run this outside an IDE that uses the Gradle Tooling API property

    Instance is null, returning unconfigured instance
    
    thread_pool.default PoolConfiguration = useBoundary = [false] boundarySize = [2000] maximumPoolSize = [150] minimumPoolSize = [4] keepAliveTime = [300000] whenBlockedPolicy = [RUN] startUpSize = [4]
    Setting default auxiliaries to ODC
    setting defaultCompositeCacheAttributes to [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
    setting defaultElementAttributes to [ IS_LATERAL = false, IS_SPOOL = true, IS_REMOTE = false, IS_ETERNAL = false, MaxLifeSeconds = 86400, IdleTime = 1800, CreateTime = 1669519678636, LastAccessTime = 1669519678636, getTimeToLiveSeconds() = 86399, createTime = 1669519678636 ]
    
    [...]
    
    initialized MemoryCache for POM
    Constructed cache with name [POM] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 0, maxSpoolPerRun = -1, diskUsagePattern = UPDATE, spoolChunkSize = 2 ]
    No cache event logger defined for auxiliary [jcs.auxiliary.ODC]
    Using standard serializer [org.apache.commons.jcs.utils.serialization.StandardSerializer@7b49312a] for auxiliary [jcs.auxiliary.ODC]
    Region [POM] Cache file root directory: <USER_HOME>\.gradle\dependency-check-data\7.0\cache
    Region [POM] Set maxKeySize to: '1000000'
    Region [POM] Loaded keys from [POM], key count: 105; up to 1000000 will be available.
    Region [POM] Finished inital consistency check, isOk = true in 0ms.
    Region [POM] Indexed Disk Cache is alive.
    
    [...]
    
    Parsed regions [CENTRAL, POM, NODEAUDIT]
    Finished configuration in 51 ms.
   

   • CentralAnalyzer now completes instantly due to 100% cache hits:

    [...]
   
    [org.apache.commons.jcs.engine.control.CompositeCache] get: key = https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom, localOnly = false
    [org.apache.commons.jcs.engine.memory.AbstractDoubleLinkedListMemoryCache] POM: getting item for key https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    
    [...]
   
    [org.apache.commons.jcs.engine.control.CompositeCache] Attempting to get from aux [POM] which is of type: DISK_CACHE
    [org.apache.commons.jcs.utils.struct.AbstractLRUMap] getting item  for key https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.apache.commons.jcs.utils.struct.AbstractLRUMap] LRUMap miss for https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.apache.commons.jcs.auxiliary.disk.indexed.IndexedDiskCache] Region [POM] Trying to get from disk: https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.apache.commons.jcs.utils.struct.AbstractLRUMap] getting item  for key https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.apache.commons.jcs.utils.struct.AbstractLRUMap] LRUMap hit for https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.apache.commons.jcs.auxiliary.disk.indexed.IndexedDiskCache] Region [POM] Found on disk, key: https://search.maven.org/remotecontent?filepath=org/projectlombok/lombok/1.18.10/lombok-1.18.10.pom
    [org.owasp.dependencycheck.xml.pom.Model@54e0245], attr [[ IS_LATERAL = false, IS_SPOOL = true, IS_REMOTE = false, IS_ETERNAL = true, MaxLifeSeconds = 7776000, IdleTime = -1, CreateTime = 1669576503525, LastAccessTime = 1669576503525, getTimeToLiveSeconds() = 7756128, createTime = 1669576503525 ]]
    [org.apache.commons.jcs.engine.control.CompositeCache] POM - Aux cache[POM] hit
   
    [...]
   
    Finished Central Analyzer (0 seconds)
   

Suggested Fix

Ugrade to JCS3 Core. This solves JCS issue 199 that was discovered in version 2.2.1 which is currently used by ODC.

Points to consider when moving from 2.x to 3.x are outlined on this help page. They raised the baseline to Java 8. The current ODC parent defines the same baseline.

In the MWE attached you may try out the Gradle plugin running with JCS core 3.1.

1. Delete cache data directory
2. Switch to myproject
3. Uncomment lines in build.gradle and settings.gradle
4. Comment line with plugin version 7.3.2 in build.gradle
5. Package JAR for ODC core project
6. gradlew :dependencyCheckAggregate --info
7. repeat step 6
   • same behavior as in point 5 from repro above but this time without having to deactivate the daemon