The Dynamics Explorer

Introduction

This post is similar to a previous post I did when investigating deletions on a SOP table however it takes things one step further to confirm 100% which user deleted the data.

Along with similar techniques as the previous post I also use a stored procedure and SQL job to create an alert to highlight when the deletion occurs as well as DBCC PAGE to query the contents of a 8k page of data in a restored SQL data file.

The issue

We had an ongoing issue at a client where randomly and without explanation a distribution line went missing on posted payables transactions? This is very strange as altering distribution lines isn’t allowed once a transaction has been posted. The distribution lines also must balance prior to the transaction being posted.

In order to get to the bottom of this I created a SQL stored procedure that would email me and the client when it identified any transactions with missing distributions. The stored procedure would run via a SQL agent job on a 15 minute schedule. As this had occurred in the past, but we had no idea when or how, the idea behind the alert is that it would then give us a 15 minute window to figure out what had happened. i.e. I could do SQL investigations and the client could ask all users what they were doing etc.

The stored procedure I used for the alert is below:

SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
Create Procedure [dbo].[CheckMissingDists]
as

BEGIN

Declare @NumOfMissingDistsOpen as int
Declare @NumOfMissingDistsHist as int

select @NumOfMissingDistsHist = COUNT(*) from PM80600 pmdist
	left join PM30600 pm
		on pmdist.VCHRNMBR=pm.VCHRNMBR and pmdist.DSTSQNUM=pm.DSTSQNUM
	inner join PM30200 pmhdr
		on pmdist.VCHRNMBR=pmhdr.VCHRNMBR and pmdist.DOCTYPE=pmhdr.DOCTYPE
	where pm.VCHRNMBR is null 

select @NumOfMissingDistsOpen = COUNT(*) from PM80600 pmdist
	left join PM10100 pm
		on pmdist.VCHRNMBR=pm.VCHRNMBR and pmdist.DSTSQNUM=pm.DSTSQNUM
	inner join PM20000 pmhdr
		on pmdist.VCHRNMBR=pmhdr.VCHRNMBR and pmdist.DOCTYPE=pmhdr.DOCTYPE
	where pm.VCHRNMBR is null


IF (@NumOfMissingDistsHist > 0 or @NumOfMissingDistsOpen > 0)

EXEC msdb.dbo.sp_send_dbmail 
@profile_name='Email Profile', 
@recipients='myemail@email.com;clientsemail@email.com',
@importance='High',
@subject = 'Potential missing distributions',
@body = 'Potential missing distributions'

ELSE



RETURN

END

I then created an SQL job to execute the stored procedure every 15 minutes.

** Please note the query above runs on potentially large tables (PM30200) so may take a while and lock tables on some systems.

This had all been in place for a while, and nothing happened, until yesterday when I received an alert to inform me of missing distributions.

At this point I emailed the client to ask them to check what users where doing and I connected to the SQL server to confirm the document(s) with missing distributions.

Confirming the affected document

First of all I ran the query below which is based on the code from my alert. This highlighted the transaction in question was in the OPEN PM tables

I then ran the query below to find out which transaction had the missing distributions

This shows that the distribution with the DSTSQNUM number of 32768 is no longer in the PM10100 table.

Finally I logged into Dynamics GP and found the invoice and confirmed a distribution was definitely missing

SQL Investigation

Now I had confirmed that the issue had reoccured I commenced my SQL investigations.

As I knew the issue had happened in a 15 minute window I needed to query the SQL transaction backup log file from that time period to find all deletions in a certain time frame. (I couldn’t query the actually log file using fn_dblog as a log backup had occurred). To do this I ran the query below:

select	
	[Transaction ID]
	,[begin time] as BeginTime
	,[End Time] as EndTime
	,SUSER_SNAME ([transaction sid]) as UserID
	,object_name(object_id) as TableName
	,[Lock Information]
FROM fn_dump_dblog 
	(NULL, NULL, N'DISK', 1, N'D:\<Path to Transaction Log backup file>\Transaction Log Backup File.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:\<Path to Transaction Log backup file>\Transaction Log Backup File.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 ('PM10100')) 
order by [Transaction ID]

** Please note this query is a hybrid of a query on SQL Skills blog taken from here: https://www.sqlskills.com/blogs/paul/using-fn_dblog-fn_dump_dblog-and-restoring-with-stopbeforemark-to-an-lsn/

This query highlighted a delete performed by User ID “sa” in the time frame I was looking for as per below

As there was other deletes on PM10100 around the same time I needed to figure out a way to confirm that this delete did remove the distribution on my transaction. (the other deletes could be genuine i.e. a transaction moving from OPEN to HISTORY tables)

As I couldn’t figure out a way of finding out what exact data had been deleted using just the information returned by fn_dump_dblog, I utilised the information recorded in the “Lock Information” column. (as it didn’t fit in the screen shot above I’ve expanded this below)

As you can see this provides a Page ID and a Hash Value for the data that was locked and therefore removed.

As this data has now gone from the LIVE SQL database, I restored the database to a new database called “TEST1” at a point in time prior to the issue, and used DBCC PAGE to view the contents of Page ID 3813166

And hey presto that Page did contain the data for the missing distribution from this transaction!

Therefore I can now say with certainty that the user “sa” must have somehow removed the distribution from the table. What’s more I’m fairly certain that no users use this login to access GP, therefore something else using this account must have somehow removed the distribution. (so further investigations now commence)

Conclusion

This process shows how you can use various SQL tools to pinpoint exactly who has deleted a row of data from an SQL table in a SQL database.

Please note there might be a more efficient way to do this however as fn_dump_dblog and DBCC Page are undocumented tools I couldn’t find much information on how to do this so devised this method.

I hope this helps someone in future!

Thanks for reading!