We have a working EC2 hosted web application running within Tomcat with Spring, Hibernate, and Hibernate Search using Infinispan as the Lucene directory. We have 3 nodes clustered using S3 ping for auto-discovery and a master/slave config with jgroups (instead of JMS) serving as the backend. It works beautifully! However, there is a problem when we restart a node or deploy a new build to one of the slave nodes. As the Tomcat instance starts, Spring tries to create the Entity Manager for the data source. This fails when HSearch has Lucene read the indexes via Infinispan.
Code:
java.io.FileNotFoundException: Error loading medatada for index file: _0.tis|M|net.rcdb.td.model.Music
at org.infinispan.lucene.InfinispanDirectory.openInput(InfinispanDirectory.java:289)
At this point, if we make a Lucene query, we get zero results back. We see the same node that was restarted has altered the indexes to the point where they're no longer readable. I'm able to reproduce this same behavior locally in Eclipse by issuing a Restart command instead of the Stop and Start commands.
If we issue a kill command on the tomcat process, the server starts properly without corrupting the index. It seems there is some process on node shutdown which alters the index in a destructive way.
Has anyone seen this before? Perhaps we're missing some subtle bit of cache management config? Any insights are much appreciated. If we must alter the shutdown process, how is that best achieved? So far we've tried making the cluster replication asynchronous. We've also tried shutdown hook values of REGISTER and DEFAULT without effect.
We're using Hibernate Search version 4.1.1.Final which depends on Infinispan 5.1.4.Final.
Here's our server log when restarting the node. Below is our configuration.
Code:
19:36:37,956 INFO XmlWebApplicationContext:1032 - Closing WebApplicationContext for namespace 'dispatcher-servlet': startup date [Tue Jan 22 02:40:05 UTC 2013]; parent: Root WebApplicationContext
19:36:37,957 INFO DefaultListableBeanFactory:434 - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@2f3b5500: defining beans [...]; parent: org.springframework.beans.factory.support.DefaultListableBeanFactory@7b19753
19:36:37,964 INFO XmlWebApplicationContext:1032 - Closing Root WebApplicationContext: startup date [Tue Jan 22 02:39:41 UTC 2013]; root of context hierarchy
19:36:37,966 INFO DefaultListableBeanFactory:434 - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7b19753: defining beans [...]; root of factory hierarchy
19:36:38,034 DEBUG ThreadSafeClientConnManager:282 - Shutting down
19:36:38,049 INFO LocalContainerEntityManagerFactoryBean:441 - Closing JPA EntityManagerFactory for persistence unit 'td-model'
19:36:38,344 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Music'
19:36:38,345 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:43,166 DEBUG FD:445 - sending are-you-alive msg to domU-12-31-39-0C-D4-8D-39420 (own address=ip-10-66-90-118-43281)
19:36:44,422 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Individual'
19:36:44,423 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:46,167 DEBUG FD:445 - sending are-you-alive msg to domU-12-31-39-0C-D4-8D-39420 (own address=ip-10-66-90-118-43281)
19:36:46,575 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Product'
19:36:46,576 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:46,576 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Location'
19:36:46,576 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:48,240 DEBUG FD:445 - sending are-you-alive msg to domU-12-31-39-0C-D4-8D-16686 (own address=ip-10-66-90-118-57786)
19:36:49,100 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Character'
19:36:49,101 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,101 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Season'
19:36:49,102 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,102 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Series'
19:36:49,102 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,133 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.ProductCategory'
19:36:49,134 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,168 DEBUG FD:445 - sending are-you-alive msg to domU-12-31-39-0C-D4-8D-39420 (own address=ip-10-66-90-118-43281)
19:36:49,298 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Work'
19:36:49,298 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,299 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Setting'
19:36:49,299 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,299 DEBUG AbstractWorkspaceImpl:109 - HSEARCH000108: Shutting down backend for IndexManager 'net.rcdb.td.model.Studio'
19:36:49,299 DEBUG InfinispanDirectoryProvider:97 - Stopped InfinispanDirectory
19:36:49,300 INFO JGroupsChannelProvider:80 - HSEARCH000013: Disconnecting and closing JGroups Channel
19:36:49,300 DEBUG GMS:64 - sending LEAVE request to ip-10-29-195-137-32871 (local_addr=ip-10-66-90-118-43281)
19:36:49,356 DEBUG TCPConnectionMap:158 - connection table is not running, discarding message to 10.29.195.137:7800
19:36:49,658 DEBUG FD_SOCK:484 - socket to domU-12-31-39-0C-D4-8D-39420 was closed gracefully
19:36:49,658 DEBUG TCP:85 - closing sockets and stopping threads
19:36:49,661 DEBUG DefaultCacheManager:731 - Stopping cache manager snap-td-ec2-HibernateSearch-Infinispan-cluster on ip-10-66-90-118-57786
19:36:49,662 DEBUG CacheImpl:535 - Stopping cache LuceneIndexesMetadata on ip-10-66-90-118-57786
19:36:49,663 DEBUG TransactionTable:447 - Wait for on-going transactions to finish for 30 seconds.
19:36:49,663 DEBUG TransactionTable:468 - All transactions terminated
19:36:49,667 DEBUG CacheImpl:535 - Stopping cache LuceneIndexesData on ip-10-66-90-118-57786
19:36:49,669 DEBUG TransactionTable:447 - Wait for on-going transactions to finish for 30 seconds.
19:36:49,670 DEBUG TransactionTable:468 - All transactions terminated
19:36:49,672 DEBUG CacheImpl:535 - Stopping cache LuceneIndexesLocking on ip-10-66-90-118-57786
19:36:49,672 DEBUG TransactionTable:447 - Wait for on-going transactions to finish for 30 seconds.
19:36:49,673 DEBUG TransactionTable:468 - All transactions terminated
19:36:49,676 INFO JGroupsTransport:227 - ISPN000080: Disconnecting and closing JGroups Channel
19:36:49,677 DEBUG GMS:64 - sending LEAVE request to ip-10-29-195-137-2099 (local_addr=ip-10-66-90-118-57786)
19:36:49,732 DEBUG TCPConnectionMap:158 - connection table is not running, discarding message to 10.29.195.137:7801
19:36:49,732 DEBUG TCPConnectionMap:158 - connection table is not running, discarding message to 10.215.215.123:7801
19:36:49,733 DEBUG TCP:85 - closing sockets and stopping threads
19:36:49,735 INFO JGroupsTransport:244 - ISPN000082: Stopping the RpcDispatcher
19:36:49,736 INFO LocalContainerEntityManagerFactoryBean:441 - Closing JPA EntityManagerFactory for persistence unit 'rcdb-model'
19:36:49,784 INFO EhCacheManagerFactoryBean:133 - Shutting down EHCache CacheManager
19:37:13,202 INFO ContextLoader:272 - Root WebApplicationContext: initialization started
19:37:13,326 INFO XmlWebApplicationContext:503 - Refreshing Root WebApplicationContext: startup date [Tue Jan 22 19:37:13 UTC 2013]; root of context hierarchy
19:37:13,409 INFO XmlBeanDefinitionReader:315 - Loading XML bean definitions from class path resource [context-app.xml]
19:37:18,126 INFO LocalContainerEntityManagerFactoryBean:283 - Building JPA container EntityManagerFactory for persistence unit 'rcdb-model'
19:37:18,157 DEBUG UpdateChecker:68 - Checking for update...
19:37:18,203 DEBUG logging:142 - Logging Provider: org.jboss.logging.Log4jLoggerProvider
19:37:18,461 INFO Version:37 - HCANN000001: Hibernate Commons Annotations {4.0.1.Final}
19:37:18,484 INFO Version:41 - HHH000412: Hibernate Core {4.1.3.Final}
19:37:18,495 INFO Environment:239 - HHH000206: hibernate.properties not found
19:37:18,498 INFO Environment:342 - HHH000021: Bytecode provider name : javassist
19:37:18,541 INFO Ejb3Configuration:527 - HHH000204: Processing PersistenceUnitInfo [
name: rcdb-model
...]
19:37:19,581 INFO ConnectionProviderInitiator:188 - HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
19:37:20,532 INFO Dialect:122 - HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
19:37:20,550 INFO LobCreatorBuilder:94 - HHH000423: Disabling contextual LOB creation as JDBC driver reported JDBC version [3] less than 4
19:37:20,576 INFO TransactionFactoryInitiator:73 - HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory
19:37:20,584 INFO ASTQueryTranslatorFactory:48 - HHH000397: Using ASTQueryTranslatorFactory
19:37:20,651 INFO Version:27 - HV000001: Hibernate Validator 4.3.0.Final
19:37:21,099 INFO Version:39 - HSEARCH000034: Hibernate Search 4.1.1.Final
19:37:21,146 WARN ConfigContext:299 - HSEARCH000075: Configuration setting hibernate.search.lucene_version was not specified, using LUCENE_CURRENT.
19:37:21,174 DEBUG ConfigContext:208 - Using default similarity implementation: org.apache.lucene.search.DefaultSimilarity
19:37:21,216 DEBUG FullTextIndexEventListener:147 - Hibernate Search event listeners deactivated
19:37:21,217 DEBUG FullTextIndexEventListener:150 - Hibernate Search dirty checks enabled
19:37:21,543 INFO LocalContainerEntityManagerFactoryBean:283 - Building JPA container EntityManagerFactory for persistence unit 'td-model'
19:37:21,545 INFO Ejb3Configuration:527 - HHH000204: Processing PersistenceUnitInfo [
name: td-model
...]
19:37:21,783 INFO ConnectionProviderInitiator:188 - HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
19:37:22,107 INFO Dialect:122 - HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect
19:37:22,108 INFO LobCreatorBuilder:94 - HHH000423: Disabling contextual LOB creation as JDBC driver reported JDBC version [3] less than 4
19:37:22,109 INFO TransactionFactoryInitiator:73 - HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory
19:37:22,110 INFO ASTQueryTranslatorFactory:48 - HHH000397: Using ASTQueryTranslatorFactory
19:37:22,284 WARN ConfigContext:299 - HSEARCH000075: Configuration setting hibernate.search.lucene_version was not specified, using LUCENE_CURRENT.
19:37:22,285 DEBUG ConfigContext:208 - Using default similarity implementation: org.apache.lucene.search.DefaultSimilarity
19:37:22,516 INFO JGroupsChannelProvider:93 - HSEARCH000005: Starting JGroups Channel
19:37:22,562 DEBUG ClassConfigurator:74 - Using jg-magic-map.xml as magic number file and jg-protocol-ids.xml for protocol IDs
19:37:22,798 DEBUG Configurator:830 - set property TCP.diagnostics_addr to default value /224.0.75.75
19:37:22,837 DEBUG FRAG2:176 - received CONFIG event: {bind_addr=/10.66.90.118}
19:37:23,427 DEBUG GMS:920 - address=ip-10-66-90-118-20922, cluster=snap-backend, physical address=10.66.90.118:7800
19:37:23,548 DEBUG GMS:307 - election results: {ip-10-29-195-137-32871=1}
19:37:23,549 DEBUG GMS:131 - sending JOIN(ip-10-66-90-118-20922) to ip-10-29-195-137-32871
19:37:23,828 DEBUG NAKACK:1131 -
[setDigest()]
existing digest: []
new digest: ip-10-29-195-137-32871: [549 (549)], domU-12-31-39-0C-D4-8D-39420: [514 (514)], ip-10-66-90-118-20922: [0 (0)]
resulting digest: domU-12-31-39-0C-D4-8D-39420: [514 (514)], ip-10-29-195-137-32871: [549 (549)], ip-10-66-90-118-20922: [0 (0)]
19:37:23,829 DEBUG GMS:591 - ip-10-66-90-118-20922: view is [ip-10-29-195-137-32871|4] [ip-10-29-195-137-32871, domU-12-31-39-0C-D4-8D-39420, ip-10-66-90-118-20922]
19:37:23,830 DEBUG FD_SOCK:330 - VIEW_CHANGE received: [ip-10-29-195-137-32871, domU-12-31-39-0C-D4-8D-39420, ip-10-66-90-118-20922]
19:37:23,832 DEBUG STABLE:364 - [ergonomics] setting max_bytes to 1.2MB (3 members)
19:37:23,837 INFO JGroupsMasterMessageListener:117 - HSEARCH000015: Received new cluster view: [ip-10-29-195-137-32871|4] [ip-10-29-195-137-32871, domU-12-31-39-0C-D4-8D-39420, ip-10-66-90-118-20922]
19:37:23,843 INFO JGroupsChannelProvider:107 - HSEARCH000006: Connected to cluster [ snap-backend ]. The node address is ip-10-66-90-118-20922
19:37:23,843 WARN JGroupsChannelProvider:110 - HSEARCH000007: FLUSH is not present in your JGroups stack! FLUSH is needed to ensure messages are not dropped while new nodes join the cluster. Will proceed, but inconsistencies may arise!
19:37:23,861 DEBUG FD_SOCK:388 - ping_dest is ip-10-29-195-137-32871, pingable_mbrs=[ip-10-29-195-137-32871, domU-12-31-39-0C-D4-8D-39420, ip-10-66-90-118-20922]
19:37:23,863 DEBUG WorkspaceFactory:47 - Starting workspace for index net.rcdb.td.model.Music using a shared index strategy
19:37:23,937 DEBUG InfinispanDirectoryProvider:82 - Starting InfinispanDirectory
19:37:24,237 DEBUG L1ConfigurationBuilder:141 - L1 is enabled and L1OnRehash was not defined, enabling it
19:37:24,254 DEBUG L1ConfigurationBuilder:141 - L1 is enabled and L1OnRehash was not defined, enabling it
19:37:24,254 DEBUG L1ConfigurationBuilder:141 - L1 is enabled and L1OnRehash was not defined, enabling it
19:37:24,274 DEBUG TransactionConfigurationBuilder:217 - Switching to Synchronization based enlistment.
19:37:24,274 DEBUG L1ConfigurationBuilder:141 - L1 is enabled and L1OnRehash was not defined, enabling it
19:37:24,293 DEBUG TransactionConfigurationBuilder:217 - Switching to Synchronization based enlistment.
19:37:24,293 DEBUG TransactionConfigurationBuilder:217 - Switching to Synchronization based enlistment.
19:37:24,294 DEBUG TransactionConfigurationBuilder:217 - Switching to Synchronization based enlistment.
19:37:24,310 DEBUG ModuleProperties:71 - Loading lifecycle SPI class: org.infinispan.lucene.LifecycleCallbacks@4c0d39ac
19:37:24,380 DEBUG ModuleProperties:117 - No module command extensions to load
19:37:24,393 DEBUG AbstractJBossMarshaller:54 - Using JBoss Marshalling
19:37:24,638 DEBUG DefaultCacheManager:721 - Started cache manager snap-td-ec2-HibernateSearch-Infinispan-cluster on null
19:37:24,646 DEBUG JmxUtil:96 - Object name org.infinispan:type=CacheManager,name="HibernateSearch",component=CacheManager already registered
19:37:24,647 DEBUG DefaultCacheManager:721 - Started cache manager snap-td-ec2-HibernateSearch-Infinispan-cluster on null
19:37:24,752 INFO JGroupsTransport:172 - ISPN000078: Starting JGroups Channel
19:37:24,810 DEBUG Configurator:830 - set property TCP.diagnostics_addr to default value /224.0.75.75
19:37:24,837 DEBUG FRAG2:176 - received CONFIG event: {bind_addr=/10.66.90.118}
19:37:24,880 DEBUG GMS:920 - address=ip-10-66-90-118-32362, cluster=snap-td-ec2-HibernateSearch-Infinispan-cluster, physical address=10.66.90.118:7801
19:37:24,969 DEBUG GMS:307 - election results: {ip-10-29-195-137-2099=2}
19:37:24,969 DEBUG GMS:131 - sending JOIN(ip-10-66-90-118-32362) to ip-10-29-195-137-2099
19:37:25,158 DEBUG NAKACK:1131 -
[setDigest()]
existing digest: []
new digest: ip-10-29-195-137-2099: [582 (582)], domU-12-31-39-0C-D4-8D-16686: [629 (629)], ip-10-66-90-118-32362: [0 (0)]
resulting digest: domU-12-31-39-0C-D4-8D-16686: [629 (629)], ip-10-29-195-137-2099: [582 (582)], ip-10-66-90-118-32362: [0 (0)]
19:37:25,158 DEBUG GMS:591 - ip-10-66-90-118-32362: view is [ip-10-29-195-137-2099|4] [ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]
19:37:25,158 DEBUG FD_SOCK:330 - VIEW_CHANGE received: [ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]
19:37:25,159 DEBUG STABLE:364 - [ergonomics] setting max_bytes to 1.2MB (3 members)
19:37:25,160 DEBUG JGroupsTransport:580 - New view accepted: [ip-10-29-195-137-2099|4] [ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]
19:37:25,161 INFO JGroupsTransport:607 - ISPN000094: Received new cluster view: [ip-10-29-195-137-2099|4] [ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]
19:37:25,161 DEBUG FD_SOCK:388 - ping_dest is ip-10-29-195-137-2099, pingable_mbrs=[ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]
19:37:25,202 INFO JGroupsTransport:210 - ISPN000079: Cache local address is ip-10-66-90-118-32362, physical addresses are [10.66.90.118:7801]
19:37:25,203 DEBUG JGroupsTransport:395 - Waiting on view being accepted
19:37:25,210 INFO GlobalComponentRegistry:204 - ISPN000128: Infinispan version: Infinispan 'Brahma' 5.1.4.FINAL
19:37:25,265 INFO TransactionManagerFactory:76 - ISPN000161: Using a batchMode transaction manager
19:37:25,391 DEBUG AbstractJBossMarshaller:54 - Using JBoss Marshalling
19:37:25,406 INFO TransactionManagerFactory:76 - ISPN000161: Using a batchMode transaction manager
19:37:25,410 DEBUG AbstractJBossMarshaller:54 - Using JBoss Marshalling
19:37:25,412 INFO TransactionManagerFactory:76 - ISPN000161: Using a batchMode transaction manager
19:37:25,433 DEBUG TransactionTable:143 - Min view id set to 4
19:37:25,440 DEBUG AbstractJBossMarshaller:54 - Using JBoss Marshalling
19:37:25,441 DEBUG TransactionTable:143 - Min view id set to 4
19:37:25,439 DEBUG TransactionTable:143 - Min view id set to 4
19:37:25,446 DEBUG InterceptorChain:75 - Interceptor chain size: 10
19:37:25,446 DEBUG InterceptorChain:76 - Interceptor chain is:
>> org.infinispan.interceptors.BatchingInterceptor
>> org.infinispan.interceptors.InvocationContextInterceptor
>> org.infinispan.interceptors.CacheMgmtInterceptor
>> org.infinispan.interceptors.StateTransferLockInterceptor
>> org.infinispan.interceptors.TxInterceptor
>> org.infinispan.interceptors.NotificationInterceptor
>> org.infinispan.interceptors.locking.OptimisticLockingInterceptor
>> org.infinispan.interceptors.EntryWrappingInterceptor
>> org.infinispan.interceptors.ReplicationInterceptor
>> org.infinispan.interceptors.CallInterceptor
19:37:25,446 DEBUG InterceptorChain:75 - Interceptor chain size: 10
19:37:25,446 DEBUG InterceptorChain:75 - Interceptor chain size: 10
19:37:25,448 DEBUG InterceptorChain:76 - Interceptor chain is:
>> org.infinispan.interceptors.BatchingInterceptor
>> org.infinispan.interceptors.InvocationContextInterceptor
>> org.infinispan.interceptors.CacheMgmtInterceptor
>> org.infinispan.interceptors.StateTransferLockInterceptor
>> org.infinispan.interceptors.TxInterceptor
>> org.infinispan.interceptors.NotificationInterceptor
>> org.infinispan.interceptors.locking.OptimisticLockingInterceptor
>> org.infinispan.interceptors.EntryWrappingInterceptor
>> org.infinispan.interceptors.ReplicationInterceptor
>> org.infinispan.interceptors.CallInterceptor
19:37:25,454 DEBUG InterceptorChain:76 - Interceptor chain is:
>> org.infinispan.interceptors.BatchingInterceptor
>> org.infinispan.interceptors.InvocationContextInterceptor
>> org.infinispan.interceptors.CacheMgmtInterceptor
>> org.infinispan.interceptors.StateTransferLockInterceptor
>> org.infinispan.interceptors.TxInterceptor
>> org.infinispan.interceptors.NotificationInterceptor
>> org.infinispan.interceptors.locking.OptimisticLockingInterceptor
>> org.infinispan.interceptors.EntryWrappingInterceptor
>> org.infinispan.interceptors.ReplicationInterceptor
>> org.infinispan.interceptors.CallInterceptor
19:37:25,457 DEBUG JmxUtil:96 - Object name org.infinispan:type=Cache,name="LuceneIndexesData(repl_sync)",manager="HibernateSearch",component=Cache already registered
19:37:25,459 INFO CacheJmxRegistration:84 - ISPN000031: MBeans were successfully registered to the platform mbean server.
19:37:25,459 DEBUG JmxUtil:96 - Object name org.infinispan:type=Cache,name="LuceneIndexesLocking(repl_sync)",manager="HibernateSearch",component=Cache already registered
19:37:25,459 DEBUG JmxUtil:96 - Object name org.infinispan:type=Cache,name="LuceneIndexesMetadata(repl_sync)",manager="HibernateSearch",component=Cache already registered
19:37:25,460 INFO CacheJmxRegistration:84 - ISPN000031: MBeans were successfully registered to the platform mbean server.
19:37:25,460 INFO CacheJmxRegistration:84 - ISPN000031: MBeans were successfully registered to the platform mbean server.
19:37:25,468 DEBUG CacheViewsManagerImpl:400 - LuceneIndexesData: Node ip-10-66-90-118-32362 is joining
19:37:25,471 DEBUG CacheViewsManagerImpl:400 - LuceneIndexesLocking: Node ip-10-66-90-118-32362 is joining
19:37:25,468 DEBUG CacheViewsManagerImpl:400 - LuceneIndexesMetadata: Node ip-10-66-90-118-32362 is joining
19:37:25,558 DEBUG BaseStateTransferManagerImpl:233 - Applying new state from domU-12-31-39-0C-D4-8D-16686: received 0 keys
19:37:25,559 DEBUG BaseStateTransferManagerImpl:233 - Applying new state from ip-10-29-195-137-2099: received 0 keys
19:37:25,559 DEBUG BaseStateTransferManagerImpl:233 - Applying new state from ip-10-29-195-137-2099: received 10 keys
19:37:25,560 DEBUG BaseStateTransferManagerImpl:233 - Applying new state from domU-12-31-39-0C-D4-8D-16686: received 58 keys
19:37:25,571 DEBUG DefaultConsistentHash:134 - Using 1 virtualNodes to initialize consistent hash wheel
19:37:25,572 DEBUG DefaultConsistentHash:134 - Using 1 virtualNodes to initialize consistent hash wheel
19:37:25,578 DEBUG DefaultConsistentHash:134 - Using 1 virtualNodes to initialize consistent hash wheel
19:37:25,582 DEBUG ReplicatedStateTransferTask:79 - Commencing state transfer 5 on node: ip-10-66-90-118-32362. Before start, data container had 0 entries
19:37:25,584 DEBUG ReplicatedStateTransferTask:79 - Commencing state transfer 5 on node: ip-10-66-90-118-32362. Before start, data container had 68 entries
19:37:25,584 DEBUG StateTransferLockImpl:225 - Blocking new write commands for cache view 5
19:37:25,584 DEBUG StateTransferLockImpl:225 - Blocking new write commands for cache view 5
19:37:25,583 DEBUG ReplicatedStateTransferTask:79 - Commencing state transfer 5 on node: ip-10-66-90-118-32362. Before start, data container had 0 entries
19:37:25,585 DEBUG StateTransferLockImpl:225 - Blocking new write commands for cache view 5
19:37:25,589 DEBUG CacheViewsManagerImpl:506 - LuceneIndexesLocking: Committing cache view CacheView{viewId=5, members=[ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]}
19:37:25,589 DEBUG BaseStateTransferTask:109 - Node ip-10-66-90-118-32362 completed state transfer for view 5 in 6 milliseconds!
19:37:25,590 DEBUG CacheViewsManagerImpl:506 - LuceneIndexesData: Committing cache view CacheView{viewId=5, members=[ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]}
19:37:25,590 DEBUG BaseStateTransferTask:109 - Node ip-10-66-90-118-32362 completed state transfer for view 5 in 7 milliseconds!
19:37:25,591 DEBUG StateTransferLockImpl:257 - Unblocking write commands for cache view 5
19:37:25,591 DEBUG StateTransferLockImpl:257 - Unblocking write commands for cache view 5
19:37:25,592 DEBUG CacheImpl:524 - Started cache LuceneIndexesLocking on ip-10-66-90-118-32362
19:37:25,592 DEBUG CacheImpl:524 - Started cache LuceneIndexesData on ip-10-66-90-118-32362
19:37:25,639 DEBUG BaseStateTransferManagerImpl:233 - Applying new state from ip-10-29-195-137-2099: received 6 keys
19:37:25,648 DEBUG BaseStateTransferManagerImpl:233 - Applying new state from domU-12-31-39-0C-D4-8D-16686: received 69 keys
19:37:25,656 DEBUG CacheViewsManagerImpl:506 - LuceneIndexesMetadata: Committing cache view CacheView{viewId=5, members=[ip-10-29-195-137-2099, domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]}
19:37:25,657 DEBUG BaseStateTransferTask:109 - Node ip-10-66-90-118-32362 completed state transfer for view 5 in 74 milliseconds!
19:37:25,657 DEBUG StateTransferLockImpl:257 - Unblocking write commands for cache view 5
19:37:25,657 DEBUG CacheImpl:524 - Started cache LuceneIndexesMetadata on ip-10-66-90-118-32362
19:37:25,695 DEBUG InfinispanDirectoryProvider:90 - Initialized Infinispan index: 'net.rcdb.td.model.Music'
19:37:25,730 INFO DefaultListableBeanFactory:434 - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@14eac7c8: defining beans [...]; root of factory hierarchy
19:37:25,739 INFO LocalContainerEntityManagerFactoryBean:441 - Closing JPA EntityManagerFactory for persistence unit 'rcdb-model'
19:37:25,787 INFO EhCacheManagerFactoryBean:133 - Shutting down EHCache CacheManager
19:37:25,792 ERROR ContextLoader:307 - Context initialization failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'tdEntityManagerFactory' defined in class path resource [context-app.xml]: Invocation of init method failed; nested exception is org.hibernate.search.SearchException: HSEARCH000103: Unable to initialize IndexManager net.rcdb.td.model.Music
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1455)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:294)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1105)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:915)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:472)
at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:383)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:283)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:111)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4779)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5273)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:895)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:871)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:615)
at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1099)
at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1621)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Caused by: org.hibernate.search.SearchException: HSEARCH000103: Unable to initialize IndexManager net.rcdb.td.model.Music
at org.hibernate.search.indexes.impl.IndexManagerHolder.createDirectoryManager(IndexManagerHolder.java:244)
at org.hibernate.search.indexes.impl.IndexManagerHolder.buildEntityIndexBinding(IndexManagerHolder.java:111)
at org.hibernate.search.spi.SearchFactoryBuilder.initDocumentBuilders(SearchFactoryBuilder.java:411)
at org.hibernate.search.spi.SearchFactoryBuilder.buildNewSearchFactory(SearchFactoryBuilder.java:221)
at org.hibernate.search.spi.SearchFactoryBuilder.buildSearchFactory(SearchFactoryBuilder.java:145)
at org.hibernate.search.event.impl.FullTextIndexEventListener.initialize(FullTextIndexEventListener.java:129)
at org.hibernate.search.hcore.impl.HibernateSearchIntegrator.integrate(HibernateSearchIntegrator.java:82)
at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:306)
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1744)
at org.hibernate.ejb.EntityManagerFactoryImpl.<init>(EntityManagerFactoryImpl.java:94)
at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:905)
at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:890)
at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:74)
at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:287)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:310)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1514)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1452)
... 26 more
Caused by: org.hibernate.search.SearchException: Unable to open Lucene IndexReader for IndexManager net.rcdb.td.model.Music
at org.hibernate.search.indexes.impl.SharingBufferReaderProvider.createReader(SharingBufferReaderProvider.java:113)
at org.hibernate.search.indexes.impl.SharingBufferReaderProvider.initialize(SharingBufferReaderProvider.java:91)
at org.hibernate.search.indexes.impl.CommonPropertiesParse.createDirectoryBasedReaderProvider(CommonPropertiesParse.java:159)
at org.hibernate.search.indexes.impl.DirectoryBasedIndexManager.createIndexReader(DirectoryBasedIndexManager.java:212)
at org.hibernate.search.indexes.impl.DirectoryBasedIndexManager.initialize(DirectoryBasedIndexManager.java:94)
at org.hibernate.search.indexes.impl.IndexManagerHolder.createDirectoryManager(IndexManagerHolder.java:241)
... 42 more
Caused by: java.io.FileNotFoundException: Error loading medatada for index file: _0.tis|M|net.rcdb.td.model.Music
at org.infinispan.lucene.InfinispanDirectory.openInput(InfinispanDirectory.java:289)
at org.apache.lucene.store.Directory.openInput(Directory.java:143)
at org.apache.lucene.index.TermInfosReader.<init>(TermInfosReader.java:104)
at org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders.java:76)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:115)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:93)
at org.apache.lucene.index.DirectoryReader.<init>(DirectoryReader.java:113)
at org.apache.lucene.index.ReadOnlyDirectoryReader.<init>(ReadOnlyDirectoryReader.java:29)
at org.apache.lucene.index.DirectoryReader$1.doBody(DirectoryReader.java:81)
at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:754)
at org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:75)
at org.apache.lucene.index.IndexReader.open(IndexReader.java:462)
at org.apache.lucene.index.IndexReader.open(IndexReader.java:322)
at org.hibernate.search.indexes.impl.SharingBufferReaderProvider.readerFactory(SharingBufferReaderProvider.java:131)
at org.hibernate.search.indexes.impl.SharingBufferReaderProvider$PerDirectoryLatestReader.<init>(SharingBufferReaderProvider.java:205)
at org.hibernate.search.indexes.impl.SharingBufferReaderProvider.createReader(SharingBufferReaderProvider.java:108)
... 47 more
19:37:26,230 DEBUG FD_SOCK:403 - could not create socket to ip-10-29-195-137-2099
19:37:26,231 DEBUG FD_SOCK:690 - suspecting ip-10-29-195-137-2099 (own address is ip-10-66-90-118-32362)
19:37:26,231 DEBUG FD_SOCK:388 - ping_dest is domU-12-31-39-0C-D4-8D-16686, pingable_mbrs=[domU-12-31-39-0C-D4-8D-16686, ip-10-66-90-118-32362]
Code:
<infinispan
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="urn:infinispan:config:5.1 http://www.infinispan.org/schemas/infinispan-config-5.1.xsd"
xmlns="urn:infinispan:config:5.1">
<!-- *************************** -->
<!-- System-wide global settings -->
<!-- *************************** -->
<global>
<!-- Duplicate domains are allowed so that multiple deployments with default configuration
of Hibernate Search applications work - if possible it would be better to use JNDI to share
the CacheManager across applications -->
<globalJmxStatistics
enabled="true"
cacheManagerName="HibernateSearch"
allowDuplicateDomains="true" />
<!-- If the transport is omitted, there is no way to create distributed or clustered
caches. There is no added cost to defining a transport but not creating a cache that uses one,
since the transport is created and initialized lazily. -->
<transport clusterName="${ww.env}-ec2-HibernateSearch-Infinispan-cluster"
distributedSyncTimeout="50000"
transportClass="org.infinispan.remoting.transport.jgroups.JGroupsTransport">
<properties>
<property name="configurationFile" value="jgroups-ec2.xml"/>
</properties>
</transport>
<!-- Note that the JGroups transport uses sensible defaults if no configuration property
is defined. See the Infinispan wiki for more JGroups settings:
http://community.jboss.org/wiki/ClusteredConfigurationQuickStart -->
<!-- Used to register JVM shutdown hooks. hookBehavior: DEFAULT, REGISTER, DONT_REGISTER.
Hibernate Search takes care to stop the CacheManager so registering is not needed -->
<shutdown
hookBehavior="REGISTER" />
</global>
<!-- *************************** -->
<!-- Default "template" settings -->
<!-- *************************** -->
<default>
<locking
lockAcquisitionTimeout="20000"
writeSkewCheck="false"
concurrencyLevel="500"
useLockStriping="false" />
<!-- Invocation batching is required for use with the Lucene Directory -->
<invocationBatching
enabled="true" />
<!-- This element specifies that the cache is clustered. modes supported: distribution
(d), replication (r) or invalidation (i). Don't use invalidation to store Lucene indexes (as
with Hibernate Search DirectoryProvider). Replication is recommended for best performance of
Lucene indexes, but make sure you have enough memory to store the index in your heap.
Also distribution scales much better than replication on high number of nodes in the cluster. -->
<clustering
mode="replication">
<!-- Prefer loading all data at startup than later -->
<stateTransfer
timeout="480000"
fetchInMemoryState="true" />
<!-- Network calls are synchronous by default -->
<sync
replTimeout="20000" />
</clustering>
<jmxStatistics
enabled="true" />
<eviction
maxEntries="-1"
strategy="NONE" />
<expiration
maxIdle="-1" />
</default>
<!-- ******************************************************************************* -->
<!-- Individually configured "named" caches. -->
<!-- -->
<!-- While default configuration happens to be fine with similar settings across the -->
<!-- three caches, they should generally be different in a production environment. -->
<!-- -->
<!-- Current settings could easily lead to OutOfMemory exception as a CacheStore -->
<!-- should be enabled, and maybe distribution is desired. -->
<!-- ******************************************************************************* -->
<!-- *************************************** -->
<!-- Cache to store Lucene's file metadata -->
<!-- *************************************** -->
<namedCache
name="LuceneIndexesMetadata">
<clustering
mode="replication">
<stateTransfer
fetchInMemoryState="true" />
<sync
replTimeout="25000" />
</clustering>
</namedCache>
<!-- **************************** -->
<!-- Cache to store Lucene data -->
<!-- **************************** -->
<namedCache
name="LuceneIndexesData">
<clustering
mode="replication">
<stateTransfer
fetchInMemoryState="true" />
<sync
replTimeout="25000" />
</clustering>
</namedCache>
<!-- ***************************** -->
<!-- Cache to store Lucene locks -->
<!-- ***************************** -->
<namedCache
name="LuceneIndexesLocking">
<clustering
mode="replication">
<stateTransfer
fetchInMemoryState="true" />
<sync
replTimeout="25000" />
</clustering>
<expiration lifespan="15000" />
</namedCache>
</infinispan>
Code:
<config xmlns="urn:org:jgroups"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="urn:org:jgroups file:schema/JGroups-3.0.xsd">
<TCP
bind_addr="${jgroups.tcp.address:127.0.0.1}"
bind_port="${jgroups.tcp.port:7800}"
loopback="true"
port_range="30"
recv_buf_size="20000000"
send_buf_size="640000"
discard_incompatible_packets="true"
max_bundle_size="64000"
max_bundle_timeout="30"
enable_bundling="true"
use_send_queues="true"
sock_conn_timeout="300"
enable_diagnostics="false"
thread_pool.enabled="true"
thread_pool.min_threads="2"
thread_pool.max_threads="30"
thread_pool.keep_alive_time="60000"
thread_pool.queue_enabled="false"
thread_pool.queue_max_size="100"
thread_pool.rejection_policy="Discard"
oob_thread_pool.enabled="true"
oob_thread_pool.min_threads="2"
oob_thread_pool.max_threads="30"
oob_thread_pool.keep_alive_time="60000"
oob_thread_pool.queue_enabled="false"
oob_thread_pool.queue_max_size="100"
oob_thread_pool.rejection_policy="Discard"
/>
<S3_PING secret_access_key="secret" access_key="secret" location="secret"/>
<MERGE2 max_interval="30000"
min_interval="10000"/>
<FD_SOCK start_port="9777"/>
<FD timeout="3000" max_tries="3"/>
<VERIFY_SUSPECT timeout="1500"/>
<pbcast.NAKACK
use_mcast_xmit="false"
retransmit_timeout="300,600,1200,2400,4800"
discard_delivered_msgs="false"/>
<UNICAST2 timeout="300,600,1200"/>
<pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000"
max_bytes="400000"/>
<pbcast.GMS print_local_addr="false" join_timeout="7000" view_bundling="true"/>
<UFC max_credits="2000000" min_threshold="0.10"/>
<MFC max_credits="2000000" min_threshold="0.10"/>
<FRAG2 frag_size="60000"/>
</config>
Any help is greatly appreciated!
Login
FAQ
Search
