Ehcache Logging example

Ehcache is using SLF4j logging, to log stuff, put a slf4j implementation in the project classpath, in this example, we use logback.

Tools used :

1. Ehcache 2.9
2. Maven 3
3. logback 1.0.13

1. Project Directory Structure

2. Project Dependencies

	<dependency>
		<groupId>net.sf.ehcache</groupId>
		<artifactId>ehcache</artifactId>
		<version>2.9.0</version>
	</dependency>
	<dependency>
		<groupId>ch.qos.logback</groupId>
		<artifactId>logback-classic</artifactId>
		<version>1.0.13</version>
	</dependency>

3. Logback.xml

Create a logback.xml file and put it into the src/main/resources folder.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	//Log everything to console
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
	  <layout class="ch.qos.logback.classic.PatternLayout">
		<Pattern>
			%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n
		</Pattern>
	  </layout>
	</appender>
	<logger name="com.mkyong.cache" level="debug"
		additivity="false">
		<appender-ref ref="STDOUT" />
	</logger>
	<root level="error">
		<appender-ref ref="STDOUT" />
	</root>
</configuration>

4. Logging

A simple Java Ehcache example.

package com.mkyong.cache;
import net.sf.ehcache.Cache;
import net.sf.ehcache.CacheManager;
import net.sf.ehcache.Element;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class HelloEhCache{
	private final static Logger logger = LoggerFactory.getLogger(HelloEhCache.class);
	public static void main(String[] args) {
		logger.debug("Starting Ehcache...");
		CacheManager cm = CacheManager.getInstance();
		cm.addCache("cache1");
		Cache cache = cm.getCache("cache1");
		cache.put(new Element("1","Jan"));
		cache.put(new Element("2","Feb"));
		cache.put(new Element("3","Mar"));
		logger.debug("cache : {}", cache);
		Element ele = cache.get("2");
		String output = (ele == null ? null : ele.getObjectValue().toString());
		System.out.println(output);
		logger.debug("element : {}", ele);
		cm.shutdown();
		logger.debug("Shutting down Ehcache...");

Output

2015-01-20 07:35:13 [main] DEBUG com.mkyong.cache.HelloEhCache - Starting Ehcache...
2015-01-20 07:35:14 [main] DEBUG com.mkyong.cache.HelloEhCache - cache : [ name = cache1 status = STATUS_ALIVE eternal = false overflowToDisk = true maxEntriesLocalHeap = 10000 maxEntriesLocalDisk = 10000000 memoryStoreEvictionPolicy = LRU timeToLiveSeconds = 120 timeToIdleSeconds = 120 persistence = LOCALTEMPSWAP diskExpiryThreadIntervalSeconds = 120 cacheEventListeners: ; orderedCacheEventListeners:  maxBytesLocalHeap = 0 overflowToOffHeap = false maxBytesLocalOffHeap = 0 maxBytesLocalDisk = 0 pinned = false ]
Feb
2015-01-20 07:35:14 [main] DEBUG com.mkyong.cache.HelloEhCache - element : [ key = 2, value=Feb, version=1, hitCount=1, CreationTime = 1421710514063, LastAccessTime = 1421710514063 ]
2015-01-20 07:35:14 [main] DEBUG com.mkyong.cache.HelloEhCache - Shutting down Ehcache...

Changed to total debug mode :

	<root level="debug">
		<appender-ref ref="STDOUT" />
	</root>

Output

07:34:38,892 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
07:34:38,892 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
07:34:38,892 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/mkyong/workspace2/JavaCache/target/classes/logback.xml]
07:34:38,939 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
07:34:38,939 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
07:34:38,955 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
07:34:39,001 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set an encoder instead.
07:34:39,001 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
07:34:39,001 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
07:34:39,001 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.mkyong.cache] to DEBUG
07:34:39,001 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [com.mkyong.cache] to false
07:34:39,001 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[com.mkyong.cache]
07:34:39,001 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
07:34:39,001 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
07:34:39,001 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
07:34:39,001 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@6ede1f90 - Registering current configuration as safe fallback point
2015-01-20 07:34:39 [main] DEBUG com.mkyong.cache.HelloEhCache - Starting Ehcache...
2015-01-20 07:34:39 [main] WARN  n.s.e.config.ConfigurationFactory - No configuration found. Configuring ehcache from ehcache-failsafe.xml  found in the classpath: jar:file:/G:/maven/repo/net/sf/ehcache/ehcache/2.9.0/ehcache-2.9.0.jar!/ehcache-failsafe.xml
2015-01-20 07:34:39 [main] DEBUG n.s.e.config.ConfigurationFactory - Configuring ehcache from URL: jar:file:/G:/maven/repo/net/sf/ehcache/ehcache/2.9.0/ehcache-2.9.0.jar!/ehcache-failsafe.xml
2015-01-20 07:34:39 [main] DEBUG n.s.e.config.ConfigurationFactory - Configuring ehcache from InputStream
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.config.BeanHandler - Ignoring ehcache attribute xmlns:xsi
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.config.BeanHandler - Ignoring ehcache attribute xsi:noNamespaceSchemaLocation
2015-01-20 07:34:39 [main] DEBUG n.s.e.config.DiskStoreConfiguration - Disk Store Path: C:\Users\mkyong\AppData\Local\Temp\
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.CacheManager - Creating new CacheManager with default config
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.util.PropertyUtil - propertiesString is null.
2015-01-20 07:34:39 [main] DEBUG n.s.e.config.ConfigurationHelper - No CacheManagerEventListenerFactory class specified. Skipping...
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.Cache - No BootstrapCacheLoaderFactory class specified. Skipping...
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.Cache - CacheWriter factory not configured. Skipping...
2015-01-20 07:34:39 [main] DEBUG n.s.e.config.ConfigurationHelper - No CacheExceptionHandlerFactory class specified. Skipping...
2015-01-20 07:34:39 [main] WARN  net.sf.ehcache.DiskStorePathManager - diskStorePath 'C:\Users\mkyong\AppData\Local\Temp' is already used by an existing CacheManager either in the same VM or in a different process.
The diskStore path for this CacheManager will be set to C:\Users\mkyong\AppData\Local\Temp\ehcache_auto_created8095047663436693875diskstore.
To avoid this warning consider using the CacheManager factory methods to create a singleton CacheManager or specifying a separate ehcache configuration (ehcache.xml) for each CacheManager instance.
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.DiskStorePathManager - Using diskstore path C:\Users\mkyong\AppData\Local\Temp\ehcache_auto_created8095047663436693875diskstore
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.DiskStorePathManager - Holding exclusive lock on C:\Users\mkyong\AppData\Local\Temp\ehcache_auto_created8095047663436693875diskstore\.ehcache-diskstore.lock
2015-01-20 07:34:39 [main] DEBUG n.s.e.store.disk.DiskStorageFactory - Failed to delete file cache1.data
2015-01-20 07:34:39 [main] DEBUG n.s.e.store.disk.DiskStorageFactory - Failed to delete file cache1.index
2015-01-20 07:34:39 [main] DEBUG n.s.e.store.disk.DiskStorageFactory - Matching data file missing (or empty) for index file. Deleting index file C:\Users\mkyong\AppData\Local\Temp\ehcache_auto_created8095047663436693875diskstore\cache1.index
2015-01-20 07:34:39 [main] DEBUG n.s.e.store.disk.DiskStorageFactory - Failed to delete file cache1.index
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LOCAL_OFFHEAP_SIZE
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LOCAL_OFFHEAP_SIZE_BYTES
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: WRITER_QUEUE_LENGTH
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: REMOTE_SIZE
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Pass-Through Statistic: LAST_REJOIN_TIMESTAMP
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: OFFHEAP_GET
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: OFFHEAP_PUT
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: OFFHEAP_REMOVE
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: XA_COMMIT
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: XA_ROLLBACK
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: XA_RECOVERY
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: CLUSTER_EVENT
2015-01-20 07:34:39 [main] DEBUG n.s.e.s.e.ExtendedStatisticsImpl - Mocking Operation Statistic: NONSTOP
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.Cache - Initialised cache: cache1
2015-01-20 07:34:39 [main] DEBUG n.s.e.config.ConfigurationHelper - CacheDecoratorFactory not configured for defaultCache. Skipping for 'cache1'.
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
2015-01-20 07:34:39 [main] DEBUG com.mkyong.cache.HelloEhCache - cache : [ name = cache1 status = STATUS_ALIVE eternal = false overflowToDisk = true maxEntriesLocalHeap = 10000 maxEntriesLocalDisk = 10000000 memoryStoreEvictionPolicy = LRU timeToLiveSeconds = 120 timeToIdleSeconds = 120 persistence = LOCALTEMPSWAP diskExpiryThreadIntervalSeconds = 120 cacheEventListeners: ; orderedCacheEventListeners:  maxBytesLocalHeap = 0 overflowToOffHeap = false maxBytesLocalOffHeap = 0 maxBytesLocalDisk = 0 pinned = false ]
Feb
2015-01-20 07:34:39 [main] DEBUG com.mkyong.cache.HelloEhCache - element : [ key = 2, value=Feb, version=1, hitCount=1, CreationTime = 1421710479220, LastAccessTime = 1421710479220 ]
2015-01-20 07:34:39 [cache1.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
2015-01-20 07:34:39 [cache1.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk
2015-01-20 07:34:39 [cache1.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
2015-01-20 07:34:39 [cache1.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk
2015-01-20 07:34:39 [cache1.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
2015-01-20 07:34:39 [cache1.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk
2015-01-20 07:34:39 [main] DEBUG n.s.e.store.disk.DiskStorageFactory - Failed to delete file cache1.index
2015-01-20 07:34:39 [main] DEBUG n.s.e.store.disk.DiskStorageFactory - Failed to delete file cache1.data
2015-01-20 07:34:39 [main] DEBUG net.sf.ehcache.DiskStorePathManager - Deleted directory ehcache_auto_created8095047663436693875diskstore
2015-01-20 07:34:39 [main] DEBUG com.mkyong.cache.HelloEhCache - Shutting down Ehcache...

References

1. Logback Project
2. SLF4j manual
3. Ehcache logging