That sure looks like something is causing your connection to have a transaction rollback. I haven't worked in Java in far too long, but it seems like your connection pool is under the impression your connection was abandoned so it reclaims it and rollback the transaction, which would explain why you aren't seeing the table when all is said and done - all of the work is being undone at the end.
One possibility, based on the catalina log you provided - if you have either end of the connection set up to automatically close idle connections after a period of time, then you might receive a closed connection from the pool, which will just error out when you attempt to run a query. In which case, you need to set up your connection pool to test a connection before it returns it to the requester. Usually something as simple as "select 2" will be sufficient to determine if the database connection is open. I can just about guarantee that your connection pool has a parameter which allows you to specify a query to execute when a connection is requested.
One possibility, based on the catalina log you provided - if you have either end of the connection set up to automatically close idle connections after a period of time, then you might receive a closed connection from the pool, which will just error out when you attempt to run a query. In which case, you need to set up your connection pool to test a connection before it returns it to the requester. Usually something as simple as "select 2" will be sufficient to determine if the database connection is open. I can just about guarantee that your connection pool has a parameter which allows you to specify a query to execute when a connection is requested.
On Thu, May 27, 2021 at 2:58 PM Rob Sargent <robjsargent@xxxxxxxxx> wrote:
On 5/27/21 3:08 PM, Sam Gendler wrote:
I almost wish that were true.The same JDBC connection that is resulting in lost data? Sounds to me like you aren't connecting to the DB you think you are connecting to.
However, looking at AWS "Performance Insights" is see the sql statements generate by my app begin executed on the server. Not coincidentally this is from the "Top SQL (10)/Load by waits" view. Now that view does NOT, in point of fact, name the database in which the sql is running, but the rest of my environment pretty much rules out silently switching tracks on myself. I have to read from the correct database, using a UUID, to get data to analyze, then save the results of the analysis back. I'm using my wonderful webapp to run this and I've successfully analyzed and stored result for small starting data sets.
I just notice the "Top database" tab on that screen: there is only one and it's the correct one.
I've reproduced the behaviour. I'm pretty convinced it a size thing, but which part of the system is being max'd out is not clear. Not CPU, but that's the only resource the "Performance Insight" mentions (suggesting this UI wasn't designed by a database person).
The loss of the staging table is most spectacular. It filled from a file which has 7.5M records. It's clear in the tomcat logs that is was created and written to, one record read. Then the "top sql" happens:
insert into segment select * from bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where s.probandset_id >= ? and s.probandset_id < ?the "bulk" table is the staging table. The params are filled in with a quasi-uuid which grab roughly 1/16th of the data. In the stack trace on my tomcat server I get
Caused by: org.jooq.exception.DataAccessException: SQL [insert into segment select * from bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where s.probandset_id >= '30000000-0000-0000-0000-00000000\So this would have been the fourth such insert statement read from that staging table.
0000' and s.probandset_id < '40000000-0000-0000-0000-000000000000' ]; An I/O error occurred while sending to the backend.
That table is not deleted by my code. It is renamed after the last insert into segment, by appending "_done" to the name. But that table, by either name, is nowhere to be seen on the server.
For those scoring at home, the trouble in the tomcat log start with
0:02:11.452 [https-jsse-nio-10.0.2.28-15002-exec-7] INFO edu.utah.camplab.jx.PayloadFromMux - bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6": Begin transfer from bulk to segment
27-May-2021 20:02:50.338 FINE [Catalina-utility-2] org.apache.catalina.session.ManagerBase.processExpires Start expire sessions StandardManager at 1622145770338 sessioncount 0
27-May-2021 20:02:50.338 FINE [Catalina-utility-2] org.apache.catalina.session.ManagerBase.processExpires End expire sessions StandardManager processingTime 0 expired sessions: 0
27-May-2021 20:02:50.476 FINE [Catalina-utility-2] org.apache.catalina.session.ManagerBase.processExpires Start expire sessions StandardManager at 1622145770476 sessioncount 1
27-May-2021 20:02:50.476 FINE [Catalina-utility-2] org.apache.catalina.session.ManagerBase.processExpires End expire sessions StandardManager processingTime 0 expired sessions: 0
27-May-2021 20:02:51.847 WARNING [Tomcat JDBC Pool Cleaner[1731185718:1622133381802]] org.apache.tomcat.jdbc.pool.ConnectionPool.abandon Connection has been abandoned PooledConnection[org.postgresql.jdbc.PgCo\
nnection@1622ead9]:java.lang.Exception
at org.apache.tomcat.jdbc.pool.ConnectionPool.getThreadDump(ConnectionPool.java:1163)
at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:816)
at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:660)
at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)
at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:132)
at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:90)
at edu.utah.camplab.servlet.AbstractSGSServlet.getDbConn(AbstractSGSServlet.java:123)
at edu.utah.camplab.servlet.AbstractSGSServlet.getDbConn(AbstractSGSServlet.java:105)
at edu.utah.camplab.servlet.PayloadSaveServlet.doPost(PayloadSaveServlet.java:50)
....
20:02:51.854 [https-jsse-nio-10.0.2.28-15002-exec-7] DEBUG org.jooq.impl.DefaultConnectionProvider - rollback to savepoint
20:02:51.855 [https-jsse-nio-10.0.2.28-15002-exec-7] DEBUG org.jooq.impl.DefaultConnectionProvider - rollback
20:02:51.855 [https-jsse-nio-10.0.2.28-15002-exec-7] DEBUG org.jooq.impl.DefaultConnectionProvider - setting auto commit : true
20:02:51.855 [https-jsse-nio-10.0.2.28-15002-exec-7] ERROR edu.utah.camplab.jx.AbstractPayload - run c9e224ca-85d2-40b4-ad46-327cfb9f0ac6: Exception from db write: SQL [insert into segment select * from bulk.\
"rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where s.probandset_id >= '30000000-0000-0000-0000-000000000000' and s.probandset_id < '40000000-0000-0000-0000-000000000000' ]; An I/O error occurred \
while sending to the backend.: {}
org.jooq.exception.DataAccessException: SQL [insert into segment select * from bulk."rjs_GEV15_01_c9e224ca_85d2_40b4_ad46_327cfb9f0ac6" as s where s.probandset_id >= '30000000-0000-0000-0000-000000000000' an\
d s.probandset_id < '40000000-0000-0000-0000-000000000000' ]; An I/O error occurred while sending to the backend.
at org.jooq_3.14.7.POSTGRES.debug(Unknown Source)
at org.jooq.impl.Tools.translate(Tools.java:2880)
at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:757)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:389)
at edu.utah.camplab.jx.PayloadFromMux.insertAllSegments(PayloadFromMux.java:177)
at edu.utah.camplab.jx.PayloadFromMux.lambda$completeSegmentSave$3(PayloadFromMux.java:165)
at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:615)
at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:612)
at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:543)
at org.jooq.impl.Tools$35$1.block(Tools.java:5203)
at java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3137)
at org.jooq.impl.Tools$35.get(Tools.java:5200)
at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:595)
at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:512)
at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:612)
at edu.utah.camplab.jx.PayloadFromMux.completeSegmentSave(PayloadFromMux.java:164)
at edu.utah.camplab.jx.PayloadFromMux.writedb(PayloadFromMux.java:45)
at edu.utah.camplab.jx.AbstractPayload.lambda$write$0(AbstractPayload.java:77)
at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:615)
...
Suppressed: org.jooq.exception.DataAccessException: Cannot rollback transaction
at org.jooq.impl.DefaultConnectionProvider.rollback(DefaultConnectionProvider.java:142)
at org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:223)
at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:567)
... 45 common frames omitted
Caused by: java.sql.SQLException: Connection has already been closed.
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy4.rollback(Unknown Source)
at org.jooq.impl.DefaultConnectionProvider.rollback(DefaultConnectionProvider.java:139)
... 47 common frames omitted
Suppressed: org.jooq.exception.DataAccessException: Cannot set autoCommit
at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:222)
at org.jooq.impl.DefaultTransactionProvider.brace(DefaultTransactionProvider.java:246)
at org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:229)
at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:567)
... 33 common frames omitted
Caused by: java.sql.SQLException: Connection has already been closed.
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy4.setAutoCommit(Unknown Source)
at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:219)
... 36 common frames omitted
Caused by: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:350)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:153)
at jdk.internal.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
at com.sun.proxy.$Proxy14.execute(Unknown Source)
at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:214)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:458)
at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:375)
... 50 common frames omitted
Caused by: javax.net.ssl.SSLException: Socket closed
at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:127)
at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:369)
at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:312)
at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:307)
at java.base/sun.security.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1680)
at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1054)
at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)
at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
