Strange Repl Problem - Duplicate Write -- sql server replication

sql server replication : Strange Repl Problem - Duplicate Write

JLS
8/30/2005 11:36:19 AM

From time to time I have a very strange occurrence in regard to =
replication, I have an attempt to write a row which already exists in my =
replicated database & the ONLY way the row can arrive in this database =
is via replication. The replicated database is used for reporting, =
therefore, users do not have any other access than Read.

If I delete the row on the replicated database, restart the distribution =
agent, all is fine & well, the row is written. But what in the world =
could be going on? I've been tearing my hair out analyzing this.

When a shipment occurs, a row should be written to the =
reprint_shipping_tbl_usr for the Bill of Lading, and then the Packing =
List, and then the C of A. Notice in the case of 173549 that the Bill =
of Lading row is missing (This is the row that is attempted to be =
duplicated)
Here is the results of a sp_browsereplcmds query (From Hillary's book)

{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'C of A Fax')}=20

{CALL sp_MSins_reprint_shipping_tbl_usr ('270594', '270615', =
2005-08-30 07:38:30.000, 'W283', 'WWC1', 'WTO Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('270594', '270615', =
2005-08-30 07:38:30.000, 'W283', 'WWC1', 'WTO Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Bill of Lading')}=20

The row for the BOL has an entry_time of 08:09, but all the others were =
written at 07:16.
The row is in the replicated db already, and yet this is how replcmds =
looks.
I am very confused as to how this could occur & where else to look to =
stop this duplicate write attempt from happening & blowing up =
replication.

Any advice will be GREATLY appreciated!!!!

Hilary Cotter
8/31/2005 11:36:52 AM

If the entry time for the last row is later it looks like the log reader =
agent took 53 minutes to pick it up. Is it possible that your log reader =
agent hiccupped during this time?
Is it also possible that the last entry was part of a transaction which =
was open for 1 hour?=20

Were you running any dbcc commands in this interval?
--=20
Hilary Cotter
Looking for a SQL Server replication book?
http://www.nwsu.com/0974973602.html

Looking for a FAQ on Indexing Services/SQL FTS
http://www.indexserverfaq.com
[quoted text, click to view]
From time to time I have a very strange occurrence in regard to =
replication, I have an attempt to write a row which already exists in my =
replicated database & the ONLY way the row can arrive in this database =
is via replication. The replicated database is used for reporting, =
therefore, users do not have any other access than Read.

If I delete the row on the replicated database, restart the =
distribution agent, all is fine & well, the row is written. But what in =
the world could be going on? I've been tearing my hair out analyzing =
this.

When a shipment occurs, a row should be written to the =
reprint_shipping_tbl_usr for the Bill of Lading, and then the Packing =
List, and then the C of A. Notice in the case of 173549 that the Bill =
of Lading row is missing (This is the row that is attempted to be =
duplicated)
Here is the results of a sp_browsereplcmds query (From Hillary's book)

{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'C of A Fax')}=20

{CALL sp_MSins_reprint_shipping_tbl_usr ('270594', '270615', =
2005-08-30 07:38:30.000, 'W283', 'WWC1', 'WTO Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('270594', '270615', =
2005-08-30 07:38:30.000, 'W283', 'WWC1', 'WTO Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Bill of Lading')}=20

The row for the BOL has an entry_time of 08:09, but all the others =
were written at 07:16.
The row is in the replicated db already, and yet this is how replcmds =
looks.
I am very confused as to how this could occur & where else to look to =
stop this duplicate write attempt from happening & blowing up =
replication.

Any advice will be GREATLY appreciated!!!!

JLS
9/1/2005 3:21:08 PM

Log Reader hiccup, how would I determine that? Any suggestions on how =
to further troubleshoot?
(I actually am using your book to troubleshoot as it is, thanx for those =
scripts, they came in rather handy)

