RuntimeError after upgrading from 1.2.2

After upgrading from version 1.2.2 to 1.2.4 we receive the following error when trying to start the controller:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 165, in start
    raise RuntimeError("Unknown Error, failed to init SMTP server")
RuntimeError: Unknown Error, failed to init SMTP server

This error can even be triggered by running the sample code from the documentation:

import asyncio
class ExampleHandler:
  async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
    return '250 OK'

from aiosmtpd.controller import Controller
controller = Controller(ExampleHandler())
controller.start()

After executing "controller.start()" the RuntimeError from above appears.

Python version is 3.6.8
OS is Red Hat 7.9
aiosmtpd was installed with pip3. After downgrading via "sudo pip3 install aiosmtpd=1.2.2" everything works again and aiosmtpd receives and processes emails without problems.

I've just released 1.3.0, can you try with that?

TBH I tried checking out 1.2.4 on Ubuntu 18.04, ran the code snippet you gave [simplification from the docs], and I couldn't replicate the error.

Asciinema Recording: https://asciinema.org/a/Fih5rZOm5QGlIboe4JWysSdSX

Update: I've just spun up a CentOS 7 instance, installed python3, created a new virtualenv, and also cannot replicate the error.

Asciinema Recording: https://asciinema.org/a/6k5vSAI4lX5oyOn2OiwRYZNdM

Thank you for the quick reply! I tried 1.3.0 but the problem remains:

$ sudo pip3 install aiosmtpd==1.3.0
WARNING: Running pip install with root privileges is generally not a good idea. Try `pip3 install --user` instead.
Collecting aiosmtpd==1.3.0
  Downloading https://mirror/api/pypi/pypi-remote/packages/packages/8b/41/0b7693c4509c9442cb1098c1c0c9d50effdad29e36323a5e611f20a28681/aiosmtpd-1.3.0.tar.gz (103kB)
    100% |████████████████████████████████| 112kB 5.5MB/s
Requirement already satisfied: atpublic in /usr/local/lib/python3.6/site-packages (from aiosmtpd==1.3.0)
Collecting attrs (from aiosmtpd==1.3.0)
  Downloading https://mirror/api/pypi/pypi-remote/packages/packages/c3/aa/cb45262569fcc047bf070b5de61813724d6726db83259222cd7b4c79821a/attrs-20.3.0-py2.py3-none-any.whl (49kB)
    100% |████████████████████████████████| 51kB 10.9MB/s
Requirement already satisfied: typing_extensions in /usr/local/lib/python3.6/site-packages (from atpublic->aiosmtpd==1.3.0)
Installing collected packages: attrs, aiosmtpd
  Found existing installation: aiosmtpd 1.2.2
    Uninstalling aiosmtpd-1.2.2:
      Successfully uninstalled aiosmtpd-1.2.2
  Running setup.py install for aiosmtpd ... done
Successfully installed aiosmtpd-1.3.0 attrs-20.3.0

$ python3
Python 3.6.8 (default, Aug 13 2020, 07:46:32)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-39)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> class ExampleHandler:
...   async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
...     return "250 OK"
...
>>>
>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
>>> cont.start()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 177, in start
    raise RuntimeError("Unknown Error, failed to init SMTP server")
RuntimeError: Unknown Error, failed to init SMTP server
>>>

I tried it on another Red Hat 7.9 server and there the same code works. Is there any way how I can find out what exactly is failing?

I tried it on another Red Hat 7.9 server and there the same code works.

Oookay, that's ... strange.

Is there any way how I can find out what exactly is failing?

The lines that raised that exception are these lines.

It's very hard to reach that line, as can be seen in the amount of acrobatics I have to do in the relevant test.

Because even if the factory() method returned None, the _factory_invoker() method should catch that and raise an Exception.

But I wonder ...

Can you try this:

from aiosmtpd.controller import Controller
from aiosmtpd.handlers import Sink
cont = Controller(Sink())
s1 = cont.factory()
print(repr(s1))
print(s1.hostname)

Ok I believe we get one step further. The following tests where performed with aiosmtpd==1.3.0:

Output of the code you requested to be run:

$ python3
Python 3.6.8 (default, Aug 13 2020, 07:46:32)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-39)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> from aiosmtpd.controller import Controller
>>> from aiosmtpd.handlers import Sink
>>> cont = Controller(Sink())
>>> s1 = cont.factory()
>>> print(repr(s1))
<aiosmtpd.smtp.SMTP object at 0x7fda740d0f28>
>>> print(s1.hostname)
myhostname...

Then I modified /usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py and put some debug statements at the beginning of factory() and _factory_invoker().

>>> class ExampleHandler:
...   async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
...     return "250 OK"
...
>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
>>> cont.factory()
DEBUG: In factory()
<aiosmtpd.smtp.SMTP object at 0x7f7f56cf09b0>
>>> cont._factory_invoker()
DEBUG: In _factory_invoker()
DEBUG: In factory()
<aiosmtpd.smtp.SMTP object at 0x7f7f562d1e10>

