Re: How different is AWS-RDS postgres?

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.

On Thu, May 27, 2021 at 2:58 PM Rob Sargent <robjsargent(at)gmail(dot)com> wrote:

> On 5/27/21 3:08 PM, Sam Gendler wrote:
>
> 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.
>
> I almost wish that were true.
>
> 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\
> 0000' and s.probandset_id < '40000000-0000-0000-0000-000000000000' ]; An
> I/O error occurred while sending to the backend.
>
> So this would have been the fourth such insert statement read from that
> staging table.
>
> 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(at)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)
>
>
>
>