Transaction open for 1 hour is highly doubtful, the user clicks a button =
to do a shipment & the reports are fired seamlessly. If this were the =
case it would more than likely be true more often than this error is =
occurring.

No, I was not running any dbcc commands during this time.

[quoted text, click to view]
If the entry time for the last row is later it looks like the log =
reader agent took 53 minutes to pick it up. Is it possible that your log =
reader agent hiccupped during this time?
Is it also possible that the last entry was part of a transaction =
which was open for 1 hour?=20

Were you running any dbcc commands in this interval?
--=20
Hilary Cotter
Looking for a SQL Server replication book?
http://www.nwsu.com/0974973602.html

Looking for a FAQ on Indexing Services/SQL FTS
http://www.indexserverfaq.com
[quoted text, click to view]
From time to time I have a very strange occurrence in regard to =
replication, I have an attempt to write a row which already exists in my =
replicated database & the ONLY way the row can arrive in this database =
is via replication. The replicated database is used for reporting, =
therefore, users do not have any other access than Read.

If I delete the row on the replicated database, restart the =
distribution agent, all is fine & well, the row is written. But what in =
the world could be going on? I've been tearing my hair out analyzing =
this.

When a shipment occurs, a row should be written to the =
reprint_shipping_tbl_usr for the Bill of Lading, and then the Packing =
List, and then the C of A. Notice in the case of 173549 that the Bill =
of Lading row is missing (This is the row that is attempted to be =
duplicated)
Here is the results of a sp_browsereplcmds query (From Hillary's =
book)

{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173297', '208596', =
2005-08-30 06:20:33.000, 'WWC1', '5138-01', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173563', '208597', =
2005-08-30 07:09:06.000, 'WWC1', '8008-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'C of A Fax')}=20

{CALL sp_MSins_reprint_shipping_tbl_usr ('270594', '270615', =
2005-08-30 07:38:30.000, 'W283', 'WWC1', 'WTO Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('270594', '270615', =
2005-08-30 07:38:30.000, 'W283', 'WWC1', 'WTO Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('172019', '208599', =
2005-08-30 07:49:52.000, 'WST1', '5587-01', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173557', '208600', =
2005-08-30 08:00:26.000, 'WCH1', '3667-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173556', '208601', =
2005-08-30 08:02:11.000, 'WCH1', '4517-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173001', '208602', =
2005-08-30 08:06:25.000, 'WCH1', '7762-00', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Bill of Lading')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Packing List')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'Cert of Analysis')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173235', '208603', =
2005-08-30 08:07:12.000, 'WCH1', '1270-06', 'C of A Fax')}=20
{CALL sp_MSins_reprint_shipping_tbl_usr ('173549', '208598', =
2005-08-30 07:16:09.000, 'WWC1', '4270-00', 'Bill of Lading')}=20

The row for the BOL has an entry_time of 08:09, but all the others =
were written at 07:16.
The row is in the replicated db already, and yet this is how =
replcmds looks.
I am very confused as to how this could occur & where else to look =
to stop this duplicate write attempt from happening & blowing up =
replication.

Any advice will be GREATLY appreciated!!!!

Got something to say? Click here to post a reply to this thread.

Don't see what you're looking for? Try a search.

View other messages about sql server replication

View Other Months
April 2003
June 2003
July 2003
August 2003
September 2003
October 2003
November 2003
December 2003
January 2004
February 2004
March 2004
April 2004
May 2004
June 2004
July 2004
August 2004
September 2004
October 2004
November 2004
December 2004
January 2005
February 2005
March 2005
April 2005
May 2005
June 2005
July 2005
August 2005
September 2005
October 2005
November 2005
December 2005
January 2006
February 2006
March 2006
April 2006
May 2006
June 2006
July 2006
August 2006
September 2006
October 2006
November 2006
December 2006
January 2007
February 2007
March 2007
April 2007
May 2007
June 2007
July 2007
August 2007
September 2007
October 2007
November 2007

home · blog · groups

Questions? Comments? Contact the dn