Repository: aio-libs/aiosmtpd

Issue:
TimeoutError: SMTP server not responding within allotted time
Hello,
I have similar problem. My project [msztolcman/sendria](https://github.com/msztolcman/sendria) is using `aiosmtpd` to handle incoming smtp connections. It works fine with `aiosmtpd` 1.2.2, but after upgrade to 1.4.1 I have:

```bash
% sendria --db db.sqlite -d -a
2021-03-05T12:36:02.487786Z no PID file specified; runnning in foreground
2021-03-05T12:36:02.487885Z starting Sendria               db=/Users/mysz/Projects/sendria/db.sqlite debug=enabled foreground=true pidfile=None
2021-03-05T12:36:02.491769Z DB initialized
2021-03-05T12:36:02.492011Z webhooks disabled
Traceback (most recent call last):
  File "/Users/mysz/Projects/sendria/.venv/bin/sendria", line 33, in <module>
    sys.exit(load_entry_point('sendria', 'console_scripts', 'sendria')())
  File "/Users/mysz/Projects/sendria/sendria/cli.py", line 296, in main
    run_sendria_servers(loop, args)
  File "/Users/mysz/Projects/sendria/sendria/cli.py", line 176, in run_sendria_servers
    smtp.run(args.smtp_ip, args.smtp_port, args.smtp_auth, args.smtp_ident, args.debug)
  File "/Users/mysz/Projects/sendria/sendria/smtp.py", line 69, in run
    controller.start()
  File "/Users/mysz/Projects/sendria/.venv/lib/python3.9/site-packages/aiosmtpd/controller.py", line 225, in start
    raise TimeoutError("SMTP server not responding within allotted time")
TimeoutError: SMTP server not responding within allotted time
```

Platform data:
```bash
% python --version
Python 3.9.1
% uname -s
Darwin
```

Discussion:
codecov[bot]: # [Codecov](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=h1) Report
> Merging [#263](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=desc) (c042ee6) into [master](https://codecov.io/gh/aio-libs/aiosmtpd/commit/f0895056113e339a7d2b94b11c57e30cfa974d82?el=desc) (f089505) will **not change** coverage.
> The diff coverage is `100.00%`.

[![Impacted file tree graph](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263/graphs/tree.svg?width=650&height=150&src=pr&token=k9dc7NVG69)](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=tree)

```diff
@@            Coverage Diff            @@
##            master      #263   +/-   ##
=========================================
  Coverage   100.00%   100.00%           
=========================================
  Files            7         7           
  Lines         1607      1607           
  Branches       297       297           
=========================================
  Hits          1607      1607           
```


| [Impacted Files](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [aiosmtpd/\_\_init\_\_.py](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263/diff?src=pr&el=tree#diff-YWlvc210cGQvX19pbml0X18ucHk=) | `100.00% <100.00%> (ø)` | |
| [aiosmtpd/controller.py](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263/diff?src=pr&el=tree#diff-YWlvc210cGQvY29udHJvbGxlci5weQ==) | `100.00% <100.00%> (ø)` | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=footer). Last update [f089505...c042ee6](https://codecov.io/gh/aio-libs/aiosmtpd/pull/263?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).

pepoluan: All tests green across the board, and even though I didn't test on all my test systems, because the change is relatively very minor, I don't think an extensive testing is needed.

For the same reason, I'll just marinate this for ~1 day, and squamerge if no objections by tomorrow.

Patch:
diff --git a/aiosmtpd/__init__.py b/aiosmtpd/__init__.py
index 7403d8e..2124ae5 100644
--- a/aiosmtpd/__init__.py
+++ b/aiosmtpd/__init__.py
@@ -1,4 +1,4 @@
 # Copyright 2014-2021 The aiosmtpd Developers
 # SPDX-License-Identifier: Apache-2.0
 
-__version__ = "1.4.1"
+__version__ = "1.4.2a1"
diff --git a/aiosmtpd/controller.py b/aiosmtpd/controller.py
index 9dee79d..2258c54 100644
--- a/aiosmtpd/controller.py
+++ b/aiosmtpd/controller.py
@@ -27,6 +27,8 @@ from aiosmtpd.smtp import SMTP
 
 AsyncServer = asyncio.base_events.Server
 
+DEFAULT_READY_TIMEOUT: float = 5.0
+
 
 @public
 class IP6_IS:
@@ -106,7 +108,7 @@ class BaseThreadedController(metaclass=ABCMeta):
         handler,
         loop=None,
         *,
-        ready_timeout: float = 1.0,
+        ready_timeout: float,
         ssl_context: Optional[ssl.SSLContext] = None,
         # SMTP parameters
         server_hostname: Optional[str] = None,
@@ -207,7 +209,11 @@ class BaseThreadedController(metaclass=ABCMeta):
                 # See comment about WSL1.0 in the _run() method
                 raise self._thread_exception
             else:
-                raise TimeoutError("SMTP server failed to start within allotted time")
+                raise TimeoutError(
+                    "SMTP server failed to start within allotted time. "
+                    "This might happen if the system is too busy. "
+                    "Try increasing the `ready_timeout` parameter."
+                )
         respond_timeout = self.ready_timeout - (time.monotonic() - start)
 
         # Apparently create_server invokes factory() "lazily", so exceptions in
@@ -222,7 +228,11 @@ class BaseThreadedController(metaclass=ABCMeta):
             # Raise other exceptions though
             raise
         if not self._factory_invoked.wait(respond_timeout):
-            raise TimeoutError("SMTP server not responding within allotted time")
+            raise TimeoutError(
+                "SMTP server started, but not responding within allotted time. "
+                "This might happen if the system is too busy. "
+                "Try increasing the `ready_timeout` parameter."
+            )
         if self._thread_exception is not None:
             raise self._thread_exception
 
@@ -265,7 +275,7 @@ class Controller(BaseThreadedController):
         port: int = 8025,
         loop=None,
         *,
-        ready_timeout: float = 1.0,
+        ready_timeout: float = DEFAULT_READY_TIMEOUT,
         ssl_context: ssl.SSLContext = None,
         # SMTP parameters
         server_hostname: Optional[str] = None,
@@ -317,8 +327,8 @@ class UnixSocketController(BaseThreadedController):  # pragma: on-win32 on-cygwi
         unix_socket: Optional[Union[str, Path]],
         loop=None,
         *,
-        ready_timeout=1.0,
-        ssl_context=None,
+        ready_timeout: float = DEFAULT_READY_TIMEOUT,
+        ssl_context: ssl.SSLContext = None,
         # SMTP parameters
         server_hostname: str = None,
         **SMTP_parameters,
diff --git a/aiosmtpd/docs/NEWS.rst b/aiosmtpd/docs/NEWS.rst
index cb38f44..0e6aff2 100644
--- a/aiosmtpd/docs/NEWS.rst
+++ b/aiosmtpd/docs/NEWS.rst
@@ -3,6 +3,22 @@
 ###################
 
 
+1.4.2 (aiosmtpd-next)
+=====================
+
+Fixed/Improved
+--------------
+* Controller's ``ready_timeout`` parameter increased from ``1.0`` to ``5.0``.
+  This won't slow down Controller startup because it's just a timeout limit
+  (instead of a sleep delay),
+  but this should help prevent Controller from giving up too soon,
+  especially during situations where system/network is a bit busy causing slowdowns.
+  (See #262)
+* Timeout messages in ``Controller.start()`` gets more details and a mention about the
+  ``ready_timeout`` parameter. (See #262)
+
+
+
 1.4.1 (2021-03-04)
 ==================
 
diff --git a/aiosmtpd/docs/controller.rst b/aiosmtpd/docs/controller.rst
index 06a0f3b..d3e08ed 100644
--- a/aiosmtpd/docs/controller.rst
+++ b/aiosmtpd/docs/controller.rst
@@ -283,7 +283,7 @@ Controller API
    handler, \
    loop=None, \
    *, \
-   ready_timeout=1.0, \
+   ready_timeout, \
    ssl_context=None, \
    server_hostname=None, server_kwargs=None, **SMTP_parameters)
 
@@ -292,6 +292,7 @@ Controller API
       If not given, :func:`asyncio.new_event_loop` will be called to create the event loop.
    :param ready_timeout: How long to wait until server starts.
       The :envvar:`AIOSMTPD_CONTROLLER_TIMEOUT` takes precedence over this parameter.
+      See :attr:`ready_timeout` for more information.
    :type ready_timeout: float
    :param ssl_context: SSL Context to wrap the socket in.
        Will be passed-through to  :meth:`~asyncio.loop.create_server` method
@@ -330,7 +331,6 @@ Controller API
 
    .. attribute:: ready_timeout
       :type: float
-      :noindex:
 
       The timeout value used to wait for the server to start.
 
@@ -338,6 +338,11 @@ Controller API
       the :envvar:`AIOSMTPD_CONTROLLER_TIMEOUT` environment variable (converted to float),
       or the :attr:`ready_timeout` parameter.
 
+      Setting this to a high value will NOT slow down controller startup,
+      because it's a timeout limit rather than a sleep delay.
+      However, you may want to reduce the default value to something 'just enough'
+      so you don't have to wait too long for an exception, if problem arises.
+
       If this timeout is breached, a :class:`TimeoutError` exception will be raised.
 
    .. attribute:: server
@@ -430,7 +435,7 @@ Controller API
    hostname=None, port=8025, \
    loop=None, \
    *, \
-   ready_timeout=1.0, \
+   ready_timeout=3.0, \
    ssl_context=None, \
    server_hostname=None, server_kwargs=None, **SMTP_parameters)
 
@@ -488,7 +493,7 @@ Controller API
    unix_socket, \
    loop=None, \
    *, \
-   ready_timeout=1.0, \
+   ready_timeout=3.0, \
    ssl_context=None, \
    server_hostname=None,\
    **SMTP_parameters)


Test patch:
diff --git a/aiosmtpd/tests/test_proxyprotocol.py b/aiosmtpd/tests/test_proxyprotocol.py
index 3e8fb9a..bf7f939 100644
--- a/aiosmtpd/tests/test_proxyprotocol.py
+++ b/aiosmtpd/tests/test_proxyprotocol.py
@@ -38,7 +38,7 @@ from aiosmtpd.smtp import Session as SMTPSession
 from aiosmtpd.tests.conftest import Global, controller_data, handler_data
 
 DEFAULT_AUTOCANCEL = 0.1
-TIMEOUT_MULTIPLIER = 1.5
+TIMEOUT_MULTIPLIER = 2.0
 
 param = pytest.param
 parametrize = pytest.mark.parametrize
diff --git a/aiosmtpd/tests/test_server.py b/aiosmtpd/tests/test_server.py
index a271243..99c5630 100644
--- a/aiosmtpd/tests/test_server.py
+++ b/aiosmtpd/tests/test_server.py
@@ -123,7 +123,11 @@ class TestController:
     @pytest.mark.filterwarnings("ignore")
     def test_ready_timeout(self):
         cont = SlowStartController(Sink())
-        expectre = r"SMTP server failed to start within allotted time"
+        expectre = (
+            "SMTP server failed to start within allotted time. "
+            "This might happen if the system is too busy. "
+            "Try increasing the `ready_timeout` parameter."
+        )
         try:
             with pytest.raises(TimeoutError, match=expectre):
                 cont.start()
@@ -133,7 +137,11 @@ class TestController:
     @pytest.mark.filterwarnings("ignore")
     def test_factory_timeout(self):
         cont = SlowFactoryController(Sink())
-        expectre = r"SMTP server not responding within allotted time"
+        expectre = (
+            r"SMTP server started, but not responding within allotted time. "
+            r"This might happen if the system is too busy. "
+            r"Try increasing the `ready_timeout` parameter."
+        )
         try:
             with pytest.raises(TimeoutError, match=expectre):
                 cont.start()