Second level ehcache not communicating across cluster - RMI implementation
joel.armani Dec 28, 2015 3:00 PMWe are currently experiencing an issue getting the second level ehcache cluster to communicate across two nodes on the same subnet. We're using Spring's net.sf.ehcache under the Wildfly hibernate subsystem. I have both nodes bound to specific IP addresses / NICs, and the second level cache appears to be loading properly, but i cannot get the cache to replicate/work across the two nodes.
I have the nodes running with the following jvm arguments:
Node 1 -
set "JAVA_OPTS=%JAVA_OPTS% -Djboss.bind.address=10.217.65.35"
set "JAVA_OPTS=%JAVA_OPTS% -Djboss.bind.address.management=10.217.65.35"
set "JAVA_OPTS=%JAVA_OPTS% -Djgroups.bind_addr=10.217.65.35"
set "JAVA_OPTS=%JAVA_OPTS% -Djava.rmi.server.hostname=10.217.65.35"
Node 2 -
set "JAVA_OPTS=%JAVA_OPTS% -Djboss.bind.address=10.217.65.36"
set "JAVA_OPTS=%JAVA_OPTS% -Djboss.bind.address.management=10.217.65.36"
set "JAVA_OPTS=%JAVA_OPTS% -Djgroups.bind_addr=10.217.65.36"
set "JAVA_OPTS=%JAVA_OPTS% -Djava.rmi.server.hostname=10.217.65.36"
Our cache manager peer listener and peer provider are extending the RMICacheManagerPeerListernerFactory and RMICacheManagerPeerProviderFactory classes.
I'm seeing the following output in the logs relating to Hibernate and ehcache:
Node1 -
...
2015-12-28 13:45:53,009 INFO [org.hibernate.cfg.Environment] (MSC service thread 1-1) Hibernate 3.2.6
2015-12-28 13:45:53,009 INFO [org.hibernate.cfg.Environment] (MSC service thread 1-1) hibernate.properties not found
2015-12-28 13:45:53,009 INFO [org.hibernate.cfg.Environment] (MSC service thread 1-1) Bytecode provider name : cglib
2015-12-28 13:45:53,025 INFO [org.hibernate.cfg.Environment] (MSC service thread 1-1) using JDK 1.4 java.sql.Timestamp handling
2015-12-28 13:45:53,103 DEBUG [org.hibernate.util.DTDEntityResolver] (MSC service thread 1-1) trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
2015-12-28 13:45:53,103 DEBUG [org.hibernate.util.DTDEntityResolver] (MSC service thread 1-1) recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
2015-12-28 13:45:53,103 DEBUG [org.hibernate.util.DTDEntityResolver] (MSC service thread 1-1) located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
...
2015-12-28 13:45:53,462 INFO [org.springframework.orm.hibernate3.LocalSessionFactoryBean] (MSC service thread 1-1) Building new Hibernate SessionFactory
2015-12-28 13:45:53,462 DEBUG [org.hibernate.cfg.Configuration] (MSC service thread 1-1) Preparing to build session factory with filters : {}
2015-12-28 13:45:53,462 DEBUG [org.hibernate.cfg.Configuration] (MSC service thread 1-1) processing extends queue
2015-12-28 13:45:53,462 DEBUG [org.hibernate.cfg.Configuration] (MSC service thread 1-1) processing collection mappings
2015-12-28 13:45:53,462 DEBUG [org.hibernate.cfg.Configuration] (MSC service thread 1-1) processing native query and ResultSetMapping mappings
2015-12-28 13:45:53,462 DEBUG [org.hibernate.cfg.Configuration] (MSC service thread 1-1) processing association property references
2015-12-28 13:45:53,462 DEBUG [org.hibernate.cfg.Configuration] (MSC service thread 1-1) processing foreign key constraints
...
2015-12-28 13:45:53,541 INFO [org.hibernate.connection.ConnectionProviderFactory] (MSC service thread 1-1) Initializing connection provider: org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider
2015-12-28 13:45:55,275 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) RDBMS: Microsoft SQL Server, version: 11.00.3156
2015-12-28 13:45:55,275 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) JDBC driver: Microsoft JDBC Driver 4.0 for SQL Server, version: 4.0.2206.100
2015-12-28 13:45:55,306 INFO [org.hibernate.dialect.Dialect] (MSC service thread 1-1) Using dialect: org.hibernate.dialect.SQLServerDialect
2015-12-28 13:45:55,322 INFO [org.hibernate.transaction.TransactionFactoryFactory] (MSC service thread 1-1) Transaction strategy: org.springframework.orm.hibernate3.SpringTransactionFactory
2015-12-28 13:45:55,322 INFO [org.hibernate.transaction.TransactionManagerLookupFactory] (MSC service thread 1-1) No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
2015-12-28 13:45:55,322 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Automatic flush during beforeCompletion(): disabled
2015-12-28 13:45:55,322 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Automatic session close at end of transaction: disabled
2015-12-28 13:45:55,322 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Scrollable result sets: enabled
2015-12-28 13:45:55,337 DEBUG [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Wrap result sets: disabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) JDBC3 getGeneratedKeys(): enabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Connection release mode: auto
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Default batch fetch size: 1
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Generate SQL with comments: disabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Order SQL updates by primary key: disabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Order SQL inserts for batching: disabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
2015-12-28 13:45:55,337 INFO [org.hibernate.hql.ast.ASTQueryTranslatorFactory] (MSC service thread 1-1) Using ASTQueryTranslatorFactory
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Query language substitutions: {}
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) JPA-QL strict compliance: disabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Second-level cache: enabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Query cache: enabled
2015-12-28 13:45:55,337 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Cache provider: org.hibernate.cache.EhCacheProvider
2015-12-28 13:45:55,353 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Optimize cache for minimal puts: disabled
2015-12-28 13:45:55,353 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Structured second-level cache entries: disabled
2015-12-28 13:45:55,353 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Query cache factory: org.hibernate.cache.StandardQueryCacheFactory
2015-12-28 13:45:55,369 TRACE [org.hibernate.exception.SQLExceptionConverterFactory] (MSC service thread 1-1) Using dialect defined converter
2015-12-28 13:45:55,369 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Statistics: enabled
2015-12-28 13:45:55,369 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Deleted entity synthetic identifier rollback: disabled
2015-12-28 13:45:55,369 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Default entity-mode: pojo
2015-12-28 13:45:55,369 INFO [org.hibernate.cfg.SettingsFactory] (MSC service thread 1-1) Named query checking : enabled
2015-12-28 13:45:55,431 INFO [org.hibernate.impl.SessionFactoryImpl] (MSC service thread 1-1) building session factory
2015-12-28 13:45:55,431 DEBUG [org.hibernate.impl.SessionFactoryImpl] (MSC service thread 1-1) Session factory constructed with filter configurations : {}
...
2015-12-28 13:45:55,462 DEBUG [net.sf.ehcache.CacheManager] (MSC service thread 1-1) Configuring ehcache from classpath.
2015-12-28 13:45:55,478 DEBUG [net.sf.ehcache.config.ConfigurationFactory] (MSC service thread 1-1) Configuring ehcache from ehcache.xml found in the classpath: vfs:/D:/apps/jb-PentahoNode/bin/content/pentaho.war/WEB-INF/classes/ehcache.xml
2015-12-28 13:45:55,478 DEBUG [net.sf.ehcache.config.ConfigurationFactory] (MSC service thread 1-1) Configuring ehcache from URL: vfs:/D:/apps/jb-PentahoNode/bin/content/pentaho.war/WEB-INF/classes/ehcache.xml
2015-12-28 13:45:55,478 DEBUG [net.sf.ehcache.config.ConfigurationFactory] (MSC service thread 1-1) Configuring ehcache from InputStream
2015-12-28 13:45:55,603 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\/_pentaho
2015-12-28 13:45:55,619 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,619 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,634 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,650 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,666 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,666 DEBUG [net.sf.ehcache.config.DiskStoreConfiguration] (MSC service thread 1-1) Disk Store Path: C:\Windows\TEMP\
2015-12-28 13:45:55,666 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) propertiesString is null.
2015-12-28 13:45:55,681 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheManagerEventListenerFactory class specified. Skipping...
2015-12-28 13:45:55,681 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) propertiesString is null.
2015-12-28 13:45:55,681 DEBUG [net.sf.ehcache.distribution.RMICacheManagerPeerListener] (MSC service thread 1-1) Automatically finding a free TCP/IP port to listen on: 4012
2015-12-28 13:45:55,697 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) Value found for peerDiscovery: automatic
2015-12-28 13:45:55,697 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) Value found for hostName: null
2015-12-28 13:45:55,697 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) Value found for multicastGroupAddress: 230.0.0.1
2015-12-28 13:45:55,697 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) Value found for multicastGroupPort: 4446
2015-12-28 13:45:55,697 DEBUG [net.sf.ehcache.util.PropertyUtil] (MSC service thread 1-1) Value found for timeToLive: 1
2015-12-28 13:45:55,728 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:55,728 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:55,728 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.distribution.RMICacheManagerPeerListener] (MSC service thread 1-1) 0 RMICachePeers bound in registry for RMI listener
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) No BootstrapCacheLoaderFactory class specified. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.Cache] (MSC service thread 1-1) CacheWriter factory not configured. Skipping...
2015-12-28 13:45:56,806 DEBUG [net.sf.ehcache.config.ConfigurationHelper] (MSC service thread 1-1) No CacheExceptionHandlerFactory class specified. Skipping...
...
2015-12-28 13:46:24,552 DEBUG [net.sf.ehcache.distribution.MulticastKeepaliveHeartbeatReceiver] (Multicast Heartbeat Receiver Thread) rmiUrls received //10.217.65.35:4024/ <-- repeats
...
2015-12-28 13:54:10,908 DEBUG [net.sf.ehcache.distribution.RMICacheManagerPeerProvider] (Multicast keep-alive Heartbeat Receiver thread-10) Lookup URL //10.217.65.36:52440/ <-- repeats once second node comes online
Node 2 is similar, with the addition of the corresponding IP addresses of itself and node1 in the heartbeat receiver messages.
---------------------------------------------------------------------------------------------------------------------------------------------------------------
I've tried adding in the additional jvm parameters to define the provider_class, factory_class, region_prefix, etc but it doesn't seem to be related to those.
Any ideas on what could be causing the nodes to not recognize each other and replicate the cache?