Debugging in the Dynamics GP 2015 Service Based Architecture

As we move into the world of Service Based Architecture with Dynamics GP 2015, we wanted to highlight some debugging tools that will aid you as you create service procedures of your own.  Today you have various things available to you to debug integrations as they are created.  Among them are internal tools like the Dexterity script logs and the debugger or methods as simple as dropping the .set file on the runtime executable to ensure Dynamics still launches without error. There are numerous external tools at your fingertips as well such as SQL Profiler, Task Manager and Event Viewer.  While you will continue to find great value in these going forward when debugging things “inside” of the Dynamics GP environment we wanted to add tools for gathering information for all of the service events happening “outside” this environment and coming into the Dexterity Process. 

While considering the options we knew we wanted to create debugging that was low impact on the process overall and incredibly performant. We wanted to not only provide you errors that were encountered within the service but also provide context to enable easier and quicker debugging.  Along with this we wanted to provide a sufficient level of logging by default to strike a balance between usefulness and performance. 

To enable this we decided to utilize Event Tracing for Windows (ETW). This is a general-purpose, high-speed tracing facility provided by the operating system and is the standard way to trace used by all features in Windows.  This gives developers the ability to instrument an application to provide tracing events, dynamically start and stop tracing sessions and consume trace events if desired.  One big advantage to this is you can use any tool available today (and there are many) that consumes these types of logs to serve the trace data up in a way that makes sense for your desired usage.  Along with the plethora of tools already available today there are also various listeners such as Logman and Performance Monitor that can be utilized.  Other tools to research in this arena would be PerfView and the Semantic Logging Service.  The former is very much a power user tool that lets you view machine-wide events correlated with everything else imaginable (CPU samples, CLR events, etc). This is a free tool and is particularly handy if you are doing .NET performance assessments.  The Semantic Logging Service can be set up to listen to a specific set of EventSources (ours all have unique names) and pick a central log sink (a file, a console session, etc) so it is highly customizable to provide the exact data you want in the format that makes sense.

If you are researching ETW consuming applications the Event Source names of our services are:
  Microsoft-Dynamics-GP-Svc-GPService
  Microsoft-Dynamics-GP-Svc-DexterityService
  Microsoft-Dynamics-GP-Svc-DexterityProcess

Now onto the new functionality we added. The first debugging tool I’d like to highlight is trace messages.  These messages can be placed within your sanScript procedures and then captured so you can verify how far within an event you are going and the data that is set at those points. These trace message are then captured in the various logs we’ve created to monitor requests as they move through the service framework from initial request to the Dexterity process. The exact syntax of this is in review so it may be changed by the RTM of GP 2015 but an example of trace messaging in today’s format is:
  
 TRACEMSG("Set Buyer ID: "+'Buyer ID' of window Buyer_Lookup_Scroll + "="+str(i));

The second debugging tool to highlight is the logging that has been added.  In the configurable %ProgramData% location we’ve added three main logs that will serve as the cornerstone of the customer/partner debugging experience.  The below graphic shows how the requests flow through the service layers and the corresponding events happening that may produce information in each log.

 

GP Service Log – This is the first place to search if you are looking for the source of a problem but have little information to go on. This is the first layer of the service that a request will hit when sent. As such it will provide information around unknown tenants, authentication failures and if a request did not successfully make it through the GP Service layer for some other reason.

Dexterity Service Log – The next layer a request will flow through is the Dexterity Service Layer. This log file will contain information to help resolve configuration errors with the environment or if there are structural errors in the request being made.  One thing to note is if there is an error object or payload contained in this log, you know the request made it through to Dexterity for processing.

These two logs are great for generic errors. However, once the environment is setup and running these logs cease to be as useful for debugging.  At this point, the next step would be to ping the service. If that is successful you’ve verified that the hosts, service and pipelines running through to the Dexterity process are working for end to end connectivity. If you still have errors once ping is successful that is when you move to the last main log we’ve added…or potentially further into the usual application logs you are used to using.

Request Log – This log gives you any and all information including errors and context for one single request.  A great advantage of this log is that it correlates all of the information together per request so you can follow the link between the service framework events to the Dex events to the response delivered. If you’ve previously added Trace Messages in your sanScript procedures they will appear in this log as well.

