During the last few Days I have been having the not so pleasant experience of trying to find some really nasty errors in incoming emails to a queue in CRM. We are using CRM 2013 SP1 (on prem) and hence are using the Server Side Sync. Everything had been working great and we had developed some neat workflows that did some magic to convert emails to cases (as those features were not available, and not good enough either) when we develop our stuff.
Well, thing stopped working, I tried sending emails to the CRM server, but none were received in CRM. All I got in CRM was a not so descriptive general alert saying:
"An error occurred while creating incoming email in Microsoft Dynamics CRM for the mailbox XYZ. To view the email that failed, see the alerts in the mailbox record."
and in the mailbox:
"An error occurred while creating the incoming email "Test 1512" in Microsoft Dynamics CRM for the mailbox XYZ."
As I am working on my telepathic abilities, I have not yet reached a level where I can understand what is wrong so I had a look in the trace, and I was very happy I was running an on-prem server. It is a bit long, don't worry if you don't understand it all, nobody (I think) does.
[2015-05-15 15:21:13.459] Process:CrmAsyncService |Organization:673c5996-a1fa-e311-93ed-00155d0a831d |Thread: 4 |Category: Platform.Metadata |User: 00000000-0000-0000-0000-000000000000 |Level: Error |ReqId: | <>c__DisplayClass1.<LoadMetadataContainerFromDatabase>b__0 ilOffset = 0x14
>Multi-org sharable cache loading system and non-system metadata with build number 6.1.0.581 and language 1033
[2015-05-15 15:33:45.132] Process:CrmAsyncService |Organization:00000000-0000-0000-0000-000000000000 |Thread: 26 |Category: Exception |User: 00000000-0000-0000-0000-000000000000 |Level: Error |ReqId: cf367175-12a2-4719-a5af-f53f7f254399 | CrmException..ctor ilOffset = 0x7
at CrmException..ctor(String message, Exception innerException, Int32 errorCode, Boolean isFlowControlException) ilOffset = 0x7
at CrmException..ctor(String message, Exception innerException, Int32 errorCode) ilOffset = 0x5
at Exceptions.ThrowIfGuidEmpty(Guid parameter, String name) ilOffset = 0x18
at OrganizationSdkServiceInternal.Retrieve(String entityName, Guid id, ColumnSet columnSet, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, Boolean checkAdminMode) ilOffset = 0x16
at InprocessServiceProxy.RetrieveCore(String entityName, Guid id, ColumnSet columnSet) ilOffset = 0x28
at OrganizationServiceProxy.Retrieve(String entityName, Guid id, ColumnSet columnSet) ilOffset = 0x4
at EntityDictionary.TryRetrieveEntity(String key) ilOffset = 0xF8
at EntityDictionary.System.Collections.Generic.IDictionary<System.String,Microsoft.Xrm.Sdk.Entity>.get_Item(String key) ilOffset = 0x1B
at VisualBasicValue`1.Execute(CodeActivityContext context) ilOffset = 0x3A
at ActivityExecutor.ExecuteInResolutionContext(ActivityInstance parentInstance, Activity`1 expressionActivity) ilOffset = 0x35
at InArgument`1.TryPopulateValue(LocationEnvironment targetEnvironment, ActivityInstance activityInstance, ActivityExecutor executor) ilOffset = 0x2F
at ActivityInstance.InternalTryPopulateArgumentValueOrScheduleExpression(RuntimeArgument argument, Int32 nextArgumentIndex, ActivityExecutor executor, IDictionary`2 argumentValueOverrides, Location resultLocation, Boolean isDynamicUpdate) ilOffset = 0x16
at ActivityInstance.ResolveArguments(ActivityExecutor executor, IDictionary`2 argumentValueOverrides, Location resultLocation, Int32 startIndex) ilOffset = 0x9C
at ExecuteActivityWorkItem.ExecuteBody(ActivityExecutor executor, BookmarkManager bookmarkManager, Location resultLocation) ilOffset = 0x1C
at ActivityExecutor.OnExecuteWorkItem(WorkItem workItem) ilOffset = 0x53
at Callbacks.ExecuteWorkItem(WorkItem workItem) ilOffset = 0xD
at Scheduler.OnScheduledWork(Object state) ilOffset = 0xC5
at SendOrPostThunk.UnhandledExceptionFrame(Object state) ilOffset = 0x0
at PumpBasedSynchronizationContext.DoPump() ilOffset = 0x2E
at WorkflowApplication.Invoke(Activity activity, IDictionary`2 inputs, WorkflowInstanceExtensionManager extensions, TimeSpan timeout) ilOffset = 0x23
at WorkflowInvoker.Invoke(Activity workflow, IDictionary`2 inputs, TimeSpan timeout, WorkflowInstanceExtensionManager extensions) ilOffset = 0x36
at SynchronousWorkflowActivityHost.ExecuteWorkflowUsingInvoker(Activity workflow, ICommonWorkflowContext context) ilOffset = 0xD0
at SynchronousWorkflowActivityHost.StartWorkflow(WorkflowActivationData activationData, ICommonWorkflowContext context) ilOffset = 0x73
at SynchronousWorkflowActivityHost.StartWorkflow(ICommonWorkflowContext context) ilOffset = 0xBA
at WorkflowProcessServiceInternalHandler`1.ExecuteSyncWorkflow(Guid workflowId, PipelineExecutionContext pipelineContext, IGenericEventData workflowInstanceData, Boolean isTriggered) ilOffset = 0x59
at WorkflowProcessServiceInternalHandler`1.ExecuteTriggeredSyncWorkflow(Guid workflowId, PipelineExecutionContext pipelineContext) ilOffset = 0x21
at SyncWorkflowExecutionPlugin.Execute(IServiceProvider provider) ilOffset = 0x2C
at V5PluginProxyStep.ExecuteInternal(PipelineExecutionContext context) ilOffset = 0x2A3
at VersionedPluginProxyStepBase.Execute(PipelineExecutionContext context) ilOffset = 0x65
at Pipeline.Execute(PipelineExecutionContext context) ilOffset = 0x65
at MessageProcessor.Execute(PipelineExecutionContext context) ilOffset = 0x1FB
at InternalMessageDispatcher.Execute(PipelineExecutionContext context) ilOffset = 0xE4
at ExtensiblePlatformMessageDispatcher.Execute(PipelineExecutionContext pluginContext) ilOffset = 0x0
at ExtensiblePlatformMessageDispatcher.CreateWithInvocationSource(BusinessEntity entity, Int32 invocationSource, ExecutionContext context) ilOffset = 0xB4
at BusinessProcessObject.Create(IBusinessEntity entity, ExecutionContext context) ilOffset = 0x54
at GenericActivityServiceBase.Create(IBusinessEntity entity, ExecutionContext context) ilOffset = 0xA1
at CommunicationActivityServiceBase.Create(IBusinessEntity entity, ExecutionContext context) ilOffset = 0x1A
at EmailService.SetRecipientsAddAdditionalAttributeAndCreate(AddressEntry[][] allResolvedAddressEntries, Email email, Entity emailDeltaEntity, String traceSubject, ExecutionContext context) ilOffset = 0x1DA
at EmailService.Deliver(Boolean userPromote, Guid emailId, String messageId, String subject, String from, String to, String cc, String bcc, DateTime receivedOn, String submittedBy, String importance, String body, BusinessEntityCollection attachments, Guid campaignResponseId, Entity emailDeltaEntity, ExecutionContext context, Boolean validateBeforeDeliver) ilOffset = 0x524
at EmailService.DeliverIncoming(String messageId, String subject, String from, String to, String cc, String bcc, DateTime receivedOn, String submittedBy, String importance, String body, BusinessEntityCollection attachments, Entity extraProperties, Boolean validateBeforeCreate, ExecutionContext context) ilOffset = 0xB8
at RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) ilOffset = 0xFFFFFFFF
at RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) ilOffset = 0x25
at RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) ilOffset = 0xCF
at LogicalMethodInfo.Invoke(Object target, Object[] values) ilOffset = 0x4F
at InternalOperationPlugin.Execute(IServiceProvider serviceProvider) ilOffset = 0x57
at V5PluginProxyStep.ExecuteInternal(PipelineExecutionContext context) ilOffset = 0x200
at VersionedPluginProxyStepBase.Execute(PipelineExecutionContext context) ilOffset = 0x65
at Pipeline.Execute(PipelineExecutionContext context) ilOffset = 0x65
at MessageProcessor.Execute(PipelineExecutionContext context) ilOffset = 0x1C5
at InternalMessageDispatcher.Execute(PipelineExecutionContext context) ilOffset = 0xE4
at ExternalMessageDispatcher.ExecuteInternal(IInProcessOrganizationServiceFactory serviceFactory, IPlatformMessageDispatcherFactory dispatcherFactory, String messageName, String requestName, Int32 primaryObjectTypeCode, Int32 secondaryObjectTypeCode, ParameterCollection fields, CorrelationToken correlationToken, CallerOriginToken originToken, UserAuth userAuth, Guid callerId, Guid transactionContextId, Int32 invocationSource, Nullable`1 requestId, Version endpointVersion) ilOffset = 0x16E
at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, UserAuth userAuth, Guid targetUserId, OrganizationContext context, Boolean returnResponse, Boolean checkAdminMode) ilOffset = 0x1F1
at OrganizationSdkServiceInternal.ExecuteRequest(OrganizationRequest request, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, Boolean checkAdminMode) ilOffset = 0x2D
at OrganizationSdkServiceInternal.Execute(OrganizationRequest request, CorrelationToken correlationToken, CallerOriginToken callerOriginToken, WebServiceType serviceType, Boolean checkAdminMode) ilOffset = 0x26
at InprocessServiceProxy.ExecuteCore(OrganizationRequest request) ilOffset = 0x34
at IncomingEmailProviderBase.DeliverMessageInternal(EmailMessage emailMessage, Boolean validateBeforeCreate) ilOffset = 0x1B7
at IncomingEmailProviderBase.DeliverMessage(EmailMessage emailMessage, Boolean validateBeforeCreate) ilOffset = 0x19
at GetItemsStep.ProcessResponse() ilOffset = 0x5AB
at ExchangeIncomingEmailProviderStep.EndOperation() ilOffset = 0xFC
at ExchangeIncomingEmailProvider.ReceiveEmails() ilOffset = 0x92
at IncomingActivityProviderBase.Run() ilOffset = 0x42
at MailboxEmailOperation.PerformOperation() ilOffset = 0x2C
at MailboxOperationBase`1.Execute() ilOffset = 0xAA
at MailboxProcessingOperation.PerformOperation() ilOffset = 0x1A
at MailboxOperationBase`1.Execute() ilOffset = 0xAA
at MailboxOperationCommand.InternalExecute(MailboxAsyncEvent asyncEvent) ilOffset = 0x64
at AsyncCallbackHandler`2.ResumeExecution(IAsyncEvent asyncEvent) ilOffset = 0x56
at AsyncEventExecutionManager`2.ExecuteHandler(IAsyncEventHandlerFactory handlerFactory) ilOffset = 0x8A
at PoolHandler.ProcessAsyncEvent(IAsyncEventExecutionManager asyncEventExecutionManager) ilOffset = 0x144
at AsyncEventOperation.<.ctor>b__2(IServiceOperation operation) ilOffset = 0x0
at FaultToleranceBehavior.Execute(ServiceOperationAction operation, IServiceOperation operationParameter) ilOffset = 0x18
at MonitoredOperation.Execute() ilOffset = 0xD
at ThreadPoolQueueExecutionEngine.InvokeNextOperationInThreadPool(Object state) ilOffset = 0xC
at ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) ilOffset = 0x70
at ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) ilOffset = 0x4
at QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() ilOffset = 0x30
at ThreadPoolWorkQueue.Dispatch() ilOffset = 0xA3
>Crm Exception: Message: Expected non-empty Guid., ErrorCode: -2147220989, InnerException: System.ArgumentException: Expected non-empty Guid.
Parameter name: id
[2015-05-15 15:33:45.304] Process:CrmAsyncService |Organization:00000000-0000-0000-0000-000000000000 |Thread: 26 |Category: Platform |User: 00000000-0000-0000-0000-000000000000 |Level: Error |ReqId: cf367175-12a2-4719-a5af-f53f7f254399 | ExceptionConverter.ConvertToFault ilOffset = 0x69
>UNEXPECTED: no fault?
My first thought was that the stack trace was really long... and then there was some mentioning of User with Guid 00000000-0000-0000-0000-000000000000.
.jpg) |
| Another kind of queue ticket |
I then revoked admin access and started re-enabling each single workflow/plugin until thing started
breaking again. This turned out to be a painstaking process as the only way I found to test this was to send an email to CRM and then wait for about 5 minutes until it was/or was not pulled into the queue.
It took me more or less a days work just to find the two workflows that were causing the problems.
The actual problems in them selves, arn't really that interesting, it turned out that the error message above was actually quite correct, If you try to set a null-user to an owner field, CRM will respond like this.
What I did notice however was that the workflows that we were using on "queue item" in this case were synchronous (yes, yes, we do have good reasons for it, I hope you do to, Otherwise, please choose asynchronous/background workflows) and as they broke, CRM did two interesting facts that are not very desirable and noteworthy:
- The mailbox was shut down for further email processing. It had to be "Test and Enabled" to start receiving emails again. I have yet to see a good way to do this in an automated fashion and to be able to monitor the mailboxes to see if they are working as expected.
- The email that was the cause of the breaking of the workflow, got lost. Even after the mailbox got reactivated, it had marked this email as read and did not read it into CRM despite the fact that it was neither in the queue nor as a lone activity which might have been the case if the Creation of the queue item broke. But obviously the entire process is handled atomically.
- If possible try to avoid an synchronous logic on receiving email or Creation of queue items. Try to move logic to asynchronous as this will cause errors to be non-fatal, like the two types of effects that are hard to handle above.
- If you do need to have synchronous logic on the receiving of emails or Creation of queue items try to add conditions in the beginning that will ensure that the logic only runs in those very specific cases where they are supposed to. Be aware of the fact that queue items can be associated to many different entities, so don't rely on the fact that they should be only connected to something specific. At least take into consideration the fact that they will be connected to emails at some Point in time.
- I read an interesting fact today, that the activation of business rules Controls in which order they will be executed. If you are using CRM 2015 with server side (Entity) scope, this could probably cause similar issues if the activation is done haphazardly and causes the execution to be done in a way that can cause a bug and break processing of the queue item or email. I havn't checked if these are run pre- or poststate but I think that depends on the action.
- If you get errors, especially when using CRM Online, try to replicate the error in the sandbox Environment and then either move backwards to a Point where it starts working again, or deactive Everything related to emails and queue items, make sure it works, and move forward. When you know where the error is, finding what the error is, is so much easier.
We also found a related bug in CRM today, if you try to create an asynchronous workflow that triggers on a field which has field based rights activated on it, it will break, with some weird error message about not being able to change domain for the user. The simple fix for that is to make the workflow synchronous and to make it run as the user that activates it, that worked. We didn't try to run it as the user who created the workflow, as that is the same logic that is used in asynchronous workflows, I wasn't too keen on trying something that was more likely to fail. If you have tried it, please leave a comment below.
I hope to see a lot of people tomorrow on the 19:th at the Swedish CRM UG Meeting!
Gustaf Westerlund
MVP, Founder and CTO at CRM-konsulterna AB
www.crmkonsulterna.se
