Duplicate key violation error after importer restart

[steven-sheehy]

Detailed Description
Importer can sometimes not shutdown cleanly while processing a record file and leave the database with partial data from that file. This occurred in testnet yesterday. In this case it finished processing the data from the file but did not add a record file entry or update application status before shutting down. We should also investigate if this can occur in other scenarios like for stopping during multi-batch files.

Actual Behavior
Steps to reproduce the behavior:

1. Shutdown importer midway through a large file
2. Start importer
3. Importer errors with duplicate key value violates unique constraint

Expected Behavior
The record file processing is atomic.

Environment:

• Java: OpenJDK 11
• OS: Ubuntu 18.04
• Version: 0.15.3

Additional Context

Jul 21 16:13:32 mirrornode-stable-testnet-primary-parser-1 java[1598]:         ,L8@@@@@@@@@@@@@@@@@@0C:                                          Mirror Importer  (v0.15.2)
Jul 21 16:13:32 mirrornode-stable-testnet-primary-parser-1 java[1598]:            ':if0@@@@@@@0fi:'
Jul 21 16:13:32 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:32,394 INFO  [main ] c.h.m.i.MirrorImporterApplication No active profile set, falling back to default profiles: default
Jul 21 16:13:36 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:36,961 INFO  [main ] c.h.m.i.c.MetricsConfiguration Collecting table metrics: [account_balance_sets, account_balances, crypto_transfer, flyway_schema_history, non_fee_transfer, t_application_status, t_contract_result, t_entities, t_entity_types, t_file_data, t_livehashes, t_record_files, t_transaction_results, t_transaction_types, topic_message, transaction]
Jul 21 16:13:37 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:37,377 INFO  [main ] o.f.c.i.c.DbMigrate Current version of schema "public": 1.26.2
Jul 21 16:13:37 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:37,381 INFO  [main ] o.f.c.i.c.DbMigrate Schema "public" is up to date. No migration necessary.
Jul 21 16:13:39 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:39,571 INFO  [main ] c.h.m.i.c.MirrorImporterConfiguration Configured to download from GCP with bucket name 'hedera-stable-testnet-streams'
Jul 21 16:13:39 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:39,825 INFO  [main ] c.h.m.i.c.MirrorImporterConfiguration Setting up S3 async client using provided access/secret key
Jul 21 16:13:40 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:40,997 INFO  [main ] c.h.m.i.a.NetworkAddressBook Restoring existing address book /var/lib/hedera-mirror-importer/addressbook.bin
Jul 21 16:13:41 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:41,000 INFO  [main ] c.h.m.i.a.NetworkAddressBook Saved 3434B partial address book update to /var/lib/hedera-mirror-importer/addressbook.bin.tmp
Jul 21 16:13:41 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:41,069 INFO  [main ] c.h.m.i.a.NetworkAddressBook New address book with 4 addresses successfully parsed and saved to /var/lib/hedera-mirror-importer/addressbook.bin
Jul 21 16:13:43 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:43,705 INFO  [scheduling-3] c.h.m.i.u.Utility Loading record format version 2 from record file: 2020-07-21T16_01_12.618989Z.rcd
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:44,164 INFO  [main ] c.h.m.i.MirrorImporterApplication Started MirrorImporterApplication in 13.972 seconds (JVM running for 15.819)
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:44,174 ERROR [scheduling-3] c.h.m.i.p.r.e.s.SqlEntityListener Error committing sql insert batch
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]: java.sql.BatchUpdateException: Batch entry 0 INSERT INTO transaction (node_account_id, memo, valid_start_ns, type, payer_account_id, result, consensus_ns, entity_id, charged_tx_fee, initial_balance, valid_duration_seconds, max_fee, transaction_hash, transaction_bytes) VALUES (6, ?, 1595347261885000000, 27, 24105, 22, 1595347272618989000, 47536, 273693, 0, 120, 100000000, ?, NULL),(6, ?, 1595347261912000000, 27, 24105, 22, 1595347272618989001, 47536, 281679, 0, 120, 100000000, ?, NULL),(6, ?, 1595347261916000000, 27, 24105, 22, 1595347272618989002, 47536, 281556, 0, 120, 100000000, ?, NULL),(6, ?, 1595347261924000000, 27, 24105, 22, 1595347272618989003, 47536, 274124, 0, 120, 100000000, ?, NULL),(6, ?, 1595347261956000000, 27, 24105, 22, 1595347272618989004, 47536, 289357, 0, 120, 100000000, ?, NULL),(6, ?, 1595347261992000000, 27, 24105, 22, 1595347272618989005, 47536, 274063, 0, 120, 100000000, ?, NULL),(6, ?, 1595347262004000000, 27, 24105, 22, 1595347272618989006, 47536, 305020, 0, 120, 100000000, ?, NULL),(6, ?, 1595347262028000000, 27, 24105, 22, 1595347272618989007, 47536, 281249, 0, 120, 100000000, ?, NULL),(6, ?, 1595347262058000000, 27, 24105, 22, 1595347272618989008, 47536, 348264, 0, 120, 100000000, ?, NULL),(5, ?, 1595347261877000000, 27, 24105, 22, 1595347272704687000, 47536, 274370, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262063000000, 27, 24105, 22, 1595347272704687001, 47536, 541016, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262093000000, 27, 24105, 22, 1595347272704687002, 47536, 282355, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262131000000, 27, 24105, 22, 1595347272704687003, 47536, 282355, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262143000000, 27, 24105, 22, 1595347272704687004, 47536, 273571, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262163000000, 27, 24105, 22, 1595347272704687005, 47536, 287883, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262171000000, 27, 24105, 22, 1595347272704687006, 47536, 287883, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262187000000, 27, 24105, 22, 1595347272704687007, 47536, 278362, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262208000000, 27, 24105, 22, 1595347272704687008, 47536, 282232, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262212000000, 27, 24105, 22, 1595347272704687009, 47536, 287883, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262216000000, 27, 24105, 22, 1595347272704687010, 47536, 273816, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262221000000, 27, 24105, 22, 1595347272704687011, 47536, 341077, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262229000000, 27, 24105, 22, 1595347272704687012, 47536, 341016, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262238000000, 27, 24105, 22, 1595347272704687013, 47536, 273939, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262246000000, 27, 24105, 22, 1595347272704687014, 47536, 287944, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262285000000, 27, 24105, 22, 1595347272704687015, 47536, 329222, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262315000000, 27, 24105, 22, 1595347272704687016, 47536, 273878, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262323000000, 27, 24105, 22, 1595347272704687017, 47536, 278362, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262340000000, 27, 24105, 22, 1595347272704687018, 47536, 282294, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262348000000, 27, 24105, 22, 1595347272704687019, 47536, 274001, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262362000000, 27, 24105, 22, 1595347272704687020, 47536, 281310, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262366000000, 27, 24105, 22, 1595347272704687021, 47536, 282294, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262383000000, 27, 24105, 22, 1595347272704687022, 47536, 282355, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262387000000, 27, 24105, 22, 1595347272704687023, 47536, 274063, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262409000000, 27, 24105, 22, 1595347272704687024, 47536, 282416, 0, 120, 100000000, ?, NULL),(5, ?, 1595347262405000000, 27, 24105, 22, 1595347272704687025, 47536, 282355, 0, 120, 100000000, ?, NULL),(4, ?, 1595347261890000000, 27, 24105, 22, 1595347272704687027, 47536, 273632, 0, 120, 100000000, ?, NULL),(4, ?, 1595347261920000000, 27, 24105, 22, 1595347272704687028, 47536, 281617, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262009000000, 27, 24105, 22, 1595347272704687029, 47536, 273939, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262017000000, 27, 24105, 22, 1595347272704687030, 47536, 273878, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262013000000, 27, 24105, 22, 1595347272704687031, 47536, 273939, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262020000000, 27, 24105, 22, 1595347272704687032, 47536, 273939, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262024000000, 27, 24105, 22, 1595347272704687033, 47536, 281433, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262033000000, 27, 24105, 22, 1595347272704687034, 47536, 281310, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262037000000, 27, 24105, 22, 1595347272704687035, 47536, 281494, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262054000000, 27, 24105, 22, 1595347272704687036, 47536, 309013, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262118000000, 27, 24105, 22, 1595347272704687037, 47536, 282294, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262122000000, 27, 24105, 22, 1595347272704687038, 47536, 282294, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262127000000, 27, 24105, 22, 1595347272704687039, 47536, 282294, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262135000000, 27, 24105, 22, 1595347272704687040, 47536, 316876, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262147000000, 27, 24105, 22, 1595347272704687041, 47536, 281433, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262159000000, 27, 24105, 22, 1595347272704687042, 47536, 274124, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262167000000, 27, 24105, 22, 1595347272704687043, 47536, 282416, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262179000000, 27, 24105, 22, 1595347272704687044, 47536, 287944, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262196000000, 27, 24105, 22, 1595347272704687045, 47536, 329222, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262242000000, 27, 24105, 22, 1595347272704687046, 47536, 287883, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262272000000, 27, 24105, 22, 1595347272704687047, 47536, 282416, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262293000000, 27, 24105, 22, 1595347272704687048, 47536, 341016, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262297000000, 27, 24105, 22, 1595347272704687049, 47536, 273878, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262311000000, 27, 24105, 22, 1595347272704687050, 47536, 287944, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262336000000, 27, 24105, 22, 1595347272704687051, 47536, 302134, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262375000000, 27, 24105, 22, 1595347272704687052, 47536, 273878, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262379000000, 27, 24105, 22, 1595347272704687053, 47536, 340954, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262444000000, 27, 24105, 22, 1595347272704687054, 47536, 274124, 0, 120, 100000000, ?, NULL),(4, ?, 1595347262452000000, 27, 24105, 22, 1595347272704687055, 47536, 274124, 0, 120, 100000000, ?, NULL) was aborted: ERROR: duplicate key value violates unique constraint "transaction_pkey"
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:   Detail: Key (consensus_ns)=(1595347272618989000) already exists.  Call getNextException to see other errors in the batch.
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.jdbc.BatchResultHandler.handleError(BatchResultHandler.java:154) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.core.ResultHandlerDelegate.handleError(ResultHandlerDelegate.java:50) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2269) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:511) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.jdbc.PgStatement.internalExecuteBatch(PgStatement.java:851) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.jdbc.PgStatement.executeBatch(PgStatement.java:874) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.jdbc.PgPreparedStatement.executeBatch(PgPreparedStatement.java:1569) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:128) ~[HikariCP-3.4.3.jar!/:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeBatch(HikariProxyPreparedStatement.java) ~[HikariCP-3.4.3.jar!/:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.executeBatch(SqlEntityListener.java:216) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.executeBatches(SqlEntityListener.java:194) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.onEnd(SqlEntityListener.java:102) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.entity.sql.SqlEntityListener.onEnd(SqlEntityListener.java:59) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFile(RecordFileParser.java:159) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFiles(RecordFileParser.java:206) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFile(RecordFileParser.java:159) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.loadRecordFiles(RecordFileParser.java:206) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at com.hedera.mirror.importer.parser.record.RecordFileParser.parse(RecordFileParser.java:261) ~[classes!/:0.15.2]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at java.lang.Thread.run(Thread.java:834) [?:?]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]: Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "transaction_pkey"
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:   Detail: Key (consensus_ns)=(1595347272618989000) already exists.
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2533) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2268) ~[postgresql-42.2.12.jar!/:42.2.12]
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]:         ... 25 more
Jul 21 16:13:44 mirrornode-stable-testnet-primary-parser-1 java[1598]: 2020-07-21 16:13:44,174 INFO  [scheduling-3] c.h.m.i.p.r.RecordFileParser Finished parsing 115 transactions from record file /var/lib/hedera-mirror-importer/recordstreams/valid/2020-07-21T16_01_12.618989Z.rcd in 704ms (163/s)