[GH-ISSUE #112 ] Event 1057, MSExchange Extensibility - Agent &#39;Exchange DkimSigner&#39; went async #88

Author

Owner

@AlexLaroche commented on GitHub (Nov 19, 2015):

Which version of the agent is used ?

@AlexLaroche commented on GitHub (Nov 19, 2015): Which version of the agent is used ?

kerem commented

Author

Owner

@Pro commented on GitHub (Nov 21, 2015):

We fixed this already in the current version (see #97).
If you are using the current version (2.1.8) and the problem stil persists, please reopen this thread.

@Pro commented on GitHub (Nov 21, 2015): We fixed this already in the current version (see #97). If you are using the current version (2.1.8) and the problem stil persists, please reopen this thread.

kerem commented

Author

Owner

@mrrogers75 commented on GitHub (Dec 17, 2015):

I am having this issue in 2.1.8

@mrrogers75 commented on GitHub (Dec 17, 2015): I am having this issue in 2.1.8

kerem commented

Author

Owner

@Pro commented on GitHub (Dec 17, 2015):

@mrrogers75 what is your windows version? Exchange version (including SP and Updates)?

@Pro commented on GitHub (Dec 17, 2015): @mrrogers75 what is your windows version? Exchange version (including SP and Updates)?

kerem commented

Author

Owner

@mrrogers75 commented on GitHub (Dec 17, 2015):

Windows Server 2012 R2 with Exchange 2013 SP1 CU 10
On Dec 17, 2015 2:38 PM, "Stefan Profanter" notifications@github.com
wrote:

@mrrogers75 https://github.com/mrrogers75 what is your windows version?
Exchange version (including SP and Updates)?

—
Reply to this email directly or view it on GitHub
https://github.com/Pro/dkim-exchange/issues/112#issuecomment-165558984.

@mrrogers75 commented on GitHub (Dec 17, 2015): Windows Server 2012 R2 with Exchange 2013 SP1 CU 10 On Dec 17, 2015 2:38 PM, "Stefan Profanter" notifications@github.com wrote: > @mrrogers75 https://github.com/mrrogers75 what is your windows version? > Exchange version (including SP and Updates)? > > — > Reply to this email directly or view it on GitHub > https://github.com/Pro/dkim-exchange/issues/112#issuecomment-165558984.

kerem commented

Author

Owner

@gogglespisano commented on GitHub (Jan 1, 2016):

Shouldn't GetAgentAsyncContext() be called from the original thread, then Resume() called in the worker thread?

Wouldn't it be better to queue the processing on a ThreadPool thread rather than creating a new thread for every email message?

@gogglespisano commented on GitHub (Jan 1, 2016): Shouldn't GetAgentAsyncContext() be called from the original thread, then Resume() called in the worker thread? Wouldn't it be better to queue the processing on a ThreadPool thread rather than creating a new thread for every email message?

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 2, 2016):

@gogglespisano thanks for the info. Changed in github.com/Pro/dkim-exchange@0e4f1c6b79

@Pro commented on GitHub (Jan 2, 2016): @gogglespisano thanks for the info. Changed in https://github.com/Pro/dkim-exchange/commit/0e4f1c6b794f6f6462af971c840550801db751ae

kerem commented

Author

Owner

@gogglespisano commented on GitHub (Jan 19, 2016):

I wonder if the agent is using the thread pool to process the message, and then the "new" thread is the same thread pool thread being used for the Resume call.

Or maybe the event message is trying to tell us something else and it's just a poor message.

@gogglespisano commented on GitHub (Jan 19, 2016): I wonder if the agent is using the thread pool to process the message, and then the "new" thread is the same thread pool thread being used for the Resume call. Or maybe the event message is trying to tell us something else and it's just a poor message.

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

It looks like the problem still exists, as by @lukehamburg reported in bug #136.

According to the official Microsoft Sample code, the current way we handle AsyncContext should be fine...
http://www.getcodesamples.com/src/D062E1E9/2552BA7

The only difference I see is:

ThreadPool.QueueUserWorkItem(new WaitCallback(HandleMessageEvent), e.MailItem);

compared to the sample code

ThreadPool.QueueUserWorkItem(this.HandleMessageEvent, e.MailItem);

But this should be the same (see http://stackoverflow.com/a/15695940/869402)

@Pro commented on GitHub (Jan 19, 2016): It looks like the problem still exists, as by @lukehamburg reported in bug #136. According to the official Microsoft Sample code, the current way we handle AsyncContext should be fine... http://www.getcodesamples.com/src/D062E1E9/2552BA7 The only difference I see is: ``` ThreadPool.QueueUserWorkItem(new WaitCallback(HandleMessageEvent), e.MailItem); ``` compared to the sample code ``` ThreadPool.QueueUserWorkItem(this.HandleMessageEvent, e.MailItem); ``` But this should be the same (see http://stackoverflow.com/a/15695940/869402)

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

@gogglespisano this may be a valid point. So one way to test it would be to create our own Thread instead of using the ThreadPool.
As it was in github.com/Pro/dkim-exchange@7eee8db425

@Pro commented on GitHub (Jan 19, 2016): @gogglespisano this may be a valid point. So one way to test it would be to create our own Thread instead of using the ThreadPool. As it was in https://github.com/Pro/dkim-exchange/commit/7eee8db42588d4b4f7d1bbadcc84fa082ee1f907

kerem commented

Author

Owner

@gogglespisano commented on GitHub (Jan 19, 2016):

Is it possible this condition is not getting set correctly?

#if !EX_2007_SP3

@gogglespisano commented on GitHub (Jan 19, 2016): Is it possible this condition is not getting set correctly? #if !EX_2007_SP3

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

The only place where this define is set is at https://github.com/Pro/dkim-exchange/blob/master/Src/Exchange.DkimSigner/Exchange.DkimSigner.csproj#L36
So it should be correct, but I'll try to do some debugging to see if it is set correctly.

@Pro commented on GitHub (Jan 19, 2016): The only place where this define is set is at https://github.com/Pro/dkim-exchange/blob/master/Src/Exchange.DkimSigner/Exchange.DkimSigner.csproj#L36 So it should be correct, but I'll try to do some debugging to see if it is set correctly.

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

#if !EX_2007_SP3 is set correctly. I just checked it.
So the .Resume call is definitely compiled.

@Pro commented on GitHub (Jan 19, 2016): `#if !EX_2007_SP3` is set correctly. I just checked it. So the .Resume call is definitely compiled.

kerem commented

Author

Owner

@luckman212 commented on GitHub (Jan 19, 2016):

@gogglespisano asked in #136 before it was closed: "What is the ratio of the event messages to emails processed? is it 1:1 or something much different?".

I am not sure how to scientifically answer this, but we've sent a few hundred emails since the DkimSigner was installed around 2am EST this morning the event 1057 has only been logged 9 times.

@luckman212 commented on GitHub (Jan 19, 2016): @gogglespisano asked in #136 before it was closed: _"What is the ratio of the event messages to emails processed? is it 1:1 or something much different?"_. I am not sure how to scientifically answer this, but we've sent a few hundred emails since the DkimSigner was installed around 2am EST this morning the event 1057 has only been logged 9 times.

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

Thanks for the info. So this means that it is not logged for every mail.
Are there any error messages or other warnings in the DKIM signer log around that time when the 1057 Event is logged?

@Pro commented on GitHub (Jan 19, 2016): Thanks for the info. So this means that it is not logged for every mail. Are there any error messages or other warnings in the DKIM signer log around that time when the 1057 Event is logged?

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

@lukehamburg Can you enable Debug Logging and wait until the next 1057 event is logged and check the debug messages in the Event Log?

@Pro commented on GitHub (Jan 19, 2016): @lukehamburg Can you enable Debug Logging and wait until the next 1057 event is logged and check the debug messages in the Event Log?

kerem commented

Author

Owner

@gogglespisano commented on GitHub (Jan 19, 2016):

I wonder if the relatively small percentage of times it's happening could be reuse of the same thread pool thread.

@gogglespisano commented on GitHub (Jan 19, 2016): I wonder if the relatively small percentage of times it's happening could be reuse of the same thread pool thread.

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 19, 2016):

That could be the case since ThreadPool is shared for the whole process. The signer .dll is loaded into the EdgeTransport.exe process and thus it may be the case that exchange uses the same ThreadPool internally.

To investigate that further, a Debug output of Thread.CurrentThread.ManagedThreadId may help.
Or we could switch to use Task instead (https://msdn.microsoft.com/en-us/library/system.threading.tasks.task%28VS.100%29.aspx)

@Pro commented on GitHub (Jan 19, 2016): That could be the case since ThreadPool is shared for the whole process. The signer .dll is loaded into the EdgeTransport.exe process and thus it may be the case that exchange uses the same ThreadPool internally. To investigate that further, a Debug output of `Thread.CurrentThread.ManagedThreadId` may help. Or we could switch to use Task instead (https://msdn.microsoft.com/en-us/library/system.threading.tasks.task%28VS.100%29.aspx)

kerem commented

Author

Owner

@gogglespisano commented on GitHub (Jan 19, 2016):

I would try to find out if the thread reuse is the actual problem before trying something like the Task.

@gogglespisano commented on GitHub (Jan 19, 2016): I would try to find out if the thread reuse is the actual problem before trying something like the Task.

kerem commented

Author

Owner

@AlexLaroche commented on GitHub (Jan 20, 2016):

@Pro: Have you try something like that to solve the problem?

private void HandleMessageEvent(Object mailItem)
{
    #if !EX_2007_SP3 //not supported in Exchange 2007
    // This allows Transport poison detection to correclty handle this message
    // if there is a crash on this thread.
    agentAsyncContext.Resume();
    #endif

    try
    {
        SignMailItem((MailItem)mailItem);
    }
    catch (Exception ex)
    {
        Logger.LogError("Signing a mail item according to DKIM failed with an exception. Check the logged exception for details.\n" + ex);
    }

    agentAsyncContext.Complete();
    agentAsyncContext = null;
}

@AlexLaroche commented on GitHub (Jan 20, 2016): @Pro: Have you try something like that to solve the problem? ``` private void HandleMessageEvent(Object mailItem) { #if !EX_2007_SP3 //not supported in Exchange 2007 // This allows Transport poison detection to correclty handle this message // if there is a crash on this thread. agentAsyncContext.Resume(); #endif try { SignMailItem((MailItem)mailItem); } catch (Exception ex) { Logger.LogError("Signing a mail item according to DKIM failed with an exception. Check the logged exception for details.\n" + ex); } agentAsyncContext.Complete(); agentAsyncContext = null; } ```

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 20, 2016):

@AlexLaroche the only change in your code is that you moved the agentAsyncContext outside of the try catch. Am I right?
I don't think that this changes anything.

What I'll try to do is to see if Thread.CurrentThread.ManagedThreadId can be used to identify the thread within a ThreadPool and add some debug output to check if Exchange uses the same thread as the Signer.

@Pro commented on GitHub (Jan 20, 2016): @AlexLaroche the only change in your code is that you moved the agentAsyncContext outside of the try catch. Am I right? I don't think that this changes anything. What I'll try to do is to see if `Thread.CurrentThread.ManagedThreadId` can be used to identify the thread within a ThreadPool and add some debug output to check if Exchange uses the same thread as the Signer.

kerem commented

Author

Owner

@AlexLaroche commented on GitHub (Jan 20, 2016):

@Pro : It is a best practice to call AsyncAgentContext.Resume() in your worker thread before doing any work to complete the event. This ensures that the thread is properly initialized for asynchronous event handling.

If you check à MSIL (Microsoft Intermediate Language) level you will see that the code generate is different. Is the try catch block is interpreted as instruction before AsyncAgentContext.Resume()? I know is sound crazy but we could give a try. It's just a suggestion.

@AlexLaroche commented on GitHub (Jan 20, 2016): @Pro : It is a best practice to call AsyncAgentContext.Resume() in your worker thread **before doing any work to complete the event**. This ensures that the thread is properly initialized for asynchronous event handling. If you check à MSIL (Microsoft Intermediate Language) level you will see that the code generate is different. Is the try catch block is interpreted as instruction before AsyncAgentContext.Resume()? I know is sound crazy but we could give a try. It's just a suggestion.

kerem commented

Author

Owner

@luckman212 commented on GitHub (Feb 27, 2016):

@Pro I installed 3.0.2 today. Still getting these in the Event Log. I was going to try to enable Debug Logging as you said, but not quite sure how to do that. Do I just set 5 in the settings.xml or something like that?

@luckman212 commented on GitHub (Feb 27, 2016): @Pro I installed 3.0.2 today. Still getting these in the Event Log. I was going to try to enable Debug Logging as you said, but not quite sure how to do that. Do I just set <Loglevel>5</Loglevel> in the settings.xml or something like that?

kerem commented

Author

Owner

@Pro commented on GitHub (Feb 27, 2016):

Yes unfortunately I didn't find any fix for this log entry yet. I need to investigate that further. I think there might be some race condition.

Anyways this doesn't have any impact on the functionality of the DKIM signer.

@lukehamburg you can try to enable Debug (set 4 in settings.xml) and check if the Event Log is fired if two mails are send nearly at the same time. Maybe there is also some other correlation between the 1057 event and debug outputs of the signer.

@Pro commented on GitHub (Feb 27, 2016): Yes unfortunately I didn't find any fix for this log entry yet. I need to investigate that further. I think there might be some race condition. Anyways this doesn't have any impact on the functionality of the DKIM signer. @lukehamburg you can try to enable Debug (set 4 in settings.xml) and check if the Event Log is fired if two mails are send nearly at the same time. Maybe there is also some other correlation between the 1057 event and debug outputs of the signer.

kerem commented

Author

Owner

@supermistag commented on GitHub (Nov 25, 2016):

Had the same issue in our Agent, spent a bit of time trying various locations for the .Resume() and eventually nailed it.

                // Call resume RIGHT BEFORE you call complete
                // This is a poorly documented option to get rid of the 
                // "Agent '' went async but did not call Resume on the new thread error"
                agentAsyncContext.Resume();

                // This allows Exchange to continue processing the message
                agentAsyncContext.Complete();

The documentation on the interweb kind of infers you should call .Resume before doing any work to COMPLETE the event. Not sure what else can be called other than Complete(), maybe a research for another day ...

Hope this helps. I see many other agents suffering the same problem.

@supermistag commented on GitHub (Nov 25, 2016): Had the same issue in our Agent, spent a bit of time trying various locations for the .Resume() and eventually nailed it. ``` // Call resume RIGHT BEFORE you call complete // This is a poorly documented option to get rid of the // "Agent '' went async but did not call Resume on the new thread error" agentAsyncContext.Resume(); // This allows Exchange to continue processing the message agentAsyncContext.Complete(); ``` The documentation on the interweb kind of infers you should call .Resume before doing any work to COMPLETE the event. Not sure what else can be called other than Complete(), maybe a research for another day ... Hope this helps. I see many other agents suffering the same problem.

kerem commented

Author

Owner

@BrianDrab commented on GitHub (Jan 5, 2018):

We are encountering the same issue.
Exchange Version: 15.1.1261.35
DKIM Signer Version: 3.0.12
Windows Server Version 6.3 (Build 9600) aka Server 2012 R2

Is this an error we should just ignore?

@BrianDrab commented on GitHub (Jan 5, 2018): We are encountering the same issue. Exchange Version: 15.1.1261.35 DKIM Signer Version: 3.0.12 Windows Server Version 6.3 (Build 9600) aka Server 2012 R2 Is this an error we should just ignore?

kerem commented

Author

Owner

@Pro commented on GitHub (Jan 14, 2018):

You can probably just ignore this message, since it doesn't impact the functionality of the signer

@Pro commented on GitHub (Jan 14, 2018): You can probably just ignore this message, since it doesn't impact the functionality of the signer

kerem commented

Author

Owner

@supermistag commented on GitHub (Jan 15, 2018):

Ignoring an error in the event log becomes bad practice IMHO.

As per my above post, the fix in the code is fairly simple - moving the .resume to just before .complete

try
            {
                SignMailItem((MailItem)mailItem);
            }
            catch (Exception ex)
            {
                Logger.LogError("Signing a mail item according to DKIM failed with an exception. Check the logged exception for details.\n" + ex);
            }
            finally
            {
#if !EX_2007_SP3 //not supported in Exchange 2007
                // This allows Transport poison detection to correclty handle this message
                // if there is a crash on this thread.
                agentAsyncContext.Resume();
#endif
                agentAsyncContext.Complete();
                agentAsyncContext = null;
            }

@supermistag commented on GitHub (Jan 15, 2018): Ignoring an error in the event log becomes bad practice IMHO. As per my above post, the fix in the code is fairly simple - moving the .resume to just before .complete ``` try { SignMailItem((MailItem)mailItem); } catch (Exception ex) { Logger.LogError("Signing a mail item according to DKIM failed with an exception. Check the logged exception for details.\n" + ex); } finally { #if !EX_2007_SP3 //not supported in Exchange 2007 // This allows Transport poison detection to correclty handle this message // if there is a crash on this thread. agentAsyncContext.Resume(); #endif agentAsyncContext.Complete(); agentAsyncContext = null; } ```

kerem commented

Author

Owner

@BrianDrab commented on GitHub (Jan 15, 2018):

I saw that but can you tell me the file I can make this code change in or is it something a developer has to do?

@BrianDrab commented on GitHub (Jan 15, 2018): I saw that but can you tell me the file I can make this code change in or is it something a developer has to do?

kerem commented

Author

Owner

@supermistag commented on GitHub (Jan 15, 2018):

A developer would need to make the change.

@supermistag commented on GitHub (Jan 15, 2018): A developer would need to make the change.

kerem commented

Author

Owner

@Pro commented on GitHub (Feb 7, 2018):

Fixed in #208

@Pro commented on GitHub (Feb 7, 2018): Fixed in #208

kerem commented