Bug 747836 - Transaction failed when re-indexing full-text-search database
Summary: Transaction failed when re-indexing full-text-search database
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Zanata
Classification: Retired
Component: Component-Logic
Version: 1.4-SNAPSHOT
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: ---
Assignee: David Mason
QA Contact: Ding-Yi Chen
URL:
Whiteboard:
Depends On:
Blocks: Zanata-1.4.3
TreeView+ depends on / blocked
 
Reported: 2011-10-21 05:29 UTC by Sean Flanigan
Modified: 2012-04-23 04:32 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-04-23 04:32:33 UTC
Embargoed:


Attachments (Terms of Use)

Description Sean Flanigan 2011-10-21 05:29:52 UTC
Description of problem:

When the HTextFlow table is large, the transaction times out after five minutes and cancels the re-index.

Version-Release number of selected component (if applicable):
Zanata version 1.4.2-SNAPSHOT (20111021-1207).

How reproducible:
1/1

Steps to Reproduce:

1. Import some large projects, with many messages
2. As admin, click "re-index full-text-search database"
3. Wait five minutes
  
Actual results:

Re-indexing finished
Transaction failed

Expected results:

Should finish indexing without error (eventually).

Additional info:

2011-10-21 14:32:56,619 INFO  [org.zanata.action.AdminActionBean] (http-0.0.0.0-8080-3) Re-indexing started                                                          
2011-10-21 14:32:56,620 INFO  [org.zanata.action.AdminActionBean] (http-0.0.0.0-8080-3) Re-indexing class org.zanata.model.HIterationProject                         
2011-10-21 14:32:56,624 INFO  [org.zanata.action.AdminActionBean] (http-0.0.0.0-8080-3) Re-indexing class org.zanata.model.HAccount                                  
2011-10-21 14:32:56,825 INFO  [org.zanata.action.AdminActionBean] (http-0.0.0.0-8080-3) Re-indexing class org.zanata.model.HTextFlow                                 
2011-10-21 14:37:56,659 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-8) [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX 7f000001:d439:4ea0d8c7:20a in state  RUN                                                                                                        
2011-10-21 14:37:56,660 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-9) [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000001:d439:4ea0d8c7:20a invoked while multiple threads active within it.                                                                                                
2011-10-21 14:37:56,660 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-9) [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000001:d439:4ea0d8c7:20a aborting with 1 threads active!                                                                                              
2011-10-21 14:37:56,661 INFO  [org.hibernate.jdbc.ConnectionManager] (Thread-9) forcing batcher resource cleanup on transaction completion; forgot to close ScrollableResults/Iterator?                                                                                                                                                   
2011-10-21 14:37:56,662 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (Thread-9) [com.arjuna.ats.arjuna.coordinator.TransactionReaper_7] - TransactionReaper::doCancellations worker Thread[Thread-9,5,jboss] successfully canceled TX 7f000001:d439:4ea0d8c7:20a                                                                   
2011-10-21 14:37:56,744 WARN  [org.hibernate.util.JDBCExceptionReporter] (http-0.0.0.0-8080-3) SQL Error: 0, SQLState: null                                          
2011-10-21 14:37:56,744 ERROR [org.hibernate.util.JDBCExceptionReporter] (http-0.0.0.0-8080-3) The result set is closed.                                             
2011-10-21 14:37:56,744 WARN  [org.zanata.action.AdminActionBean] (http-0.0.0.0-8080-3) Unable to index objects of type org.zanata.model.HTextFlow                   
org.hibernate.exception.GenericJDBCException: could not advance using next()                                                                                         
        at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:126)                                                         
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:114)                                                                             
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)                                                                          
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52)                                                                          
        at org.hibernate.impl.ScrollableResultsImpl.next(ScrollableResultsImpl.java:127)                                                                             
        at org.zanata.action.AdminActionBean.reindex(AdminActionBean.java:87)                                                                                        
        at org.zanata.action.AdminActionBean.reindexDatabase(AdminActionBean.java:65)                                                                                
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                                                                                               
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)                                                                             
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)                                                                     
        at java.lang.reflect.Method.invoke(Method.java:597)                                                                                                          
        at org.jboss.seam.util.Reflections.invoke(Reflections.java:22)                                                                                               
        at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32)                                                                     
        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56)                                                                     
        at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28)                                                                  
        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68)                                                                     
        at org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77)                                                                       
        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68)                                                                     
        at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44)                                                               
        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68)                                                                     
        at org.jboss.seam.security.SecurityInterceptor.aroundInvoke(SecurityInterceptor.java:163)                                                                    
        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68)                                                                     
        at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107)                                                                                 
        at org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185)                                                            
        at org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103)                                                                         
        at org.zanata.action.AdminActionBean_$$_javassist_seam_1.reindexDatabase(AdminActionBean_$$_javassist_seam_1.java)                                           
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                                                                                               
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)                                                                             
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)                                                                     
        at java.lang.reflect.Method.invoke(Method.java:597)                                                                                                          
        at org.jboss.el.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:335)                                                                                    
        at org.jboss.el.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:348)                                                                                    
        at org.jboss.el.parser.AstPropertySuffix.invoke(AstPropertySuffix.java:58)                                                                                   
        at org.jboss.el.parser.AstValue.invoke(AstValue.java:96)                                                                                                     
        at org.jboss.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:276)                                                                                   
        at com.sun.facelets.el.TagMethodExpression.invoke(TagMethodExpression.java:68)                                                                               
        at javax.faces.component.MethodBindingMethodExpressionAdapter.invoke(MethodBindingMethodExpressionAdapter.java:88)                                           
        at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:102)                                                                   
        at javax.faces.component.UICommand.broadcast(UICommand.java:387)                                                                                             
        at org.ajax4jsf.component.AjaxActionComponent.broadcast(AjaxActionComponent.java:55)                                                                         
        at org.ajax4jsf.component.AjaxViewRoot.processEvents(AjaxViewRoot.java:329)                                                                                  
        at org.ajax4jsf.component.AjaxViewRoot.broadcastEventsForPhase(AjaxViewRoot.java:304)                                                                        
        at org.ajax4jsf.component.AjaxViewRoot.processPhase(AjaxViewRoot.java:261)                                                                                   
        at org.ajax4jsf.component.AjaxViewRoot.processApplication(AjaxViewRoot.java:474)                                                                             
        at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:82)                                                                    
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100)                                                                                                     
        at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)                                                                                     
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:265)                                                                                            
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)                                                         
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)                                                                 
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:638)                                                                     
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:444)                                                             
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:382)                                                                  
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:310)                                                                    
        at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:195)                                                               
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:159)                                                                             
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:141)                                                                                   
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:90)                                                                         
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:406)                                                                    
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)                                                         
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)                                                                 
        at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:83)                                                                            
        at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:73)                                                                            
        at org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:64)
        at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)
        at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:206)
        at org.ajax4jsf.webapp.BaseFilter.handleRequest(BaseFilter.java:290)
        at org.ajax4jsf.webapp.BaseFilter.processUploadsAndHandleRequest(BaseFilter.java:388)
        at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:515)
        at org.jboss.seam.web.Ajax4jsfFilter.doFilter(Ajax4jsfFilter.java:56)
        at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)
        at org.jboss.seam.web.LoggingFilter.doFilter(LoggingFilter.java:60)
        at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)
        at org.jboss.seam.servlet.SeamFilter.doFilter(SeamFilter.java:158)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:433)
        at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
        at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
        at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
        at java.lang.Thread.run(Thread.java:662)
