SourceForge.net Logo
Main Overview Wiki Issues Forum Build Fisheye
Issue Details (XML | Word | Printable)

Key: CMP-331
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Minor Minor
Assignee: Shay Banon
Reporter: Matt Solnit
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Compass

Exceptions in DBCP masked as lock timeouts

Created: 04/Dec/06 05:27 PM   Updated: 05/Dec/06 11:38 AM
Component/s: Compass::Core
Affects Version/s: 1.1 M3
Fix Version/s: 1.1 RC1

File Attachments: 1. Java Source File PhantomReadLock.java (3 kB)
2. Text File PhantomReadLock.java.patch (2 kB)
Environment: Mac OS X 10.4.8 (Intel), Java 1.5.0_06


 Description  « Hide
This is minor IMO... using the DBCP configuration in the documentation (http://www.opensymphony.com/compass/versions/1.1M3/html/core-connection.html#core-connection-jdbc-dsp-dbcp), I was getting the following error when calling CompassGps.index():

Caused by: org.compass.core.engine.SearchEngineException: Failed while executing a lucene directory based operation; nested exception is java.io.IOException: Lock obtain timed out: PhantomReadLock[write.lock/index_folderitem]
[java] at org.compass.core.lucene.engine.store.LuceneStoreTemplate.execute(LuceneStoreTemplate.java:63)
[java] at org.compass.core.lucene.engine.store.LuceneStoreTemplate.executeForSubIndex(LuceneStoreTemplate.java:37)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore.createIndex(AbstractLuceneSearchEngineStore.java:208)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore.verifyIndex(AbstractLuceneSearchEngineStore.java:240)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore.verifyIndex(AbstractLuceneSearchEngineStore.java:255)
[java] at org.compass.core.lucene.engine.manager.DefaultLuceneSearchEngineIndexManager.verifyIndex(DefaultLuceneSearchEngineIndexManager.java:89)
[java] at org.compass.core.impl.DefaultCompass$TransactionalSearchEngineIndexManager$2.doInCompass(DefaultCompass.java:293)
[java] at org.compass.core.CompassTemplate.execute(CompassTemplate.java:134)
[java] at org.compass.core.CompassTemplate.execute(CompassTemplate.java:117)
[java] at org.compass.core.impl.DefaultCompass$TransactionalSearchEngineIndexManager.verifyIndex(DefaultCompass.java:291)
[java] at org.compass.core.lucene.engine.manager.ScheduledLuceneSearchEngineIndexManager.verifyIndex(ScheduledLuceneSearchEngineIndexManager.java:98)
[java] at org.compass.core.impl.DefaultCompass.<init>(DefaultCompass.java:147)
[java] at org.compass.core.impl.DefaultCompass.<init>(DefaultCompass.java:102)
[java] at org.compass.core.impl.DefaultCompass.<init>(DefaultCompass.java:95)
[java] at org.compass.core.config.CompassConfiguration.buildCompass(CompassConfiguration.java:191)
[java] at com.soasta.repository.persistence.compass.CompassUtil.<clinit>(CompassUtil.java:51)
[java] ... 3 more
[java] Caused by: java.io.IOException: Lock obtain timed out: PhantomReadLock[write.lock/index_folderitem]
[java] at org.apache.lucene.store.Lock.obtain(Lock.java:56)
[java] at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:254)
[java] at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:244)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore$1.doWithStore(AbstractLuceneSearchEngineStore.java:210)
[java] at org.compass.core.lucene.engine.store.LuceneStoreTemplate.execute(LuceneStoreTemplate.java:43)
[java] ... 18 more

The real reason for the error, though was that DBCP was throwing an exception ("MaxOpenPreparedStatements limit reached"). This exception is "eaten" in PhantomReadLock.java, line 71. It would be nice if this error were propagated to the end-user.

 All   Comments   Change History      Sort Order: Ascending order - Click to sort in descending order
[ Permlink | « Hide ]
Matt Solnit added a comment - 04/Dec/06 05:35 PM
The attached patch seems to work. The resulting stack trace is:

Caused by: org.compass.core.engine.SearchEngineException: Failed while executing a lucene directory based operation; nested exception is org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [select deleted_ from index_folderitem where name_ = ?]; nested exception is org.apache.commons.dbcp.SQLNestedException: MaxOpenPreparedStatements limit reached
[java] at org.compass.core.lucene.engine.store.LuceneStoreTemplate.execute(LuceneStoreTemplate.java:63)
[java] at org.compass.core.lucene.engine.store.LuceneStoreTemplate.executeForSubIndex(LuceneStoreTemplate.java:37)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore.createIndex(AbstractLuceneSearchEngineStore.java:208)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore.verifyIndex(AbstractLuceneSearchEngineStore.java:240)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore.verifyIndex(AbstractLuceneSearchEngineStore.java:255)
[java] at org.compass.core.lucene.engine.manager.DefaultLuceneSearchEngineIndexManager.verifyIndex(DefaultLuceneSearchEngineIndexManager.java:89)
[java] at org.compass.core.impl.DefaultCompass$TransactionalSearchEngineIndexManager$2.doInCompass(DefaultCompass.java:293)
[java] at org.compass.core.CompassTemplate.execute(CompassTemplate.java:134)
[java] at org.compass.core.CompassTemplate.execute(CompassTemplate.java:117)
[java] at org.compass.core.impl.DefaultCompass$TransactionalSearchEngineIndexManager.verifyIndex(DefaultCompass.java:291)
[java] at org.compass.core.lucene.engine.manager.ScheduledLuceneSearchEngineIndexManager.verifyIndex(ScheduledLuceneSearchEngineIndexManager.java:98)
[java] at org.compass.core.impl.DefaultCompass.<init>(DefaultCompass.java:147)
[java] at org.compass.core.impl.DefaultCompass.<init>(DefaultCompass.java:102)
[java] at org.compass.core.impl.DefaultCompass.<init>(DefaultCompass.java:95)
[java] at org.compass.core.config.CompassConfiguration.buildCompass(CompassConfiguration.java:191)
[java] at com.soasta.repository.persistence.compass.CompassUtil.<clinit>(CompassUtil.java:51)
[java] ... 3 more
[java] Caused by: org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [select deleted_ from index_folderitem where name_ = ?]; nested exception is org.apache.commons.dbcp.SQLNestedException: MaxOpenPreparedStatements limit reached
[java] at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeSelect(JdbcTemplate.java:112)
[java] at org.apache.lucene.store.jdbc.handler.AbstractFileEntryHandler.fileExists(AbstractFileEntryHandler.java:59)
[java] at org.apache.lucene.store.jdbc.JdbcDirectory.fileExists(JdbcDirectory.java:322)
[java] at org.apache.lucene.store.jdbc.lock.PhantomReadLock.obtain(PhantomReadLock.java:57)
[java] at org.apache.lucene.store.Lock.obtain(Lock.java:51)
[java] at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:254)
[java] at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:244)
[java] at org.compass.core.lucene.engine.store.AbstractLuceneSearchEngineStore$1.doWithStore(AbstractLuceneSearchEngineStore.java:210)
[java] at org.compass.core.lucene.engine.store.LuceneStoreTemplate.execute(LuceneStoreTemplate.java:43)
[java] ... 18 more
[java] Caused by: org.apache.commons.dbcp.SQLNestedException: MaxOpenPreparedStatements limit reached
[java] at org.apache.commons.dbcp.PoolingConnection.prepareStatement(PoolingConnection.java:89)
[java] at org.apache.commons.dbcp.DelegatingConnection.prepareStatement(DelegatingConnection.java:185)
[java] at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.prepareStatement(PoolingDataSource.java:278)
[java] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[java] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[java] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[java] at java.lang.reflect.Method.invoke(Method.java:585)
[java] at org.apache.lucene.store.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:211)
[java] at $Proxy0.prepareStatement(Unknown Source)
[java] at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeSelect(JdbcTemplate.java:104)
[java] ... 26 more
[java] Caused by: java.util.NoSuchElementException
[java] at org.apache.commons.pool.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:808)
[java] at org.apache.commons.dbcp.PoolingConnection.prepareStatement(PoolingConnection.java:87)
[java] ... 35 more


[ Permlink | « Hide ]
Matt Solnit added a comment - 04/Dec/06 05:38 PM
Sorry, here's that patch again as a diff output.

[ Permlink | « Hide ]
Shay Banon added a comment - 05/Dec/06 02:02 AM
As far as I can see, your does not catch an exception, and throws it. The problem is, the exception might be valid, which means that a lock could not be obtained (and there will usually be an exception in such cases). I have added a trace level logging for the exception, makes sense?

[ Permlink | « Hide ]
Matt Solnit added a comment - 05/Dec/06 11:30 AM
Yeah, I was very uncertain about that . Logging is definitely a big improvement.

[ Permlink | « Hide ]
Shay Banon added a comment - 05/Dec/06 11:38 AM
OK, I will close this issue.


Powered by a free Atlassian JIRA open source license for compass-project.org. Try JIRA - bug tracking software for your team.
Atlassian JIRA the Professional Issue Tracker. (Enterprise Edition, Version: 3.13-#330) - Bug/feature request - Atlassian news - Contact Administrators