search

zabszk / CSharp-SMTP-Server

SMTP Server in C#
MIT License
16 stars 4 forks source link

Client receive loop Exception #16

Open endmax opened 1 week ago

endmax commented 1 week ago

I use the SMTP server to process mails from a specific gmail account. It frequently happens that there are subsequent System.IO.IOException inside the receive loop.

2024-09-08 22:09:01.772 +02:00 [ERR] [Client receive loop] Exception: System.IO.IOException, at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken) at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken) at System.IO.StreamReader.ReadLineAsyncInternal(CancellationToken cancellationToken) at CSharp_SMTP_Server.Networking.ClientProcessor.Receive(), Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..

2024-09-08 22:11:21.449 +02:00 [ERR] [Client receive loop] Exception: System.IO.IOException, at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken) at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken) at System.IO.StreamReader.ReadLineAsyncInternal(CancellationToken cancellationToken) at CSharp_SMTP_Server.Networking.ClientProcessor.Receive(), Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..

2024-09-08 22:12:51.415 +02:00 [ERR] [Client receive loop] Exception: System.IO.IOException, at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken) at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken) at System.IO.StreamReader.ReadLineAsyncInternal(CancellationToken cancellationToken) at CSharp_SMTP_Server.Networking.ClientProcessor.Receive(), An existing connection was forcibly closed by the remote host..

After 3 exceptions the loop is exited but the exception is not throwed and the listener is not stopped by anyone.


catch (Exception e)
{
    Server.LoggerInterface?.LogError("[Client receive loop] Exception: " + e.GetType().FullName + ", " + e.StackTrace + ", " + e.Message);
    _fails++;
    if (_fails <= 3) continue;
    break;
}

I have some questions:

zabszk commented 1 week ago

Hi, Thank your for reporting the issue. I'm starting analyzing it.

zabszk commented 1 week ago

The exception itself means that the client forcefully stopped connection (either sent RST packet or connection was dropped). It should not affect the server itself. If that's the case, I will make changes to simply disconnect such client.

Can you answer to these two questions:

  1. Can you tell me more about your use-case? Is this a "regular" SMTP server and external clients (eg. users or other SMTP servers) connect to this server, send messages and disconnect or do you have some custom client that maintains long connection that gets for some reason dropped with this exception?
  2. How the SMTP server behaves after this exception? New clients should be able to connect to it. Is this the case or does the server stop accepting new clients?
zabszk commented 1 week ago

