View Issue Details

IDProjectCategoryView StatusLast Update
0003845SymmetricDSBugpublic2022-09-19 18:41
Reporterlukasz.krawczyk Assigned Topmarzullo  
Priorityhigh 
Status closedResolutionfixed 
Product Version3.9.16 
Target Version3.14.2Fixed in Version3.14.2 
Summary0003845: Primary key constraint violation while replicating single table from MSSQL 2017 into PostgreSQL 9.6
DescriptionThis bug does NOT appear in SymmetricDS 3.8.41 version and is due to erroneous MSSQL database trigger definition in 3.9.16 version.

Consider the following MSSQL table:
CREATE TABLE [dbo].[rightsholder_invoice](
    [rightsholder_invoice_id] [int] NOT NULL,
    [rightsholder_invoice_datetime] [datetime] NOT NULL,
    [rightsholder_id] [int] NOT NULL,
    [number] [varchar](128) NOT NULL,
    [income_date] [date] NOT NULL,
    [invoice_date] [date] NOT NULL,
    [sale_date] [date] NOT NULL,
    [rightsholder_invoice_type_id] [int] NOT NULL,
    [status_description] [varchar](128) NULL,
    [comment] [varchar](max) NULL,
    [correcting_rightshaolder_invoice_id] [int] NULL,
    [GUID] [uniqueidentifier] NOT NULL,
    [LAST_UPDATE_DATE_TIME] [datetime2](7) NOT NULL,
 CONSTRAINT [PK_rightsholder_invoice] PRIMARY KEY CLUSTERED
(
    [rightsholder_invoice_id] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]
GO

Initial table definition creation and initial loading of data is performed correctly.

After performing simple update on multiple records at once exception occurs (mutiple records changed in single transaction are a must for this error to occur):

UPDATE [zol].[dbo].[rightsholder_message]
SET [message_content] = 'some_text';
(1252 rows affected)

Error in changes replication:

2019-01-03 18:10:51,796 INFO [zapaonline-001] [DefaultDatabaseWriter] [zapaonline-001-dataloader-6] Failed to process update event in batch 000-32 on channel 'zol_to_zapaonline'.
Failed sql was: update "public"."rightsholder_invoice" set "rightsholder_invoice_id" = 1, "rightsholder_invoice_datetime" = {ts '2012-12-05 12:24:17.433'}, "rightsholder_id" = 5982, "number" = '11/2012', "income_date" = '2012-11-16', "invoice_date" = '2012-11-09', "sale_date" = '2012-11-09', "rightsholder_invoice_type_id" = 1, "status_description" = 'Zaakceptowana', "comment" = 'wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg', "correcting_rightsholder_invoice_id" = null, "guid" = 'EE49EA84-105E-435B-9D79-06558EBEA744', "last_update_date_time" = {ts '2018-11-06 14:43:39.606'} where "rightsholder_invoice_id" = 4285
Failed raw sql was: update "public"."rightsholder_invoice" set "rightsholder_invoice_id" = ?, "rightsholder_invoice_datetime" = ?, "rightsholder_id" = ?, "number" = ?, "income_date" = ?, "invoice_date" = ?, "sale_date" = ?, "rightsholder_invoice_type_id" = ?, "status_description" = ?, "comment" = ?, "correcting_rightsholder_invoice_id" = ?, "guid" = ?, "last_update_date_time" = ? where "rightsholder_invoice_id" = ?
Failed sql parameters: [1, {ts '2012-12-05 12:24:17.433'}, 5982, '11/2012', '2012-11-16', '2012-11-09', '2012-11-09', 1, 'Zaakceptowana', 'wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg', null, 'EE49EA84-105E-435B-9D79-06558EBEA744', {ts '2018-11-06 14:43:39.606'}, 4285]
Failed sql parameters types: [INTEGER, TIMESTAMP, INTEGER, VARCHAR, VARCHAR, VARCHAR, VARCHAR, INTEGER, VARCHAR, LONGVARCHAR, INTEGER, CHAR, TIMESTAMP, INTEGER]
Failed sql state and code: 23505 (0)
Failed pk data was: "4285"
Failed row data was: "1","2012-12-05 12:24:17.433","5982","11/2012","2012-11-16","2012-11-09","2012-11-09","1","Zaakceptowana","wZjKbXąJŚźHyżtohmoĄei9ćTQpLłŻ7ŁNxDuęqFóg",,"EE49EA84-105E-435B-9D79-06558EBEA744","2018-11-06 14:43:39.6066667"
Failed old data was: "4285","2018-10-26 14:29:28.987","1469","12/2018","2018-10-26","2018-10-15","2018-10-15","1","Zaakceptowana",,,"0A16CC16-1216-4C59-A3EE-6521517E52F2","2018-11-06 14:43:39.6066667"
 StackTraceKey.init [UniqueKeyException:2026926579]
org.jumpmind.db.sql.UniqueKeyException: org.postgresql.util.PSQLException: BŁĄD: podwójna wartość klucza narusza ograniczenie unikalności "rightsholder_invoice_pkey"
  Detail: Klucz (rightsholder_invoice_id)=(1) już istnieje.
    at org.jumpmind.db.sql.AbstractSqlTemplate.translate(AbstractSqlTemplate.java:296)
    at org.jumpmind.db.sql.AbstractSqlTemplate.translate(AbstractSqlTemplate.java:291)
    at org.jumpmind.db.sql.JdbcSqlTransaction.addRow(JdbcSqlTransaction.java:466)
    at org.jumpmind.symmetric.io.data.writer.DefaultDatabaseWriter.execute(DefaultDatabaseWriter.java:904)
    at org.jumpmind.symmetric.io.data.writer.DefaultDatabaseWriter.update(DefaultDatabaseWriter.java:488)
    at org.jumpmind.symmetric.io.data.writer.AbstractDatabaseWriter.write(AbstractDatabaseWriter.java:188)
    at org.jumpmind.symmetric.io.data.writer.NestedDataWriter.write(NestedDataWriter.java:64)
    at org.jumpmind.symmetric.model.ProcessInfoDataWriter.write(ProcessInfoDataWriter.java:84)
    at org.jumpmind.symmetric.io.data.writer.NestedDataWriter.write(NestedDataWriter.java:64)
    at org.jumpmind.symmetric.io.data.writer.TransformWriter.write(TransformWriter.java:201)
    at org.jumpmind.symmetric.io.data.DataProcessor.forEachDataInTable(DataProcessor.java:210)
    at org.jumpmind.symmetric.io.data.DataProcessor.forEachTableInBatch(DataProcessor.java:177)
    at org.jumpmind.symmetric.io.data.DataProcessor.process(DataProcessor.java:123)
    at org.jumpmind.symmetric.service.impl.DataLoaderService$LoadIntoDatabaseOnArrivalListener$2.call(DataLoaderService.java:1039)
    at org.jumpmind.symmetric.service.impl.DataLoaderService$LoadIntoDatabaseOnArrivalListener$2.call(DataLoaderService.java:1016)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: org.postgresql.util.PSQLException: BŁĄD: podwójna wartość klucza narusza ograniczenie unikalności "rightsholder_invoice_pkey"
  Detail: Klucz (rightsholder_invoice_id)=(1) już istnieje.
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2422)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2167)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:306)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:155)
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:132)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
    at org.jumpmind.db.sql.JdbcSqlTransaction.executePreparedUpdate(JdbcSqlTransaction.java:485)
    at org.jumpmind.db.sql.JdbcSqlTransaction.addRow(JdbcSqlTransaction.java:463)
    ... 16 more

