NLog Not Closing SMTP Connections

[jzielke]

I have an issue were NLog SMTP Targets are not closing the SMTP Connections to the mails servers. The default SMTP connections in C# is two unless changed in the App.Config. 2 is fine for the amount of mail I send as long as the connections can be reused. Tested with code from the repo.

There appears to issues with the SMTP Framework class in 3.5 and lower. I am on 4.5. To note that my mailer, which uses the same framework SMTP Class, does not exhibit the same behavior. If NLog sends any SMTP mail, it locks the connections and my mailer can't send.

Sample Program with a standard SMTP target
        static void Main(string[] args)
        {
            Logger Instance = LogManager.GetCurrentClassLogger();
            try
            {

                Instance.Log(LogLevel.Fatal, "Message 1");
                Instance.Log(LogLevel.Fatal, "Message 2");
                Instance.Log(LogLevel.Fatal, "Message 3");
                Instance.Log(LogLevel.Fatal, "Message 4");
                Instance.Log(LogLevel.Fatal, "Message 5");
                Instance.Log(LogLevel.Fatal, "Message 6");
                Instance.Log(LogLevel.Fatal, "Message 7");

                Console.ReadKey();
            }
            catch (Exception Ex)
            {

                Instance.Log(LogLevel.Debug, "exception", Ex);
            }
        }

No open 587 ports before running. Run to the readkey or break point in the middle, don't exit.

netstat -a  | find "587"
  TCP    <MY IP>:50673       <SERVER IP>:587  CLOSE_WAIT
  TCP    <MY IP>:50770       <SERVER IP>:587  CLOSE_WAIT

The connections will stay in a CLOSE_WAIT status as the the SMTP server is waiting for the QUIT message. I received 3 of the 7 messages that were supposed to be sent, rest probably timeouted out waiting for the connection. All 7 went to the File Target fine.

Now the SMTPClient is using a 'using' so it should be disposing of the SMTP object. Things don't go back to normal until the application is ended.

Now I increased the number of connections in C# but that will not solve the issue as it will come back after those connections aren't closed.

I increased the connections in the App.Config to 4

    <connectionManagement>
      <add address="*" maxconnection="4" />
    </connectionManagement>

Now I get 4 Connections Blocked and receive 5 of the 7 emails.

netstat -a  | find "587"
  TCP    <MY IP>:51762       <SERVER IP>:587  CLOSE_WAIT
  TCP    <MY IP>:51763       <SERVER IP>:587  CLOSE_WAIT
  TCP    <MY IP>:51764       <SERVER IP>:587  CLOSE_WAIT
  TCP    <MY IP>:51765       <SERVER IP>:587  CLOSE_WAIT

Turned on NLog Exceptions and here is the standard Net.SMTP Client Exception that is thrown when there are no more connections available.