Caused by: java.sql.SQLException: The result set is closed.
        at org.jboss.resource.adapter.jdbc.WrappedResultSet.checkState(WrappedResultSet.java:1959)
        at org.jboss.resource.adapter.jdbc.WrappedResultSet.next(WrappedResultSet.java:1193)
        at org.hibernate.impl.ScrollableResultsImpl.next(ScrollableResultsImpl.java:122)
        ... 90 more
2011-10-21 14:37:56,744 INFO  [org.zanata.action.AdminActionBean] (http-0.0.0.0-8080-3) Re-indexing finished
2011-10-21 14:37:56,746 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (http-0.0.0.0-8080-3) [com.arjuna.ats.arjuna.coordinator.BasicAction_40] - Abort called on already aborted atomic action 7f000001:d439:4ea0d8c7:20a

Comment 1 David Mason 2011-11-28 04:17:04 UTC
Fixed in 1.4 and 1.5

Reindexing is now a global action so does not depend on an individual session. Errors still occur on some reindex operations, but it should now be easier to detect a failed reindex through the GUI and re-run as appropriate.


https://github.com/zanata/zanata/compare/fbc68a29faf35486959833c8533967478d4c47c5...252016b6d4f56336166c76b144a3b7363743ef21

Comment 2 Ding-Yi Chen 2011-11-29 04:55:14 UTC
VERIFIED with 

Zanata version 1.4.3-alpha-3-SNAPSHOT (20111128-1320)
Zanata version 1.5-SNAPSHOT (20111129-0927)

Comment 4 Joshua Wulf 2012-01-26 07:48:41 UTC
For the release notes:

How do you detect a failed reindex from the GUI?

Comment 5 Joshua Wulf 2012-01-26 08:06:07 UTC
RELEASE NOTES TEXT:

Cause: Database reindexing was implemented in an individual session.

Consequence: A reindex operation on a large database could time-out rather than complete. When this occurred, some entries were not indexed.

Fix: Database reindexing is now a global action, and no longer depends on an individual session.

Result: Timeouts during reindexing operations are now less frequent, and when they do occur they are reported in the administrative interface, where they can be detected and the reindex operation performed again.


QUESTION:
How do you detect them through the GUI and how do you kick off the reindexing operation?

Comment 6 David Mason 2012-01-27 00:26:02 UTC
ANSWER:
Sign in as an administrator. Navigate to Administration -> Manage Search

If a reindex operation is not in progress, a button labeled "Re-index full text search database" is visible. This begins a full text search. If no error message is shown on this page, the most recent reindex operation since server restart was successful. No error message is shown if no reindex operation has been run since server restart, even if the most recent reindex before server restart failed.

If a reindex operation is in progress, a progress bar is shown.

If the most recent reindex operation failed, an error message is shown (generic for full text search, server log should give more specific information), the progress bar should be visible showing how much of the reindex operation was successful, and the "Re-index full text search database" button should be visible.

The "Manage Search" page may be blank occasionally - refreshing the page will fix this.


Note You need to log in before you can comment on or make changes to this bug.