Through all of these logs we’ve incorporated a Correlation ID (GUID) that flows through each of the logs to link events together. This ID is returned as part of the response body (Status section) and/or in the response header. It’s important to grab this from a response to easily locate the right request log OR find the relevant lines in a service’s log file.  Within each log area you may see an error log and an info log file. The error log is provided to give you a pointer on where to look. This view is great to help isolate and locate the error spots without going through the larger info log.  Once you have the pointer you can then delve into the info logs to obtain more specifics as needed.

At this point in your debugging from a log perspective you should have all of the information you need to troubleshoot your requests.  If there is an issue that is buried deeper in the architecture we have also created a verbose log. These are the logs that will likely be requested for you to send in if you are reporting a potential issue to Support.  There will also be a folder for Dexterity Service Control logs. These won't pertain to you as you are debugging issues you’ll come across because it details information for a piece of the service we use as part of the internal architecture and not one you’d interact with directly.

To round out this debugging post I’d like to briefly talk about some service management API hooks we’ve created on the GP Service Endpoint.  As you are working on the environment configuration you may find it helpful to know what tenants or hosts are available and retrieve more in-depth data on these. To do so you can utilize the following:

Management/RouterTable – provides a list of “known” tenants/instances
Management/Hosts – provides a list of host ID’s available
Management/Hosts/{HostID} – provides more information on a specific host such as the full machine name, if it is active, memory utilization percentage, etc

That is a brief overview of the new debugging tools around the service based architecture that will be available with the release of Dynamics GP 2015. As you move into creating your own service procedures remember that your previous methods for gathering debugging information will still be very valuable for you. Now with the additional pieces such as trace messages and the expanded logs available you can broaden that scope of information gathering to include events not only within Dexterity but happening outside of it as well. 

Happy Debugging!
Alice

Comments

• Anonymous
  December 10, 2014
  I've been trying to get the Service Based Architecture running on my development machine after the RTM of Dynamics GP 2015 shipped and I think I've gotten most of the way there, but I keep getting an error in the GPService log that says, "No hosts were available to process the request for tenant 'DefaultTenant'." I can't seem to find any more detail on why that would be the case in any of the other logs. Isn't it supposed to spin up a new host if one can't be found? Where would that process be logged?

• Anonymous
  December 10, 2014
  Similar problem, Dynamics GP and Web access no problem, but access to SBA return error 403.

• Anonymous
  December 11, 2014
  “No hosts were available…” means that the GPService does not know of any machines to forward the request to.  Either the Dexterity Service Control is not running, the Dexterity Service for that tenant isn’t running, or the configuration is incorrect with the tenant not pointing to the correct instance name.   I would first ensure that all three services are running to rule out a synchronization error (GP Service, GP Dexterity Service Control, and GP Dexterity Service for the instance). Secondly I would look at the Tenant Configuration file to ensure that it is pointing to the correct instance name and the accompanying information is correct to link up to that instance (especially Tenant name, Runtime application directory and Is Active).  One question may be are you running a single instance or was a named instance installed? The architecture will spin up a new Dexterity process when one is not available for a new request coming in but the hosts should already be active with the service fully aware of it/them.  If you are not able to track down the problem I would contact the Support team for more detailed debugging assistance. The Resource Links section on the right side of this page has direct links if needed.

• Anonymous
  December 12, 2014
  Regarding the second issue ("access to SBA return error 403"), there should be additional data in the response to indicate whether the issue is with login or security. In single tenant mode, a 403 for login reasons means the calling user's identity has not been mapped to a GP user OR company access is denied OR there could be an orphaned activity table record. A 403 for security reasons means the user has not been given access to the service procedure in question.

• Anonymous
  December 16, 2014
  Just to close the loop on my initial post, I got an answer to my issue on the community forum (community.dynamics.com/.../330956.aspx), which is where I should have posted this in the first place. Highlights:

• Another useful endpoint for the GP service is /Management/Diagnostics.
• My actual issue was that the Application Settings for my Tenant were incorrect. Unfortunately, as far as I could tell (and I checked every log listed above), I didn't see anything that told me that was the problem.

• Anonymous
  March 16, 2017
  Some great and helpful information here. Out of curiosity, have you published anything similar recently about 365? Would be a great help.