Uploaded image for project: 'Sakai'
  1. Sakai
  2. SAK-27676

Search Service:IndexTransactionException: Failed to prepare

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Reopened
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.8.0
    • Fix Version/s: None
    • Component/s: Search
    • Labels:
      None
    • Environment:
      Sakai 2.8.x, Java 1.6.0_25, Linux, Mysql
    • Previous Issue Keys:
      SRCH-61

      Description

      Note: I have put version 1.3.4 in the affected versions field, we are actually at 1.3.3 which isn't in the list.

      After upgrading from 2.7.1 to 2.8.x, the Search service failed to merge the shared journal correctly. We have seen this problem regulary in the past (after upgrades and at random intervals) and the fix has always been to rebuild the index completely. The rebuild was attempted twice once the problem was noticed without success. The following snippet from catalina.out shows the error we are getting. As can be seen from the snippet, the problem occurs at the first attempt to merge the shared journal data.

      2011-08-18 12:06:45,173 INFO IndexManager org.sakaiproject.search.optimize.shared.impl.OptimizeSharedTransactionListenerImpl - Merged SavePoint /usr/local/tomcat5/sakai/indexwork/journal-optimize-import/2 in 1972 ms /usr/local/tomcat5/sakai/indexwork/journal-optimize-import/2
      2011-08-18 12:06:46,639 INFO IndexManager org.sakaiproject.search.optimize.shared.impl.OptimizeSharedTransactionListenerImpl - Merged SavePoint /usr/local/tomcat5/sakai/indexwork/journal-optimize-import/1 in 1465 ms /usr/local/tomcat5/sakai/indexwork/journal-optimize-import/1
      2011-08-18 12:06:47,851 INFO IndexManager org.sakaiproject.search.optimize.shared.impl.OptimizeSharedTransactionListenerImpl - Optimized Working SavePoint in 1211 ms
      2011-08-18 12:06:47,851 INFO IndexManager org.sakaiproject.search.optimize.shared.impl.OptimizeSharedTransactionListenerImpl - Shared Optimize Timings
      Merged SavePoint 11 in 126 ms
      Merged SavePoint 10 in 286 ms
      Merged SavePoint 9 in 795 ms
      Merged SavePoint 8 in 517 ms
      Merged SavePoint 7 in 502 ms
      Merged SavePoint 6 in 953 ms
      Merged SavePoint 5 in 1987 ms
      Merged SavePoint 4 in 1105 ms
      Merged SavePoint 3 in 1423 ms
      Merged SavePoint 2 in 1972 ms
      Merged SavePoint 1 in 1465 ms
      Optimized Working SavePoint in 1211 ms
      Total Shared Optimize Merge Time (no transfer) 12433 ms

      2011-08-18 12:06:47,852 WARN IndexManager org.sakaiproject.search.optimize.shared.impl.JournalOptimizationOperation - Failed to complete optimize
      org.sakaiproject.search.transaction.api.IndexTransactionException: Failed to prepare
      at org.sakaiproject.search.transaction.impl.IndexTransactionImpl.prepare(IndexTransactionImpl.java:157)
      at org.sakaiproject.search.optimize.shared.impl.JournalOptimizationOperation.runOnce(JournalOptimizationOperation.java:90)
      at org.sakaiproject.search.journal.impl.IndexManagementTimerTask.run(IndexManagementTimerTask.java:137)
      at java.util.TimerThread.mainLoop(Timer.java:512)
      at java.util.TimerThread.run(Timer.java:462)
      Caused by: org.apache.lucene.store.AlreadyClosedException: this IndexWriter is closed
      at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:812)
      at org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:817)
      at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:4210)
      at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:4196)
      at org.sakaiproject.search.optimize.shared.impl.OptimizeSharedTransactionListenerImpl.prepare(OptimizeSharedTransactionListenerImpl.java:318)
      at org.sakaiproject.search.transaction.impl.IndexTransactionImpl.firePrepare(IndexTransactionImpl.java:313)
      at org.sakaiproject.search.transaction.impl.IndexTransactionImpl.prepare(IndexTransactionImpl.java:147)
      ... 4 more
      2011-08-18 12:08:17,883 INFO IndexManager org.sakaiproject.search.optimize.shared.impl.DbJournalOptimizationManager - Rolled Back Failed Shared Index operation a retry will happen on annother node soon
      2011-08-18 12:08:19,277 INFO IndexManager org.sakaiproject.search.component.adapter.contenthosting.ContentHostingContentProducer - Digesting /content/group/ERSC-BIOL-GEOG3P85D03FW2008MAIN/Former Presentations/Group Presentations Class of 2003/CANADA/CANADA_files/slide0010_image049.png

      Just prior to the error occuring the following query was run to check the state of the indexing process:

      mysql> select * from search_journal;
      --------------------------------------+

      txid txts indexwriter status

      --------------------------------------+

      1 1313681070458 LMS-APP4 commited
      2 1313681258420 LMS-APP4 commited
      3 1313681442788 LMS-APP4 commited
      4 1313681623950 LMS-APP4 commited
      5 1313681803014 LMS-APP4 commited
      6 1313682015077 LMS-APP4 commited
      7 1313682213961 LMS-APP4 commited
      8 1313682403552 LMS-APP4 commited
      9 1313682586837 LMS-APP4 commited
      10 1313682771604 LMS-APP4 commited
      11 1313683039218 LMS-APP4 commited

      --------------------------------------+
      11 rows in set (0.00 sec)

      The same query immediately after the error occurred produced:

      mysql> select * from search_journal;
      -------------------------------------------------+

      txid txts indexwriter status

      -------------------------------------------------+

      1 1313683697882 LMS-APP4:1313680803745 commited
      2 1313683697882 LMS-APP4:1313680803745 commited
      3 1313683697882 LMS-APP4:1313680803745 commited
      4 1313683697882 LMS-APP4:1313680803745 commited
      5 1313683697882 LMS-APP4:1313680803745 commited
      6 1313683697882 LMS-APP4:1313680803745 commited
      7 1313683697882 LMS-APP4:1313680803745 commited
      8 1313683697882 LMS-APP4:1313680803745 commited
      9 1313683697882 LMS-APP4:1313680803745 commited
      10 1313683697882 LMS-APP4:1313680803745 commited
      11 1313683697882 LMS-APP4:1313680803745 commited
      12 1313683320280 LMS-APP4 commited
      13 1313683594285 LMS-APP4 commited

      -------------------------------------------------+
      13 rows in set (0.00 sec)

        Gliffy Diagrams

          Zeplin

            Attachments

              Issue Links

                Activity

                  People

                  Assignee:
                  Unassigned Unassigned
                  Reporter:
                  thall Tom Hall (Inactive)
                  Votes:
                  1 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                    Dates

                    Created:
                    Updated:

                      Git Integration