Fix duplicate key errors on resuming continued txn

[arajkumar]

This commit addresses and resolves the issue of duplicate key errors when resuming partially executed transactions (continuedTxn) in pgcopydb. We have reintroduced the transaction metadata file, which is essential for identifying the commitLSN of a partial transaction.

Unlike our previous approach, which led to a deadlock between the transform and apply phases, this update brings a more efficient process. Now, the apply phase creates metadata for any partial (continued) transactions during the commit. This metadata is then used to accurately skip the already applied partial transaction if a resume is needed.

This fix is crucial, particularly for tables with unique constraints, where executing the same continued transaction twice previously resulted in duplicate key errors. With this update, pgcopydb ensures smooth and error-free handling of transaction resumes.

[lospejos]

@dimitri We also faced the error ERROR: duplicate key value violates unique constraint... Key (id)=(value) already exists.
Kindly ask to verify and merge this PR, I hope this may help in our case.

Thanks!

[arajkumar]

Hello @lospejos , Did you see the error message while resuming the pgcopydb?

[lospejos]

Hello @lospejos , Did you see the error message while resuming the pgcopydb?

I tried to resume migration process using --resume command line option like this:

$ pgcopydb follow --table-jobs 8 --index-jobs 8 --resume --not-consistent --slot-name pgcopydb --no-acl --no-owner --no-role-passwords --no-comments --fail-fast --filter /opt/pgcopydb_filter.ini --plugin wal2json

and faced the same error:

ERROR  [TARGET 26433] ERROR:  duplicate key value violates unique constraint "tablename_pkey"
ERROR  [TARGET 26433] DETAIL:  Key (id)=(value) already exists.
ERROR  Failed to apply SQL from file "/root/.local/share/pgcopydb/00000001000025E700000014.sql", see above for details
INFO   Reported write_lsn 25E7/15235EC0, flush_lsn 25E7/15235EC0, replay_lsn 25E7/14FE1E60
ERROR  Subprocess catchup with pid 18699 has exited with error code 12
ERROR  Postgres query was interrupted: update pgcopydb.sentinel set startpos = $2, write_lsn = $1, flush_lsn = $2 returning startpos, endpos, apply, write_lsn, flush_lsn, replay_lsn
ERROR  Failed to fetch pgcopydb.sentinel current values
INFO   Reported write_lsn 25E7/152DEC50, flush_lsn 25E7/152DEC50, replay_lsn 25E7/14FE1E60
INFO   Streamed up to write_lsn 25E7/152DEC50, flush_lsn 25E7/152DEC50, stopping: endpos is 0/0
INFO   Prefetch process has terminated
ERROR  Some sub-process exited with errors, see above for details
ERROR  Failed to follow changes from source, see above for details

[arajkumar]

Thanks @lospejos, This is the exact scenario the PR is trying to solve. I recommend compiling pgcopydb with this PR to find out whether it helps.

[lospejos]

Thanks @lospejos, This is the exact scenario the PR is trying to solve. I recommend compiling pgcopydb with this PR to find out whether it helps.

Thanks for your information and for your contribution!

[shubhamdhama]

@arajkumar can you please elaborate the root cause? Maybe I need to revisit my understanding of how whole resuming is working in online now. I believe #525 wouldn't allow the case you mentioned in the description.

Also, is there a way to reproduce this?

[arajkumar]

@shubhamdhama In issue #525, the implementation permits the execution of transactions up to the COMMIT stage. The decision to either COMMIT or ROLLBACK is made based on the transaction's commit LSN. However, this approach encounters a challenge with transactions (lacking a Commit LSN) that target tables with UNIQUE or PRIMARY KEY constraints. When such a transaction is executed a second time (as might occur during a resume operation), it leads to failures due to constraint violations.

This PR also has a test case which can be used to reproduce the problem.

EDIT: The current version of txn metadata has been written and consumed only from apply process, so there won't be any kind of deadlock would be possible unlike the previous implementation.

[lospejos]

