So many interesting cases, so little time to talk about them.

My interesting case this week is the mystery of the deleted POP Distributions.

The ISV had a customer where all of the distribution records in the POP10390 were being randomly deleted.  They had been trying to track this down for weeks and with the help of the Support Debugging Tool was able to capture a script.log of this happening.

To make it easier for us, the ISV whittled the file down to what he felt was the appropriate area.  As it turned out, it was true that the section that was the area where the deletions happened but it didn't really tell us what was causing this in the first place.  One thing that made looking at the file difficult was that the script.log wasn't indented as is typical, everything was left aligned.  So it made it a bear to trace through the log because you couldn't tell what was nested (and therefore less important) from line to line.

After looking at the piece of the script.log and apply our "pattern analysis goggles", Dave noticed that a block of lines was being run 151 times.

Script.log snippet of one of the similar repeated lines 'AdjustAmt of form [799]', "", 7, 63, "568368", 0, 0.00000, -CA, 0.00000, ""

So it appeared that we were looping through a bunch of records for some reason, far more than just the one specific document.  So we wondered if the customer was running some kind of maintenance?  The odd thing in the above call is that the first parameter in the snippet above is the Purchase Receipt Number and it should not be blank.  Looking at the log more closely, we very rarely saw a Purchase Receipt Number.  Hmm, not good.

The ISV didn't believe there was any type of maintenance running and provided another piece of the script.log to examine after I asked to see more of "how this started". 

In it we can see the POP_Invoice_Entry form opening and the Vendor ID change script being run.  From there it was difficult to trace, but after looking at the script.log and tracing by matching up the source code to the script log (you wouldn't be able to do this without source code) the only possibility I could conclude was that the Vendor ID change script was running however the POP Receipt Number was empty.

I had the following observations.

1. The window was an alternate window by the ISV.  You can tell by the script.log in that the form names are [resid] and not the real names of the forms.  That is a bug in the script logging process in that if the script is being run from a form that is an alternate, the code won't "fall back" all the time to determine the correct name.  Just one more thing to make it more difficult to trace since it is more difficult to read [799] instead of POP_Distribution to understand what is happening.
    
2. From the new script.log, I didn't see the POP Receipt Number pre script being run.  But we do see the Vendor ID change script running and then (bad) things happening from there.  This seemed impossible as there is a Vendor ID Pre script on the Vendor ID field that takes focus out of Vendor ID if the POP Receipt Number not set and gives an error message.  That didn't seem to be running either and the customer didn't indicate they received any type of error from Dynamics when this issue occurred.

2^nd script.log key section

What is happening in the above piece of the log file is that we are defaulting to the "CA" currency because Dynamics believes the currency changed.  This happened because the document wasn't pulled up (therefore blank on the document) and then defaulted to the Currency ID of the vendor when the Vendor Change script ran.

That wouldn't be too bad except for the "Create() of form [741]" which is the POP_ReceiptLine object form.  The  "" parameter is supposed to be the Purchase Receipt Number field.  If empty, then this is a simple create which sets a range on the entire table.  From there we are going to loop through all the PO Lines for the invoice but instead we get all the lines in the table and they are adjusted to $0 which deletes them.

So that is the trail of the script log and tells us why exactly the data is removed.  But still not quite answering how we could get into this situation.  This shouldn't be possible through the UI.

From there I asked the ISV:

1. Because the POP Receipt Number is the field that gets focus first and that didn't seem to happen in this alternate window, did they change the UI so some other field received focus instead?
    
2. Because I didn't see the POP Receipt Number pre or the Vendor ID pre scripts running, did they have VBA code on the fields that suppressed it?  It couldn't be Dexterity or VSTools because we'd see that in the script.log.  I really doubted it as because this wouldn't happen randomly - it would happen every time.
    
3. Did they have some kind of customization that was opening the window and running the change script of the Vendor ID directly? (we didn't see that piece in the script.log, only at the start of the form POP Invoice Entry opening) as the Security script runs.

As it turns out hunch number 3 was correct.  They did have a "customization" doing this but not what I suspected.  The customer had created their own Smartlist and GoTo using Smartlist Builder.  The goal was to create a "Create new Invoice for Vendor" type of GoTo for the custom Smartlist.

To make this GoTo, they chose to Open a Form and made a task for "Set a field value and run the field script" for the Vendor ID.  When I made my own Smartlist and the GoTo using this same method, everything in the window appeared fine.  It did seem to take a long time to pull up the invoice however - even with just Fabrikam data.  That is because Dynamics looped through about 100 invoice lines and "adjusting" the distributions for those lines.  Using SQL Server Management Studio, when querying the POP10390 table I found no records in it.  So this indeed was the issue.

Now that we knew what was causing this chain of events, fixing the GoTo was trivial.  For this, I made a new GoTo using the "Open Form" method.

The 3 tasks for the "Open Form" GoTo are:

• Run a field script - (L) ReceiptNumPre
• Run a field script - POP Receipt Number
• Set a field value and run the field script - Vendor ID

Making this change allowed the POP Invoice Entry window to be opened successfully with the selected Vendor displayed without deleting the POP distributions.

Hope this saves someone a headache.

Patrick