The Dynamics Explorer

This week I dealt with a very bizarre issue affecting all Sales Order Processing Transactions that I thought was worth documenting. It started with a simple support request explaining that Sales Order Processing Invoice transactions weren’t posting due to missing distributions. See below

When I connected to investigate further I found the Sales Order Processing Distribution Work\History table (SOP10102) was, with the exception of a hand full of rows, completely blank. (and those rows related to the most recently added SOP transactions)

As this table contains the distributions for both Work and History documents all distributions on posted Sales Order Processing transactions had been lost as well.

Before I even considered how this could have happened I set about trying to find out which user could have done this, and when it happened, so I could recover the missing data.

The first clue for when this could have happened lay with the SQL transaction log backups. As this table would have had hundreds of thousands of rows, I suspected this would have generated lots of SQL transaction log, so I checked the size of the transaction log backups and this highlighted a larger than normal LOG backup at midday (I could do this as the SQL database is in FULL recovery model and the client performs hourly transaction log backups)

I now suspected the issue had arose between 11am and midday so I set about querying the contents of this SQL transaction log backup file looking for transactions with deletes on the SOP10102 table using the query below.

(As usual I’m standing on the shoulders of giants for this one by using this excellent blog post by SQL guru Paul Randal as the basis of the query https://www.sqlskills.com/blogs/paul/using-fn_dblog-fn_dump_dblog-and-restoring-with-stopbeforemark-to-an-lsn/. As a side note this website is an awesome SQL resource!)

select	
	[begin time] as BeginTime,
	[End Time] as EndTime,
	SUSER_SNAME ([transaction sid]) as UserID, 
	object_name(object_id) as TableName, *
FROM fn_dump_dblog 
	(NULL, NULL, N'DISK', 1, N'D:\...\backup_2019_10_07_120002_5428125.TRN', 
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT) as log1
left join sys.partitions part 
	 on part.partition_id=log1.partitionid
where  
	[transaction id] IN
(select 
	[transaction id]
 FROM fn_dump_dblog 
	(NULL, NULL, N'DISK', 1, N'D:\...\backup_2019_10_07_120002_5428125.TRN',
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT) as log1
left join sys.partitions part 
	on part.partition_id=log1.partitionid
where 
	operation = 'LOP_DELETE_ROWS' and 
	object_name(object_id) in ('SOP10102')) 
order by [Transaction ID]

I scanned through the results and found the transaction id below which was logging lots of deletes on the SOP10102 table

I then took this Transaction ID and ran the following SQL query to get full details on this SQL Transaction

select 
	[begin time] as BeginTime, 
	[End Time] as EndTime,
	SUSER_SNAME ([transaction sid]) as UserID, 
	object_name(object_id) as TableName, *
FROM fn_dump_dblog 
	(NULL, NULL, N'DISK', 1, N'D:\...\backup_2019_10_07_120002_5428125.TRN', 
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
	 DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT) as log1
left join sys.partitions part 
	on part.partition_id=log1.partitionid
where  [transaction id] IN ('0000:088fba17')

This query returned 1,466,128 rows all of which are deletes to SOP10102. (this is more than the number of rows in the table which is likely because of the additional deletes on the SQL non clustered indexes that also need maintaining)

Following on from this I’m now know the user who has caused the deletes, and the exact time it happened. I also know this SQL Login ID relates to a GP user which means this has to have happened inadvertently while using GP. (you can’t use a Dynamics GP SQL Login to access the data via any tool other than Dynamics GP as the password is encrypted)

I asked the user in question if they noticed anything strange at this time like GP crashing or hanging but unfortunately they don’t recall. Therefore this is still a total mystery I’m afraid.

To recover the data I restored the backup to a new database right up to the point of the data going missing i.e. I restored the FULL SQL backup and all LOG backups with NORECOVERY with the exception of the last LOG backup which I restored as per below

I then copied the data back using the SQL query below

INSERT INTO LIVEDB..SOP10102
(SOPTYPE, SOPNUMBE, SEQNUMBR, DISTTYPE, DistRef,
ACTINDX, DEBITAMT, ORDBTAMT, CRDTAMNT, ORCRDAMT,
CURRNIDX, TRXSORCE, POSTED, Contract_Exchange_Rate)
SELECT
A.SOPTYPE,
A.SOPNUMBE,
A.SEQNUMBR,
A.DISTTYPE,
A.DistRef,
A.ACTINDX,
A.DEBITAMT,
A.ORDBTAMT,
A.CRDTAMNT,
A.ORCRDAMT,
A.CURRNIDX,
A.TRXSORCE,
A.POSTED,
A.Contract_Exchange_Rate
FROM RESTOREDDB..SOP10102 A
LEFT JOIN LIVEDB..SOP10102 b
on a.SOPNUMBE=b.SOPNUMBE and a.SOPTYPE=b.SOPTYPE
WHERE
B.SOPNUMBE IS NULL

After running the INSERT query the client confirmed that all the data had been recovered.

I’d be interested to know if anyone else has seen anything similar in the past. Unfortunately I’ve also seen this happen on the Purchase Order Processing side but it was before my blogging days. I’ve also found this Microsoft blog which documents a similar issue that Microsoft support dealt with https://blogs.msdn.microsoft.com/developingfordynamicsgp/2010/04/08/pop-distributions-randomly-being-deleted/

Although I didn’t get to the bottom of the missing POP data I did have my suspicions however there are no related third parties that could have caused this issue with SOP10102.

Unfortunately I suspect this will also remain an unsolved mystery I just hope it doesn’t happen again.

Thanks for reading