I tried to add changes from this PR (I replacing file ld_apply.c with copy form your PR) and rerun previously interrupted migration using command line:

$ pgcopydb follow --table-jobs 8 --index-jobs 8 --resume --not-consistent --slot-name pgcopydb --no-acl --no-owner --no-role-passwords --no-comments --fail-fast --filter /opt/pgcopydb_filter.ini --plugin wal2json

BTW I'm not sure if the rerun command was ok, please, correct me, if I was wrong with this command.

Unfortunately I encountered the same error:

13:52:42 38458 ERROR  [TARGET 31303] ERROR:  duplicate key value violates unique constraint "tablename_pkey"
13:52:42 38458 ERROR  [TARGET 31303] DETAIL:  Key (id)=(247420390) already exists.
13:52:42 38458 ERROR  Failed to apply SQL from file "/root/.local/share/pgcopydb/00000001000025E700000014.sql", see above for details
13:52:42 38456 INFO   Reported write_lsn 25E7/152DEC50, flush_lsn 25E7/152DEC50, replay_lsn 25E7/14FE1E60
13:52:42 38452 ERROR  Subprocess catchup with pid 38458 has exited with error code 12
13:52:43 38456 ERROR  Postgres query was interrupted: update pgcopydb.sentinel set startpos = $2, write_lsn = $1, flush_lsn = $2 returning startpos, endpos, apply, write_lsn, flush_lsn, replay_lsn
13:52:43 38456 ERROR  Failed to fetch pgcopydb.sentinel current values
13:52:43 38456 INFO   Reported write_lsn 25E7/15511EB8, flush_lsn 25E7/15511EB8, replay_lsn 25E7/14FE1E60
13:52:43 38456 INFO   Streamed up to write_lsn 25E7/15511EB8, flush_lsn 25E7/15511EB8, stopping: endpos is 0/0
13:52:43 38456 INFO   Prefetch process has terminated
13:52:43 38452 ERROR  Some sub-process exited with errors, see above for details
13:52:43 38452 ERROR  Failed to follow changes from source, see above for details

I'm not sure that my rerun command was correct.
Also hope that this information will help.

[arajkumar]

@lospejos Did you retry from the begining? It won't work if you just resume after building new binary., because the previous version of apply doesn't know about txn metadata.

I would recommend to do the following,

pgcopydb snapshot --follow --plugin wal2json &

pgcopydb follow --restart

pgcopydb follow --resume --plugin wal2json

It is not related, but these flags --table-jobs 8 --index-jobs 8 --no-acl --no-owner --no-role-passwords --no-comments --filter /opt/pgcopydb_filter.ini won't have any impact on the follow command.

[lospejos]

@arajkumar

Thanks for your comment. I tried to execute commands you provided earlier, but there was errors:

# pgcopydb snapshot --follow --plugin wal2json
16:50:21 40981 INFO   Running pgcopydb version 0.14.1.7.gbbbe01d.dirty from "/opt/pgcopydb_0.14.1.7/pgcopydb"
16:50:21 40981 INFO   A previous run has run through completion
16:50:21 40981 FATAL  Please use --restart to allow for removing files that belong to a completed previous run.

# pgcopydb follow --restart
16:51:00 40984 INFO   Running pgcopydb version 0.14.1.7.gbbbe01d.dirty from "/opt/pgcopydb_0.14.1.7/pgcopydb"
16:51:00 40984 INFO   [SOURCE] Copying database from "postgres://<skipped>"
16:51:00 40984 INFO   [TARGET] Copying database into "postgres://<skipped>"
16:51:01 40984 ERROR  Failed to send CREATE_REPLICATION_SLOT command:
16:51:01 40984 ERROR  [SOURCE 891444] [42710] ERROR:  replication slot "pgcopydb" already exists
16:51:01 40984 ERROR  [SOURCE 891444] Context: CREATE_REPLICATION_SLOT "pgcopydb" LOGICAL "test_decoding"
16:51:01 40984 ERROR  Failed to create a logical replication slot and export a snapshot, see above for details

