[Dspace-tech] I/O error occured while sending to the backend.

[John Preston]

I'm trying to get rid of the following annoying messages in the tomcat catalina.out log file. I'm running 1.5.1 on Fedora Core 9 with postgresql-8.3.3-2.fc9.i386, but I've been getting these messages even with 1.4.2. I got rid of them under 1.4 by replacing the apache database connection pooling library with another one. However since I upgraded to 1.5 I decided not to try and go too deep in customising, and these messages can't be a good sign. I'm figuring that they must have an impact on database response and they can occur quite frequently (like per request). Can anyone say whether there are any postgresql parameters, or apache pooling library parameters that I could change.

org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:214)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.executeTransactionCommand(AbstractJdbc2Connection.java:621)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.rollback(AbstractJdbc2Connection.java:658)
        at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:328)
        at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:328)
        at org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.rollback(PoolingDriver.java:377)
        at org.dspace.core.Context.abort(Context.java:356)
        at org.dspace.core.Context.finalize(Context.java:499)
        at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
        at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
        at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)
Caused by: java.io.IOException: Stream closed
        at sun.nio.cs.StreamEncoder.ensureOpen(StreamEncoder.java:26)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:121)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
        at org.postgresql.core.PGStream.flush(PGStream.java:531)
        at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:672)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:187)
        ... 11 more
java.sql.SQLException: Already closed.
        at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:84)
        at org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.close(PoolingDriver.java:269)
        at org.dspace.storage.rdbms.DatabaseManager.freeConnection(DatabaseManager.java:566)
        at org.dspace.core.Context.abort(Context.java:365)
        at org.dspace.core.Context.finalize(Context.java:499)
        at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
        at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
        at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)
dspace: System startup complete.

John

[John Preston]

I have been trying to get rid of an error that keeps dumping the following messages in my Tomcat server logs for sometime now. I posted it on this list but no one has responded, which I take to mean that this probably is not a problem for many.

In digging I have located what I think is the culprit. In the Context.java abort method, the connection is rolled back and freed without checking if it is already closed.

        try
        {
            connection.rollback();
        }
        catch (SQLException se)
        {
            log.error(se.getMessage());
            se.printStackTrace();
        }
        finally
        {
            DatabaseManager.freeConnection(connection);
            connection = null;
            events = null;
        }

If I change the code so that I first check whether the connection is closed, then I eliminate the errors.

        try
        {
            if (!connection.isClosed())
              connection.rollback();
        }
        catch (SQLException se)
        {
            log.error(se.getMessage());
            se.printStackTrace();
        }
        finally
        {
            try
            {
                if (!connection.isClosed())
                  DatabaseManager.freeConnection(connection);
            }
            catch (Exception ex)
            {
                ex.printStackTrace();
            }
            connection = null;
            events = null;
        }


I don't know whether the system performance is improved but I can't imagine that it can be a good thing to have exceptions thrown regularly. At the least my Tomcat server log is now more readable.

John

[Flavio Botelho]

Hello John and all,

We just had the same problem in our *production* site during our
change to Dspace 1.5 this weekend. These problems would appear and in
about an hour or so invalidate all Pool connections.

For the time we rolled back the Dspace version and we have been able
to reproduce the bug (wget -r -l 2 at the front page) in a test
environment. It seems to be some kind of race condition as it doesn't
appear to happen always in the same URLs. (It always occurs around
some of the browses, although that maybe just a coincidence). And it's
strange in our case as usually these Exceptions are thrown in
multiples (in the production they were coming at around 12, in the
tests they are coming in 6).

Anyways, why is Dspace trying to rollback in a already closed connection?
Maybe you are just further hiding the errors with that?

Will look more into it this week.

Kudos,
Flavio Botelho
Software Architect / Superior Court of Justice - Brazil

> -------------------------------------------------------------------------
> This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
> Build the coolest Linux based applications with Moblin SDK & win great
> prizes
> Grand prize is a trip for two to an Open Source event anywhere in the world
> http://moblin-contest.org/redirect.php?banner_id=100&url=/
> _______________________________________________
> DSpace-tech mailing list
> DSpac...@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/dspace-tech
>
>

[Flavio Botelho]

Hello John and all,

Tracking down the problem has been very hard and i didn't nail it
completely, but changing LDAPHierarchicalAuthentication's loginPageURL
method to return null did make the problem disappear.

That makes me think the problem is either in LDAPServlet, or in the
page done to choose between the login methods. (It seems like some
kind of race condition OR somewhere along someone is discarding some
important exception, and only later on some errors appear in the
connection pool). If it is a race condition this change may close one
way of it happening, but maybe there are other ways.

Dear John,
do you have any Stackable Authentication Mechanism configured?
Particularly LDAP? More particulary LDAPHierarchical?

Thanks,

Flavio Botelho
Software Architect / Superior Court of Justice - Brazil