itm / testbed-runtime

WISEBED Wireless Sensor Network Testbed Infrastructure Software
https://github.com/itm/testbed-runtime/wiki
15 stars 11 forks source link

JPA throws Exceptions #305

Closed danbim closed 11 years ago

danbim commented 11 years ago
null id in de.uniluebeck.itm.tr.rs.persistence.jpa.entity.SecretReservationKeyInternal entry (don't flush the Session after an exception occurs) org.hibernate.AssertionFailure: null id in de.uniluebeck.itm.tr.rs.persistence.jpa.entity.SecretReservationKeyInternal entry (don't flush the Session after an exception occurs) at org.hibernate.event.internal.DefaultFlushEntityEventListener.checkId(DefaultFlushEntityEventListener.java:79) at org.hibernate.event.internal.DefaultFlushEntityEventListener.getValues(DefaultFlushEntityEventListener.java:194) at org.hibernate.event.internal.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:156) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:228) at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:100) at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:58) at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1205) at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1262) at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:266) at de.uniluebeck.itm.tr.rs.persistence.jpa.RSPersistenceJPA.getReservations(RSPersistenceJPA.java:219) at de.uniluebeck.itm.tr.rs.SingleUrnPrefixRS.getReservations(SingleUrnPrefixRS.java:75) at de.uniluebeck.itm.tr.rs.SingleUrnPrefixRS.checkNodesAvailable(SingleUrnPrefixRS.java:327) at de.uniluebeck.itm.tr.rs.SingleUrnPrefixRS.makeReservation(SingleUrnPrefixRS.java:171) at de.uniluebeck.itm.tr.rs.RSAuthorizationDecorator.makeReservation(RSAuthorizationDecorator.java:133) at de.uniluebeck.itm.tr.iwsn.portal.api.rest.v1.resources.RsResource.makeReservation(RsResource.java:65) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180) at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:198) at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:102) at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58) at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:94) at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:271) at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:238) at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:218) at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:163) at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:137) at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:158) at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:243) at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:163) at javax.servlet.http.HttpServlet.service(HttpServlet.java:595) at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:219) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:648) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1072) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) at org.eclipse.jetty.server.Server.handle(Server.java:365) at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485) at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937) at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:856) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240) at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82) at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628) at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) at java.lang.Thread.run(Thread.java:724)

and

2013-08-11 12:58:48,075 | qtp30209028-43                 | ServletHandler                 | WARN  | /rest/v1.0/devicedb/byMacAddress
java.lang.RuntimeException: org.apache.cxf.interceptor.Fault: org.hibernate.TransactionException: Already have an associated managed connection
    at org.apache.cxf.interceptor.AbstractFaultChainInitiatorObserver.onMessage(AbstractFaultChainInitiatorObserver.java:117)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:331)
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:238)
    at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:218)
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:163)
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:137)
    at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:158)
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:243)
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:168)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:575)
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:219)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:648)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1072)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
    at org.eclipse.jetty.server.Server.handle(Server.java:365)
    at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
    at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:926)
    at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:988)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:635)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
    at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
    at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.cxf.interceptor.Fault: org.hibernate.TransactionException: Already have an associated managed connection
    at org.apache.cxf.service.invoker.AbstractInvoker.createFault(AbstractInvoker.java:162)
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:128)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:198)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:102)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:94)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:271)
    ... 32 more
Caused by: javax.persistence.PersistenceException: org.hibernate.TransactionException: Already have an associated managed connection
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)
    at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1397)
    at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:62)
    at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:62)
    at de.uniluebeck.itm.tr.devicedb.DeviceDBRestResourceImpl.getByMacAddress(DeviceDBRestResourceImpl.java:92)
    at sun.reflect.GeneratedMethodAccessor63.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180)
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
    ... 37 more
Caused by: org.hibernate.TransactionException: Already have an associated managed connection
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:65)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160)
    at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1426)
    at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:59)
    ... 44 more
org.hibernate.TransactionException: JDBC begin transaction failed: 
javax.persistence.PersistenceException: org.hibernate.TransactionException: JDBC begin transaction failed: 
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1310)
    at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1397)
    at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:62)
    at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:62)
    at de.uniluebeck.itm.tr.devicedb.DeviceDBWisemlProvider.get(DeviceDBWisemlProvider.java:29)
    at de.uniluebeck.itm.tr.devicedb.DeviceDBWisemlProvider.get(DeviceDBWisemlProvider.java:14)
    at de.uniluebeck.itm.tr.iwsn.portal.api.rest.v1.resources.ExperimentResource.getNetwork(ExperimentResource.java:89)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180)
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:198)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:102)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:94)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:271)
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:238)
    at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:218)
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:163)
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:137)
    at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:158)
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:243)
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:168)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:575)
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:219)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:648)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1072)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
    at org.eclipse.jetty.server.Server.handle(Server.java:365)
    at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
    at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:926)
    at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:988)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:635)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
    at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
    at java.lang.Thread.run(Thread.java:724)
Caused by: org.hibernate.TransactionException: JDBC begin transaction failed: 
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:76)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160)
    at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1426)
    at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:59)
    ... 47 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 104,396,695 milliseconds ago.  The last packet sent successfully to the server was 104,396,695 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
    at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3871)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2484)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2788)
    at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:5282)
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:72)
    ... 50 more
Caused by: java.net.SocketException: Broken pipe
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
    at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3852)
    ... 55 more

These errors were observed on the staging testbed installation at UZL testbed after longer time of inactivity.

danbim commented 11 years ago

According to this thread on StackOverflow we should never @Inject EntityManager directly but use @Inject Provider<EntityManager> instead. I'll try this...

danbim commented 11 years ago

I carefully debugged and traced the behavior of the guice-persist module, if transactions are started and stopped properly, if EntityManager and UnitOfWork instances are properly opened and closed and everything seems to be working just as it should.

However, until now we always used the default database connection pool of Hibernate. At startup Hibernate prints out a warning that this connection pool is not meant to be used in production. Therefore I'm now trying to configure c3p0 connection pooling for the several persistence units, hoping that this connection pooling mechanism will not lead to stale MySQL connnections which seem to cause the errors. In order to use c3p0 pooling add the following lines to the individual JPA properties files:

# configure connection pooling for production servers
hibernate.connection.provider_class=org.hibernate.connection.C3P0ConnectionProvider
hibernate.c3p0.acquire_increment=1
hibernate.c3p0.idle_test_period=60
hibernate.c3p0.min_size=1
hibernate.c3p0.max_size=10
hibernate.c3p0.max_statements=50
hibernate.c3p0.timeout=10
hibernate.c3p0.acquireRetryAttempts=1
hibernate.c3p0.acquireRetryDelay=250

and tweak the parameters as required. I traced the connection behavior using the MySQLWorkbench tool on my development machine and it seems that everything is working really fine. Also, when I run a load test using siege (e.g., doing 1000 DeviceDB requests with 10 parallel threads) seem to work exactly as configured for c3p0. As soon as the load test is over c3p0 will shut down connections to the DB, keeping only 1 running. The 1 connection that is always also seems to be kept alive as the admin interface shows a maximum "Time" of 10 seconds before it jumps back to 0 so I assume that this connection either is using some keepalive mechanism or is shut down and rebuilt immediately.

danbim commented 11 years ago

Seems this worked :)

master-lincoln commented 11 years ago

C3PO to the rescue!