Full log attached.

The problem is due to the error on ordering changes while inserting them into [sym_data] mssql table in [SYM_ON_U_FOR_RGHTSHLDR_NVC_ZL] trigger (after update trigger on [dbo].[rightsholder_invoice] table).

The pk_data and respecting row_data in [sym_data] are inserted in REVERSE order - please see attached screenshot.
Tagsdialect: sql-server, trigger

Activities

lukasz.krawczyk

2019-01-03 17:30

reporter  

symmetric.log (46,580 bytes)

elong

2019-01-14 15:08

developer   ~0001378

You have the sym_trigger.use_handle_key_updates=1, is that correct? I believe that causes the trigger to be generated with logic that is vulnerable to mis-ordering. Here's why. SQL-Server provides two virtual tables to the trigger: "inserted" is the new rows and "deleted" is the old rows. The trigger needs to join those two virtual tables, and it normally joins on the primary key columns. But when you enable handling of primary key updates, it can no longer join on the PK because the new and old values are different. So it assumes row 1 of "inserted" will match row 1 of "deleted", and so on. It used to open a cursor to loop through the rows, but it was changed to join the tables using row_number(), because cursors have a performance penalty. The change in technique was supposed to be equivalent logic. In reality, there is no guarantee from SQL-Server that there is any kind of order on the virtual tables.