As expected executing factory() returns its debug output, whereas executing _factory_invoker() calls both _factory_invoker() as well as factory().
However as you can see below when executing start(), neither the debug output at the beginning of factory() nor of _factory_invoker() appears. I can't tell if this is because _factory_invoker() never gets called, or if it runs asynchronously and its output doesn't reach STDOUT. But I know that if I run the same code on another server, I see the debug lines.

>>> class ExampleHandler:
...   async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
...     return "250 OK"
...
>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
>>> cont.start()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 181, in start
    raise RuntimeError("Unknown Error, failed to init SMTP server")
RuntimeError: Unknown Error, failed to init SMTP server
>>> # No DEBUG output seen

If I explicitely call _factory_invoker() first, then start() doesn't produce a RuntimeError:

>>> class ExampleHandler:
...   async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
...     return "250 OK"
...
>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
>>> cont._factory_invoker()
<aiosmtpd.smtp.SMTP object at 0x7f79b4ea3550>
>>> cont.start()
>>>

Interesting!

At first glance, it seems that on the failing machine, Python's threading library works differently.

Yet your last experiment, in which you "pre-initialize" the SMTP object (because that's what _factory_invoker() actually do), threading works!

For some reasons, the spawned thread seems to be unable to write back to the main thread, and that's why cont.smtpd in the main thread remained None ...

Hmm... I don't have a quick answer for this. Please allow me some time to study this interesting situation.

PS: This "unable to modify main thread's behavior" totally reminds me of how multiprocessing behaves. Not trying to hint about anything, just something that popped into my mind and mildly interesting enough to share....

Unfortunately I don't know enough about Pythons threading to debug this alone.
I added time.sleep(3) to run() before the self.smtpd == None check, but the RuntimeError still appeared. So it doesn't seem to be a timing issue.

Unfortunately I don't know enough about Pythons threading to debug this alone.
I added time.sleep(3) to run() before the self.smtpd == None check, but the RuntimeError still appeared. So it doesn't seem to be a timing issue.

I suddenly have an inspiration:

Within the Controller.run() method, right after this block:

        if self._thread_exception is not None:  # pragma: on-wsl
            # See comment about WSL1.0 in the _run() method
            assert self._thread is not None  # Stupid LGTM.com; see github/codeql#4918
            raise self._thread_exception

can you insert the lines:

        if not ready_event.is_set():
            raise RuntimeError("Server not ready within alotted time.")

(The if statement of the inserted line must be on the same indentation level as the if statement on if self._thread_exception)

It won't fix the problem, but at least we'll get another control point to observe the behavior. If a RuntimeError gets raised there, we can narrow down the problem.

Test newly-implemented TimeoutError

@pepoluan

Hello @pepoluan
I added the following lines inside of Controller.start()

        if not ready_event.is_set():
            raise RuntimeError("Server not ready within alotted time.")
        print("checkpoint")

This resulted in the following output:

>>> class ExampleHandler:
...   async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
...     return "250 OK"
...
>>>
>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
>>> cont.start()
checkpoint
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 180, in start
    raise RuntimeError("Unknown Error, failed to init SMTP server")
RuntimeError: Unknown Error, failed to init SMTP server

So unfortunately still the same error.

Okay, so at least we know it was not caused by timeout.

Let's add another check point.

In the middle of these lines:

        try:
            self._testconn()
        except Exception:
            # We totally don't care of exceptions experienced by _testconn,
            # which _will_ happen if factory() experienced problems.
            pass
        if self._thread_exception is not None:
            raise self._thread_exception

Please add time.sleep(0.2) right before the test for self._thread_exception, so it looks like this:

        try:
            self._testconn()
        except Exception:
            # We totally don't care of exceptions experienced by _testconn,
            # which _will_ happen if factory() experienced problems.
            pass
        time.sleep(0.5)
        if self._thread_exception is not None:
            raise self._thread_exception

We try giving additional time for create_server to finish initialization.

Wait until factory _is_ invoked

Pin aiosmtpd to latest working version

Apparently someone else is running into the same issue, so at least it's not some messed up setting only on my servers.

I added the following to Controller.start(), which is very similar to what I tried in #244 (comment)

        try:
            self._testconn()
        except Exception:
            # We totally don't care of exceptions experienced by _testconn,
            # which _will_ happen if factory() experienced problems.
            pass
        time.sleep(0.5)
        print("checkpoint2")

However the output is unchanged:

>>> class ExampleHandler:
...   async def handle_RCPT(self, server, session, envelope, address, rcpt_options):
...     return "250 OK"
...
>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
>>> cont.start()
checkpoint2
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 180, in start
    raise RuntimeError("Unknown Error, failed to init SMTP server")
RuntimeError: Unknown Error, failed to init SMTP server

Fix Controller Bug on hostname="" or IPv6 not available (PR #248, Issue

I will release v1.3.1 soon; waiting for GA to validate the squamerging to master

@gnugnug

Hi @gnugnug & @LeoVerto , I've released 1.3.1 to PyPI.

Would be swell if you can verify it has fixed this issue.

@pepoluan

Hello @pepoluan thank you very much! Looks very good, except that on my system the error 97 is thrown:

>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 107, in __init__
    self.hostname = get_localhost() if hostname is None else hostname
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 41, in get_localhost
    with makesock(AF_INET6, SOCK_STREAM) as sock:
  File "/usr/lib64/python3.6/socket.py", line 144, in __init__
    _socket.socket.__init__(self, family, type, proto, fileno)
OSError: [Errno 97] Address family not supported by protocol

Errno 97 translates to errno.EAFNOSUPPORT, however get_localhost() is catching errno.EADDRNOTAVAIL. If I replace errno.EADDRNOTAVAIL with errno.EAFNOSUPPORT, version 1.3.1 works!

@pepoluan

Hello @pepoluan thank you very much! Looks very good, except that on my system the error 97 is thrown:

>>> from aiosmtpd.controller import Controller
>>> cont = Controller(ExampleHandler())
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 107, in __init__
    self.hostname = get_localhost() if hostname is None else hostname
  File "/usr/local/lib/python3.6/site-packages/aiosmtpd/controller.py", line 41, in get_localhost
    with makesock(AF_INET6, SOCK_STREAM) as sock:
  File "/usr/lib64/python3.6/socket.py", line 144, in __init__
    _socket.socket.__init__(self, family, type, proto, fileno)
OSError: [Errno 97] Address family not supported by protocol

Errno 97 translates to errno.EAFNOSUPPORT, however get_localhost() is catching errno.EADDRNOTAVAIL. If I replace errno.EADDRNOTAVAIL with errno.EAFNOSUPPORT, version 1.3.1 works!

Thanks!

Hmm... seems like different errors for different systems? I'll just change the == to in some_set, and push another bugfix tomorrow.

@LeoVerto

I never received errno 99 (EADDRNOTAVAIL). Only errno 97. Maybe in the environment of @LeoVerto errno 99 was seen?

@LeoVerto

I never received errno 99 (EADDRNOTAVAIL). Only errno 97. Maybe in the environment of @LeoVerto errno 99 was seen?

In my test system I got EADDRNOTAVAIL, that's why the equality test was against EADDRNOTAVAIL.

I've changed it so it's if e.errno in {EADDRNOTAVAIL, EAFNOSUPPORT}, so we'll be good any which way.

Edit: After some thinking, I think the difference is because on my test systems I disabled IPv6 using sysctl, so the IPv6 modules are still loaded in the kernel, hence EADDRNOTAVAIL ("you want IPv6 address? Sure I can give you that but I'm currently on vacation.") Your kernel probably didn't load the IPv6 module at all, thus EAFNOSUPPORT ("You want what? Nobody here provides what you want.")

@pepoluan

This has fixed the issue for me, thank you so much for the quick debugging and fix, @pepoluan!

Hello,
I have similar problem. My project msztolcman/sendria is using aiosmtpd to handle incoming smtp connections. It works fine with aiosmtps 1.2.2, but after upgrade to 1.4.1 I have:

% 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

% python --version
Python 3.9.1
% uname -s
Darwin

Hello,
I have similar problem. My project msztolcman/sendria is using aiosmtpd to handle incoming smtp connections. It works fine with aiosmtps 1.2.2, but after upgrade to 1.4.1 I have:

Hi, can you create a new issue instead of replying here?

That way we can actually track which issues have been fixed, and by which PR. Would go a long way towards ease of troubleshooting as we can bisect.

Because this seems to be caused by a different bug from the 1.3.x issues.

Hi, sure. I was thinking it can be similar one :)
New one opened.

Navigation Menu

Repository navigation

RuntimeError after upgrading from 1.2.2 #244

13 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

RuntimeError after upgrading from 1.2.2 #244

Description

Activity

pepoluan commented on Feb 8, 2021

pepoluan commented on Feb 8, 2021

pepoluan commented on Feb 9, 2021

gnugnug commented on Feb 9, 2021

pepoluan commented on Feb 9, 2021

gnugnug commented on Feb 9, 2021

pepoluan commented on Feb 9, 2021

gnugnug commented on Feb 11, 2021

pepoluan commented on Feb 12, 2021

gnugnug commented on Feb 15, 2021

pepoluan commented on Feb 15, 2021

gnugnug commented on Feb 16, 2021

13 remaining items

pepoluan commented on Feb 18, 2021

pepoluan commented on Feb 18, 2021

gnugnug commented on Feb 18, 2021

pepoluan commented on Feb 18, 2021

gnugnug commented on Feb 18, 2021

pepoluan commented on Feb 18, 2021

LeoVerto commented on Feb 18, 2021

msztolcman commented on Mar 5, 2021

pepoluan commented on Mar 5, 2021

msztolcman commented on Mar 5, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions