Cannot see log from Spring Cache and Ehcache

Question

I'm using Spring MVC 4.3.9.Release with Ehcache 2.10.3

@Configuration
@EnableCaching
public class CacheConfig {
    @Bean
    public CacheManager getEhCacheManager() {
        EhCacheCacheManager ehCacheCacheManager = new EhCacheCacheManager(getEhCacheFactory().getObject());
        return ehCacheCacheManager;
    }


    @Bean
    public EhCacheManagerFactoryBean getEhCacheFactory() {
        EhCacheManagerFactoryBean factoryBean = new EhCacheManagerFactoryBean();
        factoryBean.setConfigLocation(new ClassPathResource("ehcache.xml"));
        factoryBean.setShared(true);
        return factoryBean;
    }
}

ehcache.xml

<?xml version="1.0" encoding="UTF-8"?>
<ehcache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:noNamespaceSchemaLocation="http://ehcache.org/ehcache.xsd"
         updateCheck="true" monitoring="autodetect" dynamicConfig="true">

    <cache name="books"
           maxEntriesLocalHeap="5000"
           maxEntriesLocalDisk="1000"
           eternal="false"
           diskSpoolBufferSizeMB="20"
           timeToIdleSeconds="120"
           timeToLiveSeconds="180"
           memoryStoreEvictionPolicy="LFU"
           transactionalMode="off">
    </cache>
</ehcache>

log4j2.xml with trace level config for net.sf.ehcache and org.springframework.cache

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="DEBUG">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="debug">
            <AppenderRef ref="Console"/>
        </Root>
        <Logger name="org.springframework.cache" level="trace" additivity="false">
            <appender-ref ref="Console" />
        </Logger>

        <Logger name="net.sf.ehcache" level="trace" additivity="false">
            <appender-ref ref="Console" />
        </Logger>
    </Loggers>
</Configuration>

My problem: I can verify cache is working since the method with @Cachable didn't run twice. I see some logs from net.sf.ehcache and org.springframework.cache when I start the project. But these are all logs generated from the 2 packages. Why couldn't I see detailed logs such as cache hit/miss, cache key, cache value...

Initial log when I start my app.

29-Aug-2017 12:40:19.754 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.cache.ehcache.EhCacheManagerFactoryBean.afterPropertiesSet Initializing EhCache CacheManager
12:40:19.759 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.ConfigurationFactory - Configuring ehcache from InputStream
12:40:19.775 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.BeanHandler - Ignoring ehcache attribute xmlns:xsi
12:40:19.775 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.BeanHandler - Ignoring ehcache attribute xsi:noNamespaceSchemaLocation
12:40:19.797 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.CacheManager - Creating new CacheManager with Configuration Object
12:40:19.799 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.util.PropertyUtil - propertiesString is null.
12:40:19.813 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.ConfigurationHelper - No CacheManagerEventListenerFactory class specified. Skipping...
12:40:19.870 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.Cache - No BootstrapCacheLoaderFactory class specified. Skipping...
12:40:19.870 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.Cache - CacheWriter factory not configured. Skipping...
12:40:19.870 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.ConfigurationHelper - No CacheExceptionHandlerFactory class specified. Skipping...
12:40:19.893 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.store.MemoryStore - Initialized net.sf.ehcache.store.MemoryStore for books
12:40:19.923 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LOCAL_OFFHEAP_SIZE
12:40:19.923 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LOCAL_OFFHEAP_SIZE_BYTES
12:40:19.924 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LOCAL_DISK_SIZE
12:40:19.924 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LOCAL_DISK_SIZE_BYTES
12:40:19.924 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: WRITER_QUEUE_LENGTH
12:40:19.924 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: REMOTE_SIZE
12:40:19.924 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LAST_REJOIN_TIMESTAMP
12:40:19.937 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: OFFHEAP_GET
12:40:19.937 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: OFFHEAP_PUT
12:40:19.938 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: OFFHEAP_REMOVE
12:40:19.938 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: DISK_GET
12:40:19.938 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: DISK_PUT
12:40:19.938 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: DISK_REMOVE
12:40:19.939 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: XA_COMMIT
12:40:19.939 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: XA_ROLLBACK
12:40:19.939 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: XA_RECOVERY
12:40:19.939 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: CLUSTER_EVENT
12:40:19.939 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.statistics.extended.ExtendedStatisticsImpl - Mocking Operation Statistic: NONSTOP
12:40:19.944 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.Cache - Initialised cache: books
12:40:19.945 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.ConfigurationHelper - CacheDecoratorFactory not configured. Skipping for 'books'.
12:40:19.945 [RMI TCP Connection(3)-127.0.0.1] DEBUG net.sf.ehcache.config.ConfigurationHelper - CacheDecoratorFactory not configured for defaultCache. Skipping for 'books'.