I developed a custom web service for a customer that allows one of their internal web sites to create customers in GP and store customer credit card data in a third party credit card module for GP.
During the testing process, we had to troubleshoot various issues with code, APIs, data, etc. As part of that process I used my standard logging library, which writes messages and errors to a simple daily text log file on the server. I used the log to troubleshoot issues, then I resolved them, and eventually the project went live and I pretty much forgot about the detailed logging that I had setup.
Today, the customer did some additional testing on their Test web server, and he said that he encountered a problem. He sent a screen shot from his web site, but it didn't provide any information or error text.
I then reviewed the GP web service log file and was surprised to see all of the detailed logging, which is automatically enabled in the test environment.
2/5/2015 10:56:18 AM: UpdateCC Instantiating UpdateCCResponse
2/5/2015 10:56:18 AM: UpdateCC Calling ValidateUpdateCCRequestHMAC
2/5/2015 10:56:18 AM: UpdateCC Calling ProcessUpdateCCRequest
2/5/2015 10:56:18 AM: UpdateCC Calling UpdateCustomer
2/5/2015 10:56:23 AM: UpdateCC Calling GetCustomerOpenBalance
2/5/2015 10:56:23 AM: UpdateCC UpdateCC Setting regRequest values
2/5/2015 10:56:23 AM: UpdateCC Getting company ID
2/5/2015 10:56:23 AM: UpdateCC Getting customer profile ID
2/5/2015 10:56:24 AM: UpdateCC Getting CC expiration
2/5/2015 10:56:24 AM: UpdateCC Getting customer payment profile ID
2/5/2015 10:56:24 AM: UpdateCC Getting customer payment profile info
2/5/2015 10:56:24 AM: UpdateCC Updating Authnet payment profile
2/5/2015 10:56:29 AM: UpdateCC Calling ImportCC
2/5/2015 10:56:29 AM: UpdateCC Saving update CC history
2/5/2015 10:56:29 AM: UpdateCC Checking amount paid and approval code
2/5/2015 10:56:29 AM: UpdateCC completed ProcessUpdateCCRequest
2/5/2015 10:56:29 AM: UpdateCC Process UpdateCCRequest returned True
2/5/2015 10:56:29 AM: WARNING: UpdateCC elapsed time: 10.57
Reviewing the entries, there were no errors, and it looks like everything worked properly. But on the last line, I saw the warning, indicating that the process took over 10 seconds. That likely explained the problem the customer experienced. I added a timer to each method in the web service to write to the log any time it takes longer than 10 seconds to process the request.
If you have ever worked with eConnect, you likely know that the first time you call an eConnect method, it can take 5-10 seconds for it to respond. Once the eConnect service is 'alive', it responds very quickly, but eventually it shuts down again, and there will be a delay when it processes the next request.
Since the log file told me that this was the first request of the day, I suspect that eConnect took several seconds to respond when I updated the customer information, and after 10 seconds, the customer's web site timed out, thinking that the GP request had failed. Looking at the time stamp in the log, you can see that the eConnect request started at 10:56:18, and was completed 5 seconds later by 10:56:23. We also see that the call to Authorize.net took another 5 seconds, pushing the process over the 10 second threshold.
The eConnect delay occurred in the test environment because there isn't much regular activity. In the production environment, we have a process that checks the status of eConnect, SQL, Authorize.net, and the third party credit card module every minute. Because that process talks with eConnect every minute, the eConnect service always stays 'alive' and we avoid the startup delay.
Just a quick example of the value of logging and some basic diagnostics in a Dynamics GP integration.
Steve Endow is a Microsoft MVP for Dynamics GP and a Dynamics
GP Certified IT Professional in Los Angeles. He is the owner of Precipio
Services, which provides Dynamics GP integrations, customizations, and
automation solutions.
No comments:
Post a Comment