[2014-11-12 10:55:06.201] - NLog.Test.Program                        - DEBUG  - exception 
NLog.NLogRuntimeException: Exception occurred in NLog ---> System.Net.Mail.SmtpException: The operation has timed out.
   at System.Net.Mail.SmtpClient.Send(MailMessage message)
   at NLog.Internal.MySmtpClient.NLog.Internal.ISmtpClient.Send(MailMessage )
   at NLog.Targets.MailTarget.ProcessSingleMailMessage(List`1 events) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 313
   --- End of inner exception stack trace ---
   at NLog.LoggerImpl.<>c__DisplayClass1.<Write>b__0(Exception ex) in c:\SmartBIM\NLog.github\src\NLog\LoggerImpl.cs:line 88
   at NLog.Internal.SingleCallContinuation.Function(Exception exception) in c:\SmartBIM\NLog.github\src\NLog\Internal\SingleCallContinuation.cs:line 79
   at NLog.Targets.MailTarget.ProcessSingleMailMessage(List`1 events) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 332
   at NLog.Targets.MailTarget.Write(AsyncLogEventInfo[] logEvents) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 255
   at NLog.Targets.MailTarget.Write(AsyncLogEventInfo logEvent) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 243
   at NLog.Targets.Target.WriteAsyncLogEvent(AsyncLogEventInfo logEvent) in c:\SmartBIM\NLog.github\src\NLog\Targets\Target.cs:line 215
   at NLog.LoggerImpl.WriteToTargetWithFilterChain(TargetWithFilterChain targetListHead, LogEventInfo logEvent, AsyncContinuation onException) in c:\SmartBIM\NLog.github\src\NLog\LoggerImpl.cs:line 193
   at NLog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targets, LogEventInfo logEvent, LogFactory factory) in c:\SmartBIM\NLog.github\src\NLog\LoggerImpl.cs:line 95
   at NLog.Logger.WriteToTargets(LogLevel level, IFormatProvider formatProvider, String message) in c:\SmartBIM\NLog.github\src\NLog\Logger.cs:line 1902
   at NLog.Logger.Log(LogLevel level, String message) in c:\SmartBIM\NLog.github\src\NLog\Logger.cs:line 266
   at NLog.Test.Program.Main(String[] args) in c:\Projects\NLog.Test\NLog.Test\NLog.Test\Program.cs:line 23    at NLog.LoggerImpl.<>c__DisplayClass1.<Write>b__0(Exception ex) in c:\SmartBIM\NLog.github\src\NLog\LoggerImpl.cs:line 88
   at NLog.Internal.SingleCallContinuation.Function(Exception exception) in c:\SmartBIM\NLog.github\src\NLog\Internal\SingleCallContinuation.cs:line 79
   at NLog.Targets.MailTarget.ProcessSingleMailMessage(List`1 events) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 332
   at NLog.Targets.MailTarget.Write(AsyncLogEventInfo[] logEvents) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 255
   at NLog.Targets.MailTarget.Write(AsyncLogEventInfo logEvent) in c:\SmartBIM\NLog.github\src\NLog\Targets\MailTarget.cs:line 243
   at NLog.Targets.Target.WriteAsyncLogEvent(AsyncLogEventInfo logEvent) in c:\SmartBIM\NLog.github\src\NLog\Targets\Target.cs:line 215
   at NLog.LoggerImpl.WriteToTargetWithFilterChain(TargetWithFilterChain targetListHead, LogEventInfo logEvent, AsyncContinuation onException) in c:\SmartBIM\NLog.github\src\NLog\LoggerImpl.cs:line 193
   at NLog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targets, LogEventInfo logEvent, LogFactory factory) in c:\SmartBIM\NLog.github\src\NLog\LoggerImpl.cs:line 95
   at NLog.Logger.WriteToTargets(LogLevel level, IFormatProvider formatProvider, String message) in c:\SmartBIM\NLog.github\src\NLog\Logger.cs:line 1902
   at NLog.Logger.Log(LogLevel level, String message) in c:\SmartBIM\NLog.github\src\NLog\Logger.cs:line 266
   at NLog.Test.Program.Main(String[] args) in c:\Projects\NLog.Test\NLog.Test\NLog.Test\Program.cs:line 23

John

[ghost]

Thanks for the bug report, I'll take a look at it

[gdau]

Sorry if I'm not parsing your question properly (I can't tell if you're having this issue only on .NET 3.5 or on higher versions?) but there is a known issue in < 3.5 where the .NET SmtpClient never issues the QUIT command (and there was no IDisposable in this version). In NLog there is a wrapper MySmtpClient that implements the IDisposable method but does nothing (so even though you see a "using" in the calling code, it won't actually clean up the SMTP connection - afaik, there is nothing you can really do about this without upgrading to .NET 4.0 or replacing the SmtpClient with a third-party solution).

If I misunderstood your question, my apologies :)

[jzielke]

No Prob, a lot going on in the issue.

This is a Simple .Net 4.5 Console Test Application. I agree on the < 3.5 issue but was surprised to see the issue in a 4.5 Application.

I think the Target is not getting unloaded from memory, garbage collected, allowing the dispose to clean up the connections. Meaning once the Target is used for the first time, it stays in memory until the app is closed and then the object is disposed of.

I can send you my project if you want it, but it is just a Console App with the above code and a NLog.Config with an EMail Target.

[jzielke]

Issue still happening. Something with not disposing of the SMTP Object to close the server connection.

[mikehixson]

I am also having the same problem. I did some digging based on the findings of @jzielke. It appears that this regression is related to the change:

0d523ec#diff-111027e98754fa8d87fe750d4edbd9f7

This change sets the Timeout on SmtpClient to 0 by default (when no timeout is explicitly configured for the MailTarget). In this case 0 does not mean infinity, it means 0 milliseconds. From my observations, this seems to cause SmtpException to be thrown sometimes when the mail server is not quick enough.

It seems that the problem with connections being left open is related to the SmtpException being thrown. In my case configuring the timeout on the MailTarget to 100,000 (the default used by SmtpClient) seems to work around the problem.

I could not quickly pinpoint why the connections are being left open. I just wanted to share this bit of info in hopes that it helps get to the bottom of this.

[jzielke]

Thanks @mikehixson - That appears to be the issue.

I was looking at everything concerning the dispose of the object and the timeout being zero did not even dawn on me.

As you did, I added timeout to the target and netstat returns back good after each call.

So [DefaultValue(10000)] does not set the default value if there is no timeout in the config.

Note from Microsoft On Default Attribute Values
"A DefaultValueAttribute will not cause a member to be automatically initialized with the attribute's value. You must set the initial value in your code."

http://goo.gl/rjANWd

[ghost]

Thank you very much. I'll implement the fix in the next version.

[karenconnelly]

Hello, is it possible for this fix to be made available in the 3.2.1 release instead of only 4.0.0.0? I'm experiencing the same issue now that we've upgraded our production systems with NLog 3.2.0, and have to disable all MailTargets as a tactical response. Do you know when 3.2.1 is scheduled for? Thanks! Karen.

[304NotModified]

Just set the timeout value as work around. :)

[karenconnelly]

Duh, thanks Julian!

On Mar 18, 2015, at 4:22 PM, Julian Verdurmen notifications@github.com wrote:

Just set the timeout value as work around. :)

—
Reply to this email directly or view it on GitHub.