Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Database connection failed when canceling copy operation #932

Closed
steven-sheehy opened this issue Aug 3, 2020 · 0 comments · Fixed by #935
Closed

Database connection failed when canceling copy operation #932

steven-sheehy opened this issue Aug 3, 2020 · 0 comments · Fixed by #935
Assignees
@Nana-EC
Labels
bug Type: Something isn't working P1 parser Area: File parsing regression
Milestone
Mirror 0.17.0

Comments

@steven-sheehy
Copy link
Contributor

Detailed Description
Importer is failing repeatedly in development when attempting to pgcopy.

Actual Behavior
Steps to reproduce the behavior:

  1. Run importer
  2. Wait a day
  3. Error

Expected Behavior

Environment:

  • Java: OpenJDK 11
  • OS: Ubuntu 18.04
  • Version: 0.16.0-rc1

Additional Context

Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,252 DEBUG [mirror_node connection closer] c.z.h.p.PoolBase mirror_node - Closing connection org.postgresql.jdbc.PgConnection@429812fd: (connection is broken)
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,267 DEBUG [mirror_node connection adder] c.z.h.p.HikariPool mirror_node - Added connection org.postgresql.jdbc.PgConnection@574b39d8
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,267 DEBUG [mirror_node connection adder] c.z.h.p.HikariPool mirror_node - After adding stats (total=10, active=0, idle=10, waiting=0)
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,347 INFO  [scheduling-6] c.h.m.i.u.Utility Loading record format version 2 from record file: 2020-07-31T00_22_04.148113Z.rcd
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,347 INFO  [scheduling-6] c.h.m.i.p.r.RecordFileParser Time to parse record file: 0ms
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,351 INFO  [scheduling-6] c.h.m.i.p.r.e.s.PgCopy Copied 7 rows to transaction table in 3.281 ms
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,353 INFO  [scheduling-6] c.h.m.i.p.r.e.s.PgCopy Copied 21 rows to crypto_transfer table in 2.748 ms
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,356 INFO  [scheduling-6] c.h.m.i.p.r.RecordFileParser Finished parsing 7 transactions from record file /var/lib/hedera-mirror-importer/recordstreams/valid/2020-07-31T00_22_04.148113Z.rcd in 14ms (500/s)
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,356 ERROR [scheduling-6] c.h.m.i.p.r.RecordFileParser Error parsing file /var/lib/hedera-mirror-importer/recordstreams/valid/2020-07-31T00_22_04.148113Z.rcd
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: com.hedera.mirror.importer.exception.ParserException: org.postgresql.util.PSQLException: Database connection failed when canceling copy operation
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.PgCopy.copy(PgCopy.java:99) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.executeBatches(SqlEntityListener.java:218) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.onEnd(SqlEntityListener.java:152) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.onEnd(SqlEntityListener.java:61) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFile(RecordFileParser.java:162) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFiles(RecordFileParser.java:209) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.parse(RecordFileParser.java:264) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at jdk.internal.reflect.GeneratedMethodAccessor95.invoke(Unknown Source) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.lang.Thread.run(Thread.java:834) [?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: Caused by: org.postgresql.util.PSQLException: Database connection failed when canceling copy operation
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:960) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:28) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:188) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.PgCopy.copy(PgCopy.java:95) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         ... 17 more
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: Caused by: java.net.SocketException: Connection or outbound has closed
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:976) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.PGStream.flush(PGStream.java:592) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:937) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:28) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:188) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.PgCopy.copy(PgCopy.java:95) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         ... 17 more
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,356 WARN  [scheduling-6] c.z.h.p.ProxyConnection mirror_node - Connection org.postgresql.jdbc.PgConnection@60d17a17 marked as broken because of SQLSTATE(08006), ErrorCode(0)
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:340) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.jdbc.PgConnection.executeTransactionCommand(PgConnection.java:829) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:872) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:396) ~[HikariCP-3.4.3.jar!/:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java) ~[HikariCP-3.4.3.jar!/:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.onError(SqlEntityListener.java:167) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFiles(RecordFileParser.java:221) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.parse(RecordFileParser.java:264) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at jdk.internal.reflect.GeneratedMethodAccessor95.invoke(Unknown Source) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.lang.Thread.run(Thread.java:834) [?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: Caused by: java.net.SocketException: Connection or outbound has closed
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:976) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.PGStream.flush(PGStream.java:592) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:1459) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:311) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         ... 18 more
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,356 ERROR [scheduling-6] c.h.m.i.p.r.e.s.SqlEntityListener Exception while rolling transaction back
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:340) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.jdbc.PgConnection.executeTransactionCommand(PgConnection.java:829) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:872) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:396) ~[HikariCP-3.4.3.jar!/:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java) ~[HikariCP-3.4.3.jar!/:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.onError(SqlEntityListener.java:167) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFiles(RecordFileParser.java:221) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.parse(RecordFileParser.java:264) ~[classes!/:0.16.0-rc1]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at jdk.internal.reflect.GeneratedMethodAccessor95.invoke(Unknown Source) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.lang.Thread.run(Thread.java:834) [?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: Caused by: java.net.SocketException: Connection or outbound has closed
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:976) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142) ~[?:?]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.PGStream.flush(PGStream.java:592) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:1459) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:311) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 31 22:28:08 mirrornode-dev-1 java[25408]:         ... 18 more
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,356 DEBUG [mirror_node connection closer] c.z.h.p.PoolBase mirror_node - Closing connection org.postgresql.jdbc.PgConnection@60d17a17: (connection is broken)
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,371 DEBUG [mirror_node connection adder] c.z.h.p.HikariPool mirror_node - Added connection org.postgresql.jdbc.PgConnection@7eca1f2c
Jul 31 22:28:08 mirrornode-dev-1 java[25408]: 2020-07-31 22:28:08,371 DEBUG [mirror_node connection adder] c.z.h.p.HikariPool mirror_node - After adding stats (total=10, active=0, idle=10, waiting=0)
@steven-sheehy steven-sheehy added bug Type: Something isn't working P1 regression parser Area: File parsing labels Aug 3, 2020
@Nana-EC Nana-EC self-assigned this Aug 4, 2020
@Nana-EC Nana-EC mentioned this issue Aug 6, 2020
Merged
2 tasks
@Nana-EC Nana-EC mentioned this issue Aug 7, 2020
Merged
2 tasks
@steven-sheehy steven-sheehy added this to the Mirror 0.17.0 milestone Aug 7, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Nana-EC Nana-EC

Labels
bug Type: Something isn't working P1 parser Area: File parsing regression
Projects
None yet
Milestone
Mirror 0.17.0
2 participants
@steven-sheehy @Nana-EC