# pgcopydb follow --resume --plugin wal2json
16:51:36 40987 INFO   Running pgcopydb version 0.14.1.7.gbbbe01d.dirty from "/opt/pgcopydb_0.14.1.7/pgcopydb"
16:51:36 40987 ERROR  Options --snapshot is mandatory unless using --not-consistent
16:51:36 40987 FATAL  Option --resume requires option --not-consistent

[arajkumar]

@lospejos Ok, since you are not doing clone and only follow, snapshot is not really needed. Lets try this.

pgcopydb stream cleanup

pgcopydb follow --restart

pgcopydb follow --resume

[lospejos]

@lospejos Ok, since you are not doing clone and only follow, snapshot is not really needed. Lets try this.

pgcopydb stream cleanup

pgcopydb follow --restart

pgcopydb follow --resume

@arajkumar I've started commands:

pgcopydb stream cleanup

pgcopydb follow --restart --plugin wal2json 

After that it seems that migration process resumed without errors. I see messages like:

11:29:30 48828 INFO   Transformed 11796 JSON messages into SQL file "/root/.local/share/pgcopydb/00000001000025F300000013.sql"
11:29:31 48827 INFO   Reported write_lsn 25F3/14058F30, flush_lsn 25F3/13E02FB8, replay_lsn 0/0
11:29:41 48827 INFO   Reported write_lsn 25F3/142E5A98, flush_lsn 25F3/14058F30, replay_lsn 0/0
11:29:51 48827 INFO   Reported write_lsn 25F3/14464B10, flush_lsn 25F3/142E5A98, replay_lsn 0/0
11:30:01 48827 INFO   Reported write_lsn 25F3/1461ED58, flush_lsn 25F3/14464B10, replay_lsn 0/0
11:30:11 48827 INFO   Reported write_lsn 25F3/147FA298, flush_lsn 25F3/1461ED58, replay_lsn 0/0
11:30:21 48827 INFO   Reported write_lsn 25F3/149AEA78, flush_lsn 25F3/147FA298, replay_lsn 0/0
11:30:31 48827 INFO   Reported write_lsn 25F3/14B5BFD0, flush_lsn 25F3/149BE778, replay_lsn 0/0

This continued and I have no chance to enter the third command pgcopydb follow --resume.

After checking data in tables on Source and Target databases, I see a difference - no new data was migrated to a Target database since previous migration was failed (a couple days ago).
I'm not sure is it due to my invalid previous commands (something was accidentally disabled or incorrectly updated), or something else.

I decided to cleanup target database and restart data migration process from scratch. If it also will fail with ERROR: duplicate key value violates unique constraint error, I'll try to use you approach from previous message.

[arajkumar]

@lospejos I missed pgcopydb sentinel set apply. Include that too and run it from a separate terminal tab/window with all the necessary env. Otherwise, the data won't be moved to the target.

[arajkumar]

@dimitri @shubhamdhama Could you please review this fix?

[lospejos]

@lospejos I missed pgcopydb sentinel set apply. Include that too and run it from a separate terminal tab/window with all the necessary env. Otherwise, the data won't be moved to the target.

Could you please specify, where/when exactly should I execute pgcopydb sentinel set apply?

Is this commands order correct:

pgcopydb stream cleanup
pgcopydb sentinel set apply
pgcopydb follow --restart --plugin wal2json
pgcopydb follow --resume

?

[arajkumar]

pgcopydb stream cleanup

# run follow in background 
pgcopydb follow --restart --plugin wal2json &

# wait for sentinel to be created by follow
sleep 10

# enable apply
pgcopydb sentinel set apply

# now bring follow to foreground
fg

# run for few mins & if you want to test resume, stop using Ctrl + C and then resume like below

pgcopydb follow  --plugin wal2json --resume

[dimitri]

LGTM! Just left a nitpicking comment about a DEBUG message, please consider fixing it before merge.

[dimitri]

Almost there. Sorry I missed a couple places in my previous review.

[arajkumar]

Thank you @dimitri !