Does your test fail every time you run it on 3.9, or just sometimes? Does your test work every time on 3.8, or just sometimes?

lukasz.krawczyk

2019-01-14 23:11

reporter   ~0001381

Hi, and thanks for reply.

The sym_trigger.use_handle_key_updates setting was not changed by me, and I believe it is still at default (0) value.
Also, this test always fails on 3.9, and always works on 3.8 .

I`m attaching two database triggers versions for further investigation (generated from 3.8 and 3.9 versions).

If You'll look at this fragment - this is the difference which probably causes the error:

3.8:

... from inserted inner join "zol"."dbo"."rightsholder_invoice" orig on orig."rightsholder_invoice_id"=inserted."rightsholder_invoice_id" inner join deleted on deleted."rightsholder_invoice_id"=inserted."rightsholder_invoice_id"

3.9:

... from (select "rightsholder_invoice_id","rightsholder_invoice_datetime","rightsholder_id","number","income_date","invoice_date","sale_date","rightsholder_invoice_type_id","status_description","comment","correcting_rightsholder_invoice_id","GUID","LAST_UPDATE_DATE_TIME", row_number() over (order by (select 1)) as __row_num from inserted) inserted inner join "zol"."dbo"."rightsholder_invoice" orig on orig."rightsholder_invoice_id"=inserted."rightsholder_invoice_id" inner join (select "rightsholder_invoice_id","rightsholder_invoice_datetime","rightsholder_id","number","income_date","invoice_date","sale_date","rightsholder_invoice_type_id","status_description","comment","correcting_rightsholder_invoice_id","GUID","LAST_UPDATE_DATE_TIME", row_number() over (order by (select 1)) as __row_num from deleted)deleted on (inserted.__row_num = deleted.__row_num)
           
PS.: The query used to update multiple rows in my previous post should be:

UPDATE [zol].[dbo].[rightsholder_invoice]
SET [comment] = 'some_text';
3.8_new.sql (7,709 bytes)
3.9_new.sql (8,516 bytes)

lukasz.krawczyk

2019-01-14 23:23

reporter   ~0001382

Oh, I`ve just checked that the default value for sym_trigger.use_handle_key_updates changed between versions:

In 3.9:
https://www.jumpmind.com/downloads/symmetricds/doc/3.9/html/user-guide.html
USE_HANDLE_KEY_UPDATES = default 1

In 3.8:
https://www.jumpmind.com/downloads/symmetricds/doc/3.8/html/user-guide.html
USE_HANDLE_KEY_UPDATES = default 0

Well, that was unexpected, although mentioned in changelog for 3.9:

0003053: [Improvement] Default handle_key_updates in sym_trigger to 1 (chenson)

However, error probably still remains in SQL server for this case - as I didn't change PK value, only 'comment' column value on multiple rows at once.

elong

2022-09-19 18:40

developer   ~0002200

This situation was improved in issue 0005157 for SymmetricDS 3.14, where it only uses the "handle key updates" logic when the primary key values are actually changing.

Issue History

Date Modified Username Field Change
2019-01-03 17:30 lukasz.krawczyk New Issue
2019-01-03 17:30 lukasz.krawczyk File Added: symmetric.log
2019-01-03 17:30 lukasz.krawczyk File Added: 2019-01-03 18_27_34-SQLQuery6.sql - localhost.zol (sa (57)) - Microsoft SQL Server Management Studio.png
2019-01-14 15:08 elong Note Added: 0001378
2019-01-14 23:11 lukasz.krawczyk File Added: 3.8_new.sql
2019-01-14 23:11 lukasz.krawczyk File Added: 3.9_new.sql
2019-01-14 23:11 lukasz.krawczyk Note Added: 0001381
2019-01-14 23:23 lukasz.krawczyk Note Added: 0001382
2019-04-25 18:47 elong Tag Attached: dialect: sql-server
2019-04-25 18:47 elong Tag Attached: trigger
2022-09-19 18:40 elong Note Added: 0002200
2022-09-19 18:41 elong Assigned To => pmarzullo
2022-09-19 18:41 elong Status new => closed
2022-09-19 18:41 elong Resolution open => fixed
2022-09-19 18:41 elong Fixed in Version => 3.14.2
2022-09-19 18:41 elong Target Version => 3.14.2
2022-09-19 18:41 elong Description Updated View Revisions