I reproduced the issue. It happens when connection to client is dropped (or reset) when server is in progress of reading data (that happens as well if client didn't send \n or \r at the end and then disconnected).

Server seems to properly handle new clients. Can you confirm that's the case?

zabszk commented 1 week ago

For now I simply handled that exception. There is a way to rewrite part of the code to avoid this exception in the first place (it will require implementing part of the StreamReader manually) and I will consider doing so.

The questions from my second reply are still relevant.

endmax commented 1 week ago

The exception itself means that the client forcefully stopped connection (either sent RST packet or connection was dropped). It should not affect the server itself. If that's the case, I will make changes to simply disconnect such client.

Can you answer to these two questions:

  1. Can you tell me more about your use-case? Is this a "regular" SMTP server and external clients (eg. users or other SMTP servers) connect to this server, send messages and disconnect or do you have some custom client that maintains long connection that gets for some reason dropped with this exception?
  2. How the SMTP server behaves after this exception? New clients should be able to connect to it. Is this the case or does the server stop accepting new clients?

Well, it is a "regular" SMTP server that accept only a specific google mail sender. The SMTP server stops quite frequently after it gets the errors I've reported in my first post. The gmail account is configured to forward emails from a specific sender to my SMTP server. Here is a screenshot of the log where you can see these errors and when the server stopped. image

zabszk commented 1 week ago

Thanks. Has the program crashed right after this exception?

I don't think that this exception caused it, because it's handled. Do you log stdout and stderr as well? If so, are there any exceptions or errors there? I believe that the crash is caused by some other exception (either in my library, in your app or some other library you use).

endmax commented 1 week ago

The program does not crash but the smtp server does not respond anymore to any request. The smtp server is started inside a BackGroudService

public class Worker : BackgroundService
{

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        _logger.LogInformation("Executing service...");

        ....

        StartSMTPServer();

        _logger.LogInformation("Service is ready!");

        await stoppingToken;
        _smtpServer?.Dispose();
        watcher.EnableRaisingEvents = false;
        _logger.LogInformation("Service is shutting down");
    }

    private void StartSMTPServer()
    {
        _logger.LogInformation("Configuring SMTP Server...");
        var store = new X509Store("WebHosting", StoreLocation.LocalMachine);
        store.Open(OpenFlags.ReadOnly | OpenFlags.OpenExistingOnly);

        var collection = store.Certificates;
        var certificates = collection.Find(X509FindType.FindBySubjectName, _smtpServerConfiguration.TLSCertificateName, false);

        X509Certificate2 certificate = certificates?.FirstOrDefault();

        if (certificate != null)
        {
            _logger.LogInformation("Using certificate {c}", _smtpServerConfiguration.TLSCertificateName);
        }

        _logger.LogInformation("Ports {@p}", _smtpServerConfiguration.Ports);
        _logger.LogInformation("TLSPorts {@p}", _smtpServerConfiguration.TLSPorts);

        var parameters = new ListeningParameters(IPAddress.IPv6Any, _smtpServerConfiguration.Ports,_smtpServerConfiguration.TLSPorts, true);
        var options = new ServerOptions()
        {
            ServerName = "my SMTP Server",
            RequireEncryptionForAuth = true,
            MessageCharactersLimit = 1024 * 1024 * 100
        };

        _smtpServer = new SMTPServer(new[] { parameters }, options, _mailDelivery, _smtpLogger);
        _smtpServer.SetAuthLogin(_mailAuth);
        _smtpServer.SetFilter(_mailFilter);
        _smtpServer.Start();

        _logger.LogInformation("SMTP Server ready");
    }
}
zabszk commented 1 week ago
  1. Is _logger.LogInformation("Service is shutting down"); executed during that "crash" or not?
  2. Are all SMTP ports stop being reachable?
  3. Can you check netstat (netstat -a -p tcp) on the server after the crash (before restarting the server)? Can you see any of the SMTP ports there? If you not familiar with netstat, you can run the command before it breaks to see how it should look like (port 25 should be on one of the first lines with state LISTENING).
endmax commented 1 week ago
  1. No, the service is not shut down, the LogInformation is not executed.
  2. A telnet to the server does not respond
  3. I'll do as soon as the exception occurs The strange thing is that the exception is trapped in the receiving loop and the SMTP server stops to respond when the loop is exited in the catch statement. In my understanding of your code, the listener is not notified about this event and stays hanging.
zabszk commented 1 week ago

Thanks.

I'll do as soon as the exception occurs

Ok, I'm waiting for a crash.

In my understanding of your code, the listener is not notified about this event and stays hanging.

Listener isn't responsible for receiving data from clients. Listener is only responsible for accepting new clients. AcceptTcpClient() creates a new socket for this specific client and the listener socket keeps waiting for new clients and doesn't do anything related to that client that got accepted.

So either _dispose bool in Listener is set to true or listener is stuck for some reason on accepting new client (that will mean that there is some OS/C# issue, so I think it's an issue with dispose).

zabszk commented 1 week ago

I created branch dispose-log that logs disposal. Can you try using that branch for testing? Build attached.

release.zip

endmax commented 6 days ago

I'will try this version and I'll let you know as soon as I get the error.

endmax commented 3 days ago

Hi, today the situation is the following: the smtp server does not receive any email, the log is not reporting anything, it seems not running

The application log shows the following errors:

[16:35:34 ERR]  MailError: [Client receive loop] Exception: System.Security.Authentication.AuthenticationException, Authentication failed, see inner exception.
[00:28:55 ERR]  MailError: [Client receive loop] Exception: System.IO.IOException,  Received an unexpected EOF or 0 bytes from the transport stream.

Now I'm going to use the dispose-log branch to compile my application and I'll let you know what happens.

endmax commented 2 days ago

Just another log before to pass to dispose-log branch.

2024-09-27 02:42:27.154 +02:00 [ERR] [Client write] Exception: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
2024-09-27 02:42:40.067 +02:00 [ERR] [Client receive loop] Exception: System.IO.IOException,    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
   at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken)
   at System.IO.StreamReader.ReadLineAsyncInternal(CancellationToken cancellationToken)
   at CSharp_SMTP_Server.Networking.ClientProcessor.Receive(), Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..

2024-09-27 05:00:08.655 +02:00 [ERR] [Client receive loop] Exception: System.IO.IOException,    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
   at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken)
   at System.IO.StreamReader.ReadLineAsyncInternal(CancellationToken cancellationToken)
   at CSharp_SMTP_Server.Networking.ClientProcessor.Receive(), Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..

here I've restarted the IIS server but the_logger.LogInformation("Service is shutting down"); is not executed but this could be a problem in my code.

2024-09-27 09:49:02.015 +02:00 [INF] Stopping service...

2024-09-27 09:49:16.527 +02:00 [INF] Starting service...
2024-09-27 09:49:17.020 +02:00 [INF] Executing service...
2024-09-27 09:49:17.020 +02:00 [INF] Checking for unprocessed files...
2024-09-27 09:49:17.074 +02:00 [INF] Configuring SMTP Server...
2024-09-27 09:49:17.105 +02:00 [INF] Ports [25,587]
2024-09-27 09:49:17.107 +02:00 [INF] TLSPorts [465]
2024-09-27 09:49:17.537 +02:00 [INF] SMTP Server ready
2024-09-27 09:49:17.537 +02:00 [INF] Service is ready!
2024-09-27 09:49:17.679 +02:00 [INF] AspNetCoreThreadingTimerStoragesCleaner.StartCore

In this particular case the first exception is inside the Client Write and the _fails counter is incremented by one. The other two exceptions are in the Client receive loop and after 2 exceptions the loop is exited and the SMTP server no more accepts emails even if it is active on all ports (tested with telnet). The following is the netstat output:

  TCP    0.0.0.0:80             XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:135            XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:443            XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:445            XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:465            XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:587            XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:5040           XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:7070           XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:7680           XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:49664          XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:49665          XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:49666          XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:49667          XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:49668          XXXXXXXXXXXXXXX:0      LISTENING
  TCP    0.0.0.0:49670          XXXXXXXXXXXXXXX:0      LISTENING
  TCP    XXXXXXXXXXXX:25        79.110.62.17:64586     CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.156:8972      CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.156:31512     CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.157:14064     CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.157:35590     CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.158:8650      CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.158:51571     CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.159:8258      CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        80.94.92.159:29875     CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        35.39.168.109.cust.ip.kpnqwest.it:49854  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        119-40-84-186.bdcom.com:49295  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        119-40-84-186.bdcom.com:51660  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        119-40-84-186.bdcom.com:52459  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        119-40-84-186.bdcom.com:52716  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        119-40-84-186.bdcom.com:58387  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        183.134.104.170:62653  ESTABLISHED
  TCP    XXXXXXXXXXXX:25        185.196.9.190:63569    CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        185.196.9.190:65414    CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        mail-lj1-f170.google.com:53353  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        mail-lj1-f173.google.com:42181  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        mail-lj1-f177.google.com:53438  ESTABLISHED
  TCP    XXXXXXXXXXXX:25        mail-lj1-f179.google.com:43277  CLOSE_WAIT
  TCP    XXXXXXXXXXXX:25        mail-ej1-f47.google.com:42068  ESTABLISHED