Tip #808: Tracing with Xrm Tooling in Azure Functions

By now you should be able to get your Azure Function triggered from Dynamics 365 and connect back to Dynamics 365 to do some evil awesome things. Debugging Azure Functions however, is not a walk in a park – not like you can set breakpoints and step through the code.

Well, you should, of course, write some nice classes doing the job, test them using test harness or, at very least, a simple console application and then refer to those classes in your Azure Function code.

If something goes wrong in production and you need to get to the bottom of it, all Azure Functions entry points provide TraceWriter that you can use to dump the information required. That’s in your code but what about mysterious internals of Xrm Tooling black box? What if your code cannot connect to Dynamics 365 instance?

TraceWriter is an abstract class implemented in Azure WebJobs SDK while Xrm Tooling utilizes System.Diagnostics Debug/Trace/TraceListener model.

Create additional file ToolingListener.csx

using System;
using System.Diagnostics;

// Log writter for working with Azure Functions 
// for the Xrm.Tooling.Connector
public class Toolinglistener : TraceListener
{
  private TraceWriter _log;

  public Toolinglistener(string name, 
            TraceWriter logger) : base(name)
  {
    _log = logger;
  }

  public override void Write(string message)
  {
    _log?.Info(message);
  }

  public override void WriteLine(
            string message)
  {
    _log?.Info(message);
  }
}

Then add the following to the original function:

#load "ToolingListener.csx"

using System;
using System.Diagnostics;
using Microsoft.Xrm.Tooling.Connector;

public static void Run(string input, TraceWriter log)
{
    TraceControlSettings.TraceLevel = SourceLevels.All;
    TraceControlSettings.AddTraceListener(
		new ToolingListener(
			"Microsoft.Xrm.Tooling.CrmConnectControl", 
			log));

And you should see very detailed output in your function log:


Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : Using User Specified Server
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : Trying Live Discovery Server, (North America) URI is = https://disco.crm.dynamics.com/XRMServices/2011/Discovery.svc
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Start: 256 : QueryLiveDiscoveryServer()
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : DiscoverOrganizations - Initializing Discovery Server Object with https://disco.crm.dynamics.com/XRMServices/2011/Discovery.svc
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : DiscoverOrganizations - attempting to connect to CRM server @ https://disco.crm.dynamics.com/XRMServices/2011/Discovery.svc
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : DiscoverOrganizations - created CRM server proxy configuration for https://disco.crm.dynamics.com/XRMServices/2011/Discovery.svc - duration: 00:00:11.1699811
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : DiscoverOrganizations - proxy requiring authentication type : OnlineFederation
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : DiscoverOrganizations - Authenticated via OnlineFederation. Auth Elapsed:00:00:03.2299574
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : DiscoverOrganizations - service proxy created - total create duration: 00:00:14.4031174
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : DiscoverOrganizations - Discovery Server Get Orgs Call Complete - Elapsed:00:00:15.9204376
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : Found 1 Org(s)
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Start: 256 : BuildOrgConnectUri CoreClass ()
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : DiscoveryServer indicated organization service location = https://foobar.api.crm.dynamics.com/XRMServices/2011/Organization.svc
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Stop: 512 : BuildOrgConnectUri CoreClass ()
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : Organization Service URI is = https://foobar.api.crm.dynamics.com/XRMServices/2011/Organization.svc
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : ConnectAndInitCrmOrgService - Initializing Organization Service Object
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : ConnectAndInitCrmOrgService - Requesting connection to Org with CRM Version: 8.2.0.764
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : ConnectAndInitCrmOrgService - Using ISerivceManagement
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : ConnectAndInitCrmOrgService - attempting to connect to CRM server @ https://foobar.api.crm.dynamics.com/XRMServices/2011/Organization.svc
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : ConnectAndInitCrmOrgService - created CRM server proxy configuration for https://foobar.api.crm.dynamics.com/XRMServices/2011/Organization.svc - duration: 00:00:37.6740783
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : ConnectAndInitCrmOrgService - proxy requiring authentication type : OnlineFederation
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : ConnectAndInitCrmOrgService - Authenticated via OnlineFederation. Auth Elapsed:00:00:00.5627215
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : ConnectAndInitCrmOrgService - service proxy created - total create duration: 00:00:38.2390845
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : ConnectAndInitCrmOrgService - Proxy created, total elapsed time: 00:00:38.2410960
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : User Org (org358a83d1) found in Discovery Server NorthAmerica - ONLY ORG FOUND
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : Beginning Validation of CRM Connection
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Information: 8 : Validation of CRM Connection Complete, total duration: 00:00:08.3293161
Microsoft.Xrm.Tooling.Connector.CrmServiceClient Verbose: 16 : New Batch Manager Created, Max #of Batches:50000, Max #of RequestsPerBatch:5000

Of course, the code takes a shortcut with log.Info and requires a bit of tuning like mapping logging levels from Connector to TraceWriter but those are the details we can live without, right?

Tweet about this on TwitterShare on Facebook0Share on Google+1

Leave a Reply

Your email address will not be published. Required fields are marked *