db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Brett Wooldridge <brett.wooldri...@gmail.com>
Subject Derby 10.5.1.1 regression
Date Thu, 30 Jul 2009 04:20:56 GMT
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$CleanupSynch@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.ClientXAConnection@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.ClientXAConnection@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.ClientXAConnection@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.ClientXAConnection@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.ClientXAConnection@b2ad57
09-07-29 20:28:48,890 [JdbcPooledConnection     ]
[Jetty-5                     ] DEBUG - connection
org.apache.derby.client.ClientXAConnection@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.ClientXAConnection@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.ClientXAConnection@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.ClientXAConnection@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.ClientXAConnection@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.NetXAResource@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.NetXAResource@2f1989 with XID null]
on a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE
wrapping org.apache.derby.client.ClientXAConnection@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.NetXAResource@2f1989 belongs to a
JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping
org.apache.derby.client.ClientXAConnection@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.NetXAResource@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.NetXAResource@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.NetXAResource@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

Mime
View raw message