Email Router Demystified – Tools for Troubleshooting - Email Router Logging

Author note: As you’ll notice with most of my blog posts, they tend to have a lot of information and are a bit long.  Instead of sacrificing content, I’ll break up the posts into a series for posts.  This way people don’t get overwhelmed with the amount of content but for those that want the deep technical details, they get that as well. 

This article covers Email Router Logging and is the first article within the Email Router Demystified – Tools for Troubleshooting blog series.  To get to a list of the other tools, go HERE.

Email Router logging is a good starting point to try and collect some data.  Sometimes you need to see what is happening prior to the exception to really understand what is going on.  In other instances, you just want to make sure that a mailbox is being processed.  Email Router Logging is pretty simple to setup once you understand what you are doing.  Let’s take a look at this now.

If you are familiar with setting up tracing or logging for Microsoft Dynamics CRM, you’ll find that configuring logging for the Email Router is completely different.  It requires us to modify an XML document that is used by the Email Router service.

Now this may sound a little silly but before you can enable Email Router Logging, you need to make sure that you have configured the Email Router using the Email Router Configuration Manager.  The reason this is needed is that the Configuration and Deployment profiles as well as any user/queue/forward mailbox profiles get added to the file we need to modify to enable logging.

Logging is enabled within the following file:

 C:\Program Files\Microsoft CRM Email\Service\Microsoft.Crm.Tools.EmailAgent.xml

From here on, I will refer to this document as EmailAgent.xml.  You can open this file up with Notepad if you don’t have an XML editor.  There are a few available for free on the interwebs so do some searching if you get lost in the XML format in Notepad.

Important Elements

After opening up EmailAgent.xml, you may get a little overwhelmed if you have a lot of users or if you have a lot of profiles.  Don’t be afraid, this is a lot easier than what it looks like.  Let’s first take a look at how we can navigate our way through this file. 

<ConfigUpdatePeriod>

We’ll first talk about ConfigUpdatePeriod.  This is found in the <SystemConfiguration> of this file.  This element controls when the Email Router is going to make automatic updates to the EmailAgent.xml file.  Essentially, if a new user is added in to CRM, this setting should not require you to open the Email Router Configuration Manager, click on Load Data, and then Publish.  It SHOULD automatically handle this.  The reason this is going to be important is that we don’t want the file to update on us while we have logging going.

<Direction>

Each user that is configured to use the Email Router for incoming will have their own incoming provider stored within the <ProviderConfiguration>element.  The provider is what handles the processing of that user’s mailbox.  For outgoing, there is one for each outgoing configuration profile you created.  All of the users and/or queues set to use that Configuration Profile will be listed within that ProviderConfiguration.  There are a couple of elements within the EmailAgent.xml file that leads us to understand if it is an incoming or outgoing profile.  However, the easiest element is<Direction>which is found within<ProviderConfiguration>. For a provider accessing a user’s Mailbox, the direction will be “Inbound”.  For a provider sending email out for a user and/or queue, the direction will be “Outbound”.

<EmailAddress>

For incoming providers,<EmailAddress>element helps us isolate which email address will be processed by the provider.  Again, this is only for incoming.

<UserId>or<QueueId>

For outgoing providers, you will need to know the user’s or queue’s GUID.  The easiest way of finding this out is by opening up the User or Queue and choose the “Email a Link” option on a workstation with an email application like Outlook:

From there, you parse through the URL and find the id parameter.  Then get past =%7b and copy everything between that and %7d.  Those are URI values for the curly {} braces:

https://crmsql:444/CRM/main.aspx?etc=8&extraqs=formid%3dc2cd9e55-d4b4-4b55-9951-16ead79643e5&id=%7b7472458D-28DB-E511-80E0-001DD8B98504%7d&pagetype=entityrecord

In this case, Alan Jackson’s UserId of GUID is 7472458D-28DB-E511-80E0-001DD8B98504.

Configuration

Ok that was a lot of information.  Why do we have to know all of that before we talked about configuring of Email Router logging?  The reason is that to enable logging, we need to know what provider to set logging for.  This will allow us to get information specific to the account we are working on.  So to set logging, we simply need to add a couple of elements:

<LogLevel>- This element controls how much information we get back for that provider.  The following values determine the level of …. logging …. we enable.

• 0. No logging.
• 1. Error logging only. By default, logging is set to 1.
• 2. Detailed information logging at the mailbox level
• 3. Very detailed information logging at the message level.

 <LogFile>- If we don’t specify a LogFile, it’s going to write all of the EmailRouter events to the Event Viewer.  The reason I raise this as important is because if we don’t output the details to a file, it gets dumped into the Event Viewer by default.  From there, you have to dig through and arrange the data within the Event Viewer.  When outputting it to a log file, it allows us to separate each provider and see the events sequentially very easily.

So we need to add<LogLevel>and<LogFile>but where?

Wait not so fast.  The first thing I’d suggest is to backup the EmailAgent.xml file.  If you really mess something up, you could cause some serious detrimental effect that would require you to go search for a vanilla version of the EmailAgent.xml file.  Then you would have to go through and open the Email Router Configuration Manager and Load Data and Publish the results. 

After you have backed up the file, we need to make sure the router service doesn’t overwrite our logging settings.  To do that, we need to make sure and update<ConfigUpdatePeriod>to 0.  Remember the default value is 3600000.

Now that we have that out of the way, let’s go ahead and set the logging elements.  We are going to add them within the<ProviderConfiguration>that we need to trace.  For instance, if I have a user named Alan Jackson and he mentions that he cannot find emails within Microsoft Dynamics CRM that should be within CRM.  We want to enable tracing for incoming for his mailbox.  So I take what we learned above and apply that.  I first look for Alan’s<EmailAddress>. There should only be one of them.  Additionally, I validate I’m in the right provider by confirming the<Direction>.  Once I have done that, I’m now ready to set the logging elements. 

You can set these, really, anywhere within the<ProviderConfiguration>. Personally, I like setting it right below the<EmailAddress>.  The reason is that it’s easy to identify whom I’m tracing and what file I’m writing to.

A couple of notes about this:

1. Ensure you have permission to write to the EmailAgent.xml file.  To do this, simply right-click on the file and go to Properties and then click on Security.  Ensure the user you are making the changes to has “Full control” to the file:
   
   
2. The file you are writing to, in this case it’s ER_Logging_Ajackson_Incoming.txt does not need to already exist.  The Email Router will create it if it doesn’t already.  If it does, it will simply append to the existing data in the file.
3. The Email Router SERVICE account needs to be able to write to the folder location you specify.  In my case, it’s my Administrator account:

LogFile

Now that we have logging enabled, let’s take a look at the log itself:

Here I can see what the Email Router was doing.  I can see that the Email Router was able to open the mailbox, check if there are emails, validated there were no emails, and then closed the mailbox. 

So let’s send a test email and see what happens.  I sent a simple email from Outlook to Alan Jackson:

This is what the log had to say about it:

If you follow the logging from the top down, you will see that the email was picked up.  Now, look at line 10 (counting the line wraps):

MM/DD/YYYY 16:11:50 : #60263 - The email message with subject "Test the Email Router Logging - No Track" in mailbox ajackson@contoso.local for delivery to https://crmsql:444/CRM was rejected. Reason: NoCorrelationMatch.

So this email was rejected because there was no correlation meaning that it’s not a CRM email.  If I look at Alan Jackson’s personal options, I can see he’s should only be tracking CRM emails:

Now the information we see here is pretty limited in regards to understanding what exactly is the Email Router doing.  The best details we get is from an exception when we see all of the stack.  Seeing the stack of the trace is SUPER important as it helps us understand if this is a CRM issue or an Exchange issue:

MM/DD/YYYY 15:55:54 : #26090 - An error occurred while opening mailbox ajackson@contoso.local. System.Web.Services.Protocols.SoapException: The account does not have permission to impersonate the requested user.
   at System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)
   at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)
   at Microsoft.Crm.Tools.Email.Providers.ExchangeServiceBinding.GetFolder(GetFolderType GetFolder1)
   at Microsoft.Crm.Tools.Email.Providers.ExchangeWSConnector.OpenMailbox()
   at Microsoft.Crm.Tools.Email.Providers.ExchangePollingMailboxProvider.InitExchangeConnector()
   at Microsoft.Crm.Tools.Email.Providers.ExchangePollingMailboxProvider.OpenMailbox()
   at Microsoft.Crm.Tools.Email.Providers.CrmPollingMailboxProvider.Run()\r\nErrorImpersonateUserDeniedThe account does not have permission to impersonate the requested user.

In this exception, we can see that we are doing an ExchangeServiceBinding for GetFolder.  If we do a quick search for GetFolder and Exchange, we get an article that can give us more information about that:

https://msdn.microsoft.com/en-us/library/office/aa580274(v=exchg.150).aspx

This particular error message is an Exchange error.  But what exactly is CRM doing within Exchange that is causing this error.  That’s where the next tool comes into play.