Sqlstate 01000 error 3621

[{«Product»:{«code»:»SSETBF»,»label»:»IBM Security SiteProtector System»},»Business Unit»:{«code»:»BU059″,»label»:»IBM Software w/o TPS»},»Component»:»Database»,»Platform»:[{«code»:»PF033″,»label»:»Windows»}],»Version»:»3.0;3.1;3.1.1″,»Edition»:»»,»Line of Business»:{«code»:»LOB24″,»label»:»Security Software»}}]

Today while working with an Informatica mapping, I faced a strange issue. The image below shows the design of the INFA mapping:

Here I’m Acquiring a new table with ~500k records and the table is also very fat with PK as a GUID column. Its just a plain data pull with a simple SELECT query, no JOINs, UNIONs, etc. But while running the Workflow it gave me PK Violation error, as shown below:

Severity: ERROR
Timestamp: 5/30/2013 7:22:54 PM
Node: INFA_NODE_SERVERNAME
Thread: WRITER_1_*_1
Process ID: 8216
Message Code: WRT_8229
Message: Database errors occurred: 
Microsoft OLE DB Provider for SQL Server: The statement has been terminated.
SQL State: 01000	Native Error: 3621
State: 1	Severity: 0
SQL Server Message: The statement has been terminated.

Microsoft OLE DB Provider for SQL Server:
Violation of PRIMARY KEY constraint 'PK_tblTableName'. 
Cannot insert duplicate key in object 'dbo.tblTableName'.
The duplicate key value is (2ea8b6b9-e505-4ef1-a385-0cf9143d2cfd).

SQL State: 23000	Native Error: 2627
State: 1	Severity: 14
SQL Server Message: Violation of PRIMARY KEY constraint 'PK_tblTableName'. 
Cannot insert duplicate key in object 'dbo.tblTableName'. 
The duplicate key value is (2ea8b6b9-e505-4ef1-a385-0cf9143d2cfd).

Database driver error...
Function Name : Execute Multiple
SQL Stmt : INSERT INTO tblTableName

This was strange because the error was for the GUID PK column, and there is no reason for duplicate values here. As I’ve already taken care of INSERTs & UPDATEs by ROUTER Transformation, which can be seen in the image above. I tried to find the root cause of the error, BINGed/GOOGLEd a lot, but no luck.

Then I checked with an experienced person in my team about this error. He immediately asked me if I’ve added any “WITH (NOLOCK)” option in my query with the Source Table. I said yes, so he asked me to remove it and try, as they had faced similar issues with NOLOCK option before. I removed it and the Workflow ran successfully 🙂 .

I knew that with NOLOCK option I’m doing Dirty Reads, and had added it just to avoid locking/blocking at the Source end. But I was not aware that these Dirty Reads means any kind of data, which can also be duplicate. Thus by adding NOLOCK option with the Table, which is also going through lot of changes, we may allow data to be read more than once. This may be due to Data Movement, Uncommitted Data or Page Splits on the Source table during our reads, where we may be reading the data before and after the Page-Splits.

So, be careful while using NOLOCK option while designing your queries.

For more information check following blog: http://sqlmag.com/database-development/quaere-verum-clustered-index-scans-part-iii

I got a chance work on CDC job failure issue recently. The customer had configured CDC on the database but it wasn’t working as expected. Hence he had disabled/enabled CDC multiple times on this database.

The “cdc.[DBName]_capture” job was failing with the following error

Message: 22858, Level 16, State 1
Unable to add entries to the Change Data Capture LSN time mapping table to reflect dml changes applied to the tracked tables. Refer to previous errors in the current session to identify the cause and correct any associated problems. [SQLSTATE 42000] (Error 22858) The statement has been terminated. [SQLSTATE 01000] (Error 3621). NOTE: The step was retried the requested number of times (10) without succeeding. The step failed.

Since the error message had reference to “Change Data Capture LSN time mapping table”, I looked into the cdc.lsn_time_mapping table. On a normal CDC configuration this table would have an entry for each transaction that was captured. But in this case, there was only one entry but the “tran_begin_time” and “tran_end_time” columns had a value which was a couple of days old. Also the tran_begin_lsn was printed as 0x00000000000000000000 and tran_id was 0x00. This isn’t normal.

To get more details about this error, I added a verbose log to the CDC capture job.

The verbose log printed the following message when the job was running.

session_id error_message
----------- ----------------------------------------------
5 Violation of PRIMARY KEY constraint 'lsn_time_mapping_clustered_idx'. Cannot insert duplicate key in object 'cdc.lsn_time_mapping'. The duplicate key value is (0x0008236700032c170001). CF8:0005
5 Unable to add entries to the Change Data Capture LSN time mapping table to reflect dml changes applied to the tracked tables.

From the verbose log it was evident that the CDC capture job was trying to insert a duplicate row the object cdc.lsn_time_mapping and failing.

The sys.databases DMV reported that the log_reuse_wait_desc was REPLICATION.

name database_id log_reuse_wait_desc
---------------- ----------- ---------------------
master 1 NOTHING
tempdb 2 NOTHING
model 3 LOG_BACKUP
msdb 4 NOTHING
CDC_DB_NAME 5 REPLICATION

This indicated that another CDC or replication was active on this database. Since there was no replication configured on this instance, it had to be a CDC job.

DBCC OPENTRAN reported that there was another CDC transaction was active on this database

Transaction information for database 'cdc_db_name'.
Replicated Transaction Information:
Oldest distributed LSN : (0:0:0)
Oldest non-distributed LSN : (533351:207666:1)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Since customer had attempted enabling/disabling CDC multiple there was a possibility that a stale CDC transaction was still active on the database. To clear the article cache of CDC, executed sp_replflush against the database in question.

After restarting the job, it again failed but with a different error message now.

Another connection is already running 'sp_replcmds' for Change Data Capture in the current database.

DBCC OPENTRAN reported that there was a open transaction on the database but it was a user transaction which wasn’t running sp_replcmds.

Executed sp_replflush one more time and restarted the job again. This time it didn’t fail and also we started seeing rows getting inserted into all the CDC related tables.

Since the issue at hand was resolved, didn’t delve into the root cause. Most likely it was a stale CDC transaction which wasn’t cleaned up when CDC was disabled on the database.