I recently upgraded from 10.3.2.1 to 10.5.1.1 and immediately started to get
failures in my application.
I am using Derby in combination with Hibernate and Bitronix JTA, but because
I when I rollback to 10.3.2.1 the error goes away, I am assuming the problem
is within Derby. This error is reproducible every time, but creating a
simple testcase from my server may be difficult. Here is the log4j log
containing the failure flow. It includes logging by Bitronix and Hibernate
as well.
09-07-29 20:28:48,875 [SessionImpl ]
[Jetty-5 ] DEBUG - opened session at timestamp:
12488669288
09-07-29 20:28:48,875 [BitronixTransaction ]
[Jetty-5 ] DEBUG - registering synchronization
org.hibernate.context.jtasessioncontext$cleanupsy...@27a078
09-07-29 20:28:48,875 [AbstractBatcher ]
[Jetty-5 ] DEBUG - about to open PreparedStatement (open
PreparedStatements: 0, globally: 0)
09-07-29 20:28:48,875 [ConnectionManager ]
[Jetty-5 ] DEBUG - opening JDBC connection
09-07-29 20:28:48,875 [PoolingDataSource ]
[Jetty-5 ] DEBUG - acquiring connection from a
PoolingDataSource containing an XAPool of resource ziptie-ds with 20
connection(s) (19 still available)
09-07-29 20:28:48,875 [XAPool ]
[Jetty-5 ] DEBUG - trying to recycle a NOT_ACCESSIBLE
connection of an XAPool of resource ziptie-ds with 20 connection(s) (19
still available)
09-07-29 20:28:48,875 [XAPool ]
[Jetty-5 ] DEBUG - current transaction GTRID is
[6E65746C642D3100000122C64508DB000000D5]
09-07-29 20:28:48,875 [XAPool ]
[Jetty-5 ] DEBUG - no NOT_ACCESSIBLE connection enlisted
in this transaction
09-07-29 20:28:48,875 [XAPool ]
[Jetty-5 ] DEBUG - getting a IN_POOL connection from an
XAPool of resource ziptie-ds with 20 connection(s) (19 still available)
09-07-29 20:28:48,875 [XAPool ]
[Jetty-5 ] DEBUG - waiting for IN_POOL connections count
to be > 0, currently is 19
09-07-29 20:28:48,875 [XAPool ]
[Jetty-5 ] DEBUG - found IN_POOL connection a
JdbcPooledConnection from datasource ziptie-ds in state IN_POOL wrapping
org.apache.derby.client.clientxaconnect...@b2ad57 from an XAPool of resource
ziptie-ds with 20 connection(s) (19 still available)
09-07-29 20:28:48,890 [JdbcPooledConnection ]
[Jetty-5 ] DEBUG - getting connection handle from a
JdbcPooledConnection from datasource ziptie-ds in state IN_POOL wrapping
org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [AbstractXAStatefulHolder ]
[Jetty-5 ] DEBUG - notifying 2
stateChangeEventListener(s) about state changing from IN_POOL to ACCESSIBLE
in a JdbcPooledConnection from datasource ziptie-ds in state IN_POOL
wrapping org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [AbstractXAStatefulHolder ]
[Jetty-5 ] DEBUG - state changing from IN_POOL to
ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state
IN_POOL wrapping org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [AbstractXAStatefulHolder ]
[Jetty-5 ] DEBUG - notifying 2
stateChangeEventListener(s) about state changed from IN_POOL to ACCESSIBLE
in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE
wrapping org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [JdbcPooledConnection ]
[Jetty-5 ] DEBUG - connection
org.apache.derby.client.clientxaconnect...@b2ad57 was in state IN_POOL,
testing it
09-07-29 20:28:48,890 [JdbcPooledConnection ]
[Jetty-5 ] DEBUG - testing with query 'VALUES 1'
connection of a JdbcPooledConnection from datasource ziptie-ds in state
ACCESSIBLE wrapping org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [JdbcPooledConnection ]
[Jetty-5 ] DEBUG - successfully tested connection of a
JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping
org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [JdbcPooledConnection ]
[Jetty-5 ] DEBUG - got connection handle from a
JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping
org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [PoolingDataSource ]
[Jetty-5 ] DEBUG - acquired connection from a
PoolingDataSource containing an XAPool of resource ziptie-ds with 20
connection(s) (18 still available)
09-07-29 20:28:48,890 [SQL ]
[Jetty-5 ] DEBUG - select this_.id as y0_,
this_.execution_id as y1_, this_.device_id as y2_, this_.error as y3_,
this_.grid_data as y4_, this_.start_time as y5_, this_.end_time as y6_ from
tool_details this_ where this_.execution_id=?
09-07-29 20:28:48,890 [TransactionContextHelper ]
[Jetty-5 ] DEBUG - enlisting a JdbcPooledConnection from
datasource ziptie-ds in state ACCESSIBLE wrapping
org.apache.derby.client.clientxaconnect...@b2ad57 into a Bitronix
Transaction with GTRID [6E65746C642D3100000122C64508DB000000D5],
status=ACTIVE, 0 resource(s) enlisted (started Wed Jul 29 11:28:48 GMT+00:00
2009)
09-07-29 20:28:48,890 [TransactionContextHelper ]
[Jetty-5 ] DEBUG - enlisting resource an
XAResourceHolderState with uniqueName=ziptie-ds
xaresource=org.apache.derby.client.net.netxaresou...@2f1989 with XID null
into a Bitronix Transaction with GTRID
[6E65746C642D3100000122C64508DB000000D5], status=ACTIVE, 0 resource(s)
enlisted (started Wed Jul 29 11:28:48 GMT+00:00 2009)
09-07-29 20:28:48,890 [AbstractXAResourceHolder ]
[Jetty-5 ] DEBUG - setting default XAResourceHolderState
[an XAResourceHolderState with uniqueName=ziptie-ds
xaresource=org.apache.derby.client.net.netxaresou...@2f1989 with XID null]
on a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE
wrapping org.apache.derby.client.clientxaconnect...@b2ad57
09-07-29 20:28:48,890 [AbstractXAResourceHolder ]
[Jetty-5 ] DEBUG - XAResourceHolderState previously
unknown, adding it to the list
09-07-29 20:28:48,890 [ResourceRegistrar ]
[Jetty-5 ] DEBUG - XAResource
org.apache.derby.client.net.netxaresou...@2f1989 belongs to a
JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping
org.apache.derby.client.clientxaconnect...@b2ad57 that itself belongs to a
PoolingDataSource containing an XAPool of resource ziptie-ds with 20
connection(s) (18 still available)
09-07-29 20:28:48,890 [XAResourceManager ]
[Jetty-5 ] DEBUG - creating new branch with a Bitronix
XID [6E65746C642D3100000122C64508DB000000D5 :
6E65746C642D3100000122C64508FA000000D7]
09-07-29 20:28:48,890 [XAResourceHolderState ]
[Jetty-5 ] DEBUG - assigning <a Bitronix XID
[6E65746C642D3100000122C64508DB000000D5 :
6E65746C642D3100000122C64508FA000000D7]> to <an XAResourceHolderState with
uniqueName=ziptie-ds
xaresource=org.apache.derby.client.net.netxaresou...@2f1989 with XID null>
09-07-29 20:28:48,890 [XAResourceHolderState ]
[Jetty-5 ] DEBUG - starting an XAResourceHolderState
with uniqueName=ziptie-ds
xaresource=org.apache.derby.client.net.netxaresou...@2f1989 with XID a
Bitronix XID [6E65746C642D3100000122C64508DB000000D5 :
6E65746C642D3100000122C64508FA000000D7]
09-07-29 20:28:48,906 [XAResourceManager ]
[Jetty-5 ] DEBUG - started an XAResourceHolderState with
uniqueName=ziptie-ds
xaresource=org.apache.derby.client.net.netxaresou...@2f1989 (started) with
XID a Bitronix XID [6E65746C642D3100000122C64508DB000000D5 :
6E65746C642D3100000122C64508FA000000D7] with NOFLAGS
09-07-29 20:28:48,953 [JDBCExceptionReporter ]
[Jetty-5 ] DEBUG - could not execute query [select
this_.id as y0_, this_.execution_id as y1_, this_.device_id as y2_,
this_.error as y3_, this_.grid_data as y4_, this_.start_time as y5_,
this_.end_time as y6_ from tool_details this_ where this_.execution_id=?]
java.sql.SQLException: Network protocol exception: DSS chained with same id
at end of same id chain parse. The connection has been terminated.
at
org.apache.derby.client.am.SQLExceptionFactory.getSQLException(Unknown
Source)
at org.apache.derby.client.am.SqlException.getSQLException(Unknown
Source)
at org.apache.derby.client.am.Connection.prepareStatement(Unknown
Source)
at org.apache.derby.client.am.LogicalConnection.prepareStatement(Unknown
Source)
at
bitronix.tm.resource.jdbc.JdbcConnectionHandle.prepareStatement(JdbcConnectionHandle.java:213)
at
org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
at
org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
at
org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1577)
at org.hibernate.loader.Loader.doQuery(Loader.java:696)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
at org.hibernate.loader.Loader.doList(Loader.java:2232)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2129)
at org.hibernate.loader.Loader.list(Loader.java:2124)
at
org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:118)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1597)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
at
org.ziptie.provider.tools.PluginProvider.getExecutionDetails(PluginProvider.java:77)
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:585)
at
org.ziptie.server.security.SecurityHandler.invoke(SecurityHandler.java:106)
at $Proxy56.getExecutionDetails(Unknown Source)
at
org.ziptie.provider.tools.PluginProviderDelegate.getExecutionDetails(PluginProviderDelegate.java:25)
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:585)
at
com.sun.xml.ws.api.server.InstanceResolver$1.invoke(InstanceResolver.java:246)
at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:146)
at
com.sun.xml.ws.server.sei.EndpointMethodHandler.invoke(EndpointMethodHandler.java:257)
at
com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:93)
at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:595)
at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:554)
at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:539)
at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:436)
at
com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:243)
at
com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:444)
at
com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:244)
at
com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:135)
at
com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServletDelegate.java:129)
at
com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServletDelegate.java:160)
at org.ziptie.zap.metro.ZwsServlet.doPost(ZwsServlet.java:263)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
at
org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
at
org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1097)
at
org.ziptie.server.security.ZSecurityFilter.doFilter(ZSecurityFilter.java:62)
at
org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1088)
at
org.ziptie.zap.metro.ZThreadContextFilter.doFilter(ZThreadContextFilter.java:34)
at
org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1088)
at
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
at
org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
at
org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:729)
at org.ziptie.zap.web.internal.ZContext.handle(ZContext.java:133)
at
org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
at
org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:729)
at
org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:206)
at
org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
at
org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
at org.mortbay.jetty.Server.handle(Server.java:324)
at
org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:505)
at
org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:843)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:647)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
at
org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:228)
at
org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:635)
at
org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:450)
Caused by: org.apache.derby.client.am.DisconnectException: Network protocol
exception: DSS chained with same id at end of same id chain parse. The
connection has been terminated.
at org.apache.derby.client.net.Reply.endOfSameIdChainData(Unknown
Source)
at
org.apache.derby.client.net.NetStatementReply.readPrepareDescribeOutput(Unknown
Source)
at
org.apache.derby.client.net.StatementReply.readPrepareDescribeOutput(Unknown
Source)
at
org.apache.derby.client.net.NetStatement.readPrepareDescribeOutput_(Unknown
Source)
at
org.apache.derby.client.am.Statement.readPrepareDescribeOutput(Unknown
Source)
at
org.apache.derby.client.am.PreparedStatement.readPrepareDescribeInputOutput(Unknown
Source)
at
org.apache.derby.client.am.PreparedStatement.flowPrepareDescribeInputOutput(Unknown
Source)
at org.apache.derby.client.am.PreparedStatement.prepare(Unknown Source)
at org.apache.derby.client.am.Connection.prepareStatementX(Unknown
Source)
... 68 more
09-07-29 20:28:48,968 [JDBCExceptionReporter ]
[Jetty-5 ] WARN - SQL Error: 40000, SQLState: 58009
09-07-29 20:28:48,968 [JDBCExceptionReporter ]
[Jetty-5 ] ERROR - Network protocol exception: DSS
chained with same id at end of same id chain parse. The connection has been
terminated.
09-07-29 20:28:48,968 [JDBCExceptionReporter ]
[Jetty-5 ] WARN - SQL Error: -1, SQLState: XCL30
09-07-29 20:28:48,968 [JDBCExceptionReporter ]
[Jetty-5 ] ERROR - DERBY SQL error: SQLCODE: -1,
SQLSTATE: XCL30, SQLERRMC:
java.sql.StringXCL30.SXJ001:java.io.EOFExceptionStream has already been
read and end-of-file reached and cannot be re-used.XJ001.U
09-07-29 20:28:48,968 [JDBCExceptionReporter ]
[Jetty-5 ] WARN - SQL Error: 99999, SQLState: XJ001
09-07-29 20:28:48,968 [JDBCExceptionReporter ]
[Jetty-5 ] ERROR - DERBY SQL error: SQLCODE: 0,
SQLSTATE: XJ001, SQLERRMC: java.io.EOFExceptionStream has already been read
and end-of-file reached and cannot be re-used.XJ001.U
The query (hibernate) is this:
select this_.id as y0_, this_.execution_id as y1_, this_.device_id as y2_,
this_.error as y3_,
this_.grid_data as y4_, this_.start_time as y5_, this_.end_time as
y6_
from tool_details this_
where this_.execution_id=?
The table schema, if it matters, is:
CREATE TABLE tool_details (
id INTEGER NOT NULL,
execution_id INTEGER NOT NULL,
device_id INTEGER,
start_time TIMESTAMP NOT NULL,
end_time TIMESTAMP NOT NULL,
error VARCHAR(32672),
grid_data CLOB,
details CLOB
)
Any ideas? Should I just open a bug?
-Brett
