hi,
I am running into an issue with an installation of LabKey. Several times I have encountered the following error and had to restart Tomcat to fix it.
I have pasted the last error from the logs below. We're running 14.3 on Ubuntu 14.04.1 LTS with PostgreSQL 9.3.
Let me know if you need more information.
Thanks,
bront
… from labkey.log
SELECT * FROM core.containers WHERE Parent IS NULL
org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.handleSqlException(SqlExecutingSelector.java:438)
org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:263)
org.labkey.api.data.BaseSelector.getObject(BaseSelector.java:163)
org.labkey.api.data.BaseSelector.getObject(BaseSelector.java:158)
org.labkey.api.data.ContainerManager.getForPath(ContainerManager.java:870)
ERROR ContextListener 2015-01-12 09:33:04,769 localhost-startStop-2 : Exception during shutdownStarted():
org.springframework.jdbc.UncategorizedSQLException: ExecutingSelector; uncategorized SQLException for SQL []; SQL state [25P02]; error code [0]; ERROR: current transaction is aborted, commands ignored until end of transaction block; nested exception is org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.translate(SQLStateSQLExceptionTranslator.java:124)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.translate(SQLErrorCodeSQLExceptionTranslator.java:322)
at org.labkey.api.data.ExceptionFramework$1.translate(ExceptionFramework.java:37)
at org.labkey.api.data.ExceptionFramework$1.translate(ExceptionFramework.java:31)
at org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.handleSqlException(SqlExecutingSelector.java:443)
at org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:263)
at org.labkey.api.data.BaseSelector.getObject(BaseSelector.java:163)
at org.labkey.api.data.BaseSelector.getObject(BaseSelector.java:158)
at org.labkey.api.data.ContainerManager.getForPath(ContainerManager.java:870)
at org.labkey.api.data.ContainerManager.getForPath(ContainerManager.java:855)
at org.labkey.api.data.ContainerManager.getRoot(ContainerManager.java:909)
at org.labkey.api.data.queryprofiler.QueryProfiler$4.getFormattedPrimaryStatistic(QueryProfiler.java:151)
at org.labkey.api.data.queryprofiler.QueryTracker.exportRow(QueryTracker.java:321)
at org.labkey.api.data.queryprofiler.QueryProfiler$QueryStatTsvWriter.write(QueryProfiler.java:498)
at org.labkey.api.data.TextWriter.write(TextWriter.java:147)
at org.labkey.api.data.queryprofiler.QueryProfiler$QueryProfilerThread.shutdownStarted(QueryProfiler.java:598)
at org.labkey.api.util.ContextListener.contextDestroyed(ContextListener.java:68)
at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:5014)
at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5659)
at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1575)
at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1564)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2198)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1927)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:561)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:405)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:285)
at org.labkey.api.data.dialect.StatementWrapper.executeQuery(StatementWrapper.java:916)
at org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.executeQuery(SqlExecutingSelector.java:374)
at org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.getResultSet(SqlExecutingSelector.java:324)
at org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:249) |
| |
| jeckels responded: |
2015-01-12 09:28 |
Hi Bront,
This error indicates that there's a database connection that got into a bad state, and it's causing an error when the server is shutting down. There's likely one or more other error messages earlier in the log that might point to the root cause. Can you attach the full labkey.log file, or send it directly by email if you'd prefer not to post it publicly?
Thanks,
Josh |
| |
| adam responded: |
2015-01-12 09:30 |
This usually means that a previous SQL query within this same transaction failed, which causes subsequent queries to fail. You'll need to find the first failure in the log to track down the source of the problem.
Adam |
| |
| bront responded: |
2015-01-12 11:03 |
I will forward the labkey.log file, but from what I can see there are hundreds of errors that look like this:
SELECT Path, LastCrawled, NextCrawl
FROM search.CrawlCollections
WHERE NextCrawl < ? AND (LastCrawled IS NULL OR LastCrawled < ?) ORDER BY NextCrawl
LIMIT 100
?[1] Mon Jan 12 09:33:04 EST 2015
?[2] Mon Jan 12 09:03:04 EST 2015
org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.handleSqlException(SqlExecutingSelector.java:438)
org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:263)
org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:109)
org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:156)
org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:140)
ERROR DavCrawler 2015-01-12 09:33:04,471 DavCrawler : Unexpected error
org.springframework.jdbc.UncategorizedSQLException: ExecutingSelector; uncategorized SQLException for SQL []; SQL state [25P02]; error code [0]; ERROR: current transaction is aborted, commands ignored until end of transaction block; nested exception is org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
Many thanks,
bront |
| |
| jeckels responded: |
2015-01-13 09:05 |
Hi Bront,
Is this on a developer machine, or a production/staging/etc server? I'm wondering if the Postgres JDBC driver might be stale. Can you double-check that the copy in $TOMCAT_HOME/lib matches the file size in the distribution (either the .tar.gz or ./external/lib/tomcat/ in SVN)?
Also, can you share the section of labkey.xml in $TOMCAT_HOME/conf/Catalina/localhost for the labkeyDataSource (stripping out server/username/password information, of course). It should be something like this:
<Resource name="jdbc/labkeyDataSource" auth="Container"
type="javax.sql.DataSource"
username="postgres"
password="XXXXXXXXXXXXXXXXX"
driverClassName="org.postgresql.Driver"
url="jdbc:postgresql://localhost:5433/labkey"
maxActive="20"
maxIdle="10"
accessToUnderlyingConnectionAllowed="true"
validationQuery="SELECT 1"
/>
Thanks,
Josh |
| |
| bront responded: |
2015-01-15 14:41 |
Josh,
I checked the postgresql.jar. The file sizes seemed to match, but I loaded the one from release14.3/external/lib/tomcat/ branch anyway. Restarted Tomcat.
Here is our labkey.xml file:
<Resource name="jdbc/labkeyDataSource" auth="Container"
type="javax.sql.DataSource"
username=""
password=""
driverClassName="org.postgresql.Driver"
url="jdbc:postgresql://xxx/labkey?sslmode=require"
maxActive="20"
maxIdle="10" accessToUnderlyingConnectionAllowed="true"/>
Again, thanks for your help.
bront |
| |
| jeckels responded: |
2015-01-16 17:11 |
Hi Bront,
I don't necessarily expect that this will help, but please try adding this to your <Resource>:
validationQuery="SELECT 1"
It will make sure that the connection is still active before handing it out from the pool.
Thanks,
Josh |
| |
| bront responded: |
2015-01-26 08:00 |
Josh,
I implemented that change to the labkey.xml. We're still seeing hundreds of errors like the following. Our sys admin noted that the errors kickoff at 2:00 when the site maintenance tasks are scheduled. We're still investigating, but if you can think of other possible solutions let us know.
Thanks,
bront
ERROR Table 2015-01-26 10:42:03,663 DavCrawler : SQL [15033]
SELECT Path, LastCrawled, NextCrawl
FROM search.CrawlCollections
WHERE NextCrawl < ? AND (LastCrawled IS NULL OR LastCrawled < ?) ORDER BY NextCrawl
LIMIT 100
?[1] Mon Jan 26 10:42:03 EST 2015
?[2] Mon Jan 26 10:12:03 EST 2015
org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.handleSqlException(SqlExecutingSelector.java:438)
org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:263)
org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:109)
org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:156)
org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:140)
ERROR DavCrawler 2015-01-26 10:42:03,663 DavCrawler : Unexpected error
org.springframework.jdbc.UncategorizedSQLException: ExecutingSelector; uncategorized SQLException for SQL []; SQL state [25P02]; error code [0]; ERROR: current transaction is aborted, commands ignored until end of transaction block; nested exception is org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.translate(SQLStateSQLExceptionTranslator.java:124)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.translate(SQLErrorCodeSQLExceptionTranslator.java:322)
at org.labkey.api.data.ExceptionFramework$1.translate(ExceptionFramework.java:37)
at org.labkey.api.data.ExceptionFramework$1.translate(ExceptionFramework.java:31)
at org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.handleSqlException(SqlExecutingSelector.java:443)
at org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:263)
at org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:109)
at org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:156)
at org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:140)
at org.labkey.api.data.SqlExecutingSelector.getResultSet(SqlExecutingSelector.java:135)
at org.labkey.search.model.SavePaths.getPaths(SavePaths.java:308)
at org.labkey.search.model.DavCrawler.findSomeWork(DavCrawler.java:529)
at org.labkey.search.model.DavCrawler$1.run(DavCrawler.java:496)
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2198)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1927)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:561)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:419)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:304)
at org.labkey.api.data.dialect.StatementWrapper.executeQuery(StatementWrapper.java:603)
at org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.executeQuery(SqlExecutingSelector.java:384)
at org.labkey.api.data.SqlExecutingSelector$ExecutingResultSetFactory.getResultSet(SqlExecutingSelector.java:324)
at org.labkey.api.data.BaseSelector.handleResultSet(BaseSelector.java:249) |
| |
| jeckels responded: |
2015-01-29 16:15 |
Hi Bront,
It sounds like one of the maintenance tasks is probably hitting an error and leaving the connection in a bad state. Can you try disabling/reenabling them (I'd recommend a binary search) to figure out which is causing the problem? After you're in this state, you'd probably need to restart Tomcat to clear the bad state as a way to prep for the next night.
Thanks,
Josh |
| |
| Jon (LabKey DevOps) responded: |
2015-02-04 17:06 |
Hi Bront,
Are you still seeing an issue here? Were you able to follow Josh's suggestion?
Regards,
Jon |
| |
| bront responded: |
2015-02-06 06:21 |
Jon,
We have tried disabling the maintenance tasks, and that seemed to help.
But yesterday we ran into a deadlock issue. The logs indicate that the issue still seems to be related to UPDATE search.CrawlCollections Set LastCrawled…
We're looking into it, but no we have not managed to completely isolate the issue.
Thanks,
bront |
| |
| bront responded: |
2015-03-04 06:59 |
hi,
Just wanted to follow-up on this issue. We never could adequately track the source of the problem, so we ended up rebuilding the server from the ground up. We are no longer experiencing this issue.
Thanks for your help and support.
bront |
| |
|
|