Sentry email notifications not arriving?
I've been using Sentry for quite some time now in some projects, mostly all of them running python based applications and systems, and recently I did a major upgrade of a Sentry server to the latest version (8.3.1). It was an update with lots of changes, both in the Sentry internals and the dependencies needed by it (like the addition of Redis) but everything went more or less smoothly.
Once I had the server ready, I did upgrade the Raven client accordingly and I modified something in our staging server so an exception (IOError actually) was raised and the proper notification was sent to the Sentry server.
It worked just fine, the error message was sent to the server and it appeared on the Sentry web interface. Just perfect... or not?
Not really. After the error arrived in the Sentry server, a notification should have been sent to a mailing list where developers/support would see it and act accordingly. But that email never arrived and there was no error on the Sentry server logs.
When I took a look at the SMTP server logs, I found this
12:53:12 sm-mta: NOQUEUE: connect from my.sentry.server [xxx.xxx.xxx.xxx] 12:53:12 sm-mta: AUTH: available mech=SCRAM-SHA-1 DIGEST-MD5 OTP CRAM-MD5 ANONYMOUS, allowed mech=LOGIN PLAIN 12:53:12 sm-mta: u4JArC4c001534: Milter (bogom): init success to negotiate 12:53:12 sm-mta: u4JArC4c001534: Milter (opendkim): init success to negotiate 12:53:12 sm-mta: u4JArC4c001534: Milter (opendmarc): init success to negotiate 12:53:12 sm-mta: u4JArC4c001534: Milter: connect to filters 12:53:12 sm-mta: u4JArC4c001534: milter=bogom, action=connect, continue 12:53:12 sm-mta: u4JArC4c001534: milter=opendkim, action=connect, continue 12:53:13 sm-mta: u4JArC4c001534: milter=opendmarc, action=connect, continue 12:53:17 sm-mta: u4JArC4c001534: my.sentry.server [xxx.xxx.xxx.xxx] did not issue MAIL/EXPN/VRFY/ETRN during connection to MTA
Which basically means there was an incoming connection which was suddently closed by the client.
So, what was happening? Good question indeed. First thing to try was the email testing tool that comes bundled with Sentry. In the admin panel in the web interface, there is a Mail section, at the bottom of the page you can find such tool.
I clicked there, nothing on the sentry logs, same lines in the SMTP server logs. Not really useful.
And so I started to look at Sentry's source code, to see how those emails are sent. I ended up looking at this file:
It seems that, to open the SMTP connection, it relies on the get_connection method from django, available here:
which, in this case, will use the code from the smtp backend from here:
Please note I'm linking to the files for versions 8.1.3 of sentry, which has django 1.6.11 as a dependency at the moment of writing this article.
" ... The optional timeout parameter specifies a timeout in seconds for blocking operations like the connection attempt (if not specified, the global default timeout setting will be used). If the timeout expires, socket.timeout is raised. ... "
Interesting. now, let's try to run Sentry's email sending code in a python shell/console. I'm running sentry inside a virtualenv, so after activating the environment, I start a shell and give it a try:
> sentry shell Python 2.7.11 (default, Mar 1 2016, 11:50:03) [GCC 4.2.1 Compatible FreeBSD Clang 3.4.1 (tags/RELEASE_34/dot1-final 208032)] on freebsd10 Type "help", "copyright", "credits" or "license" for more information. (InteractiveConsole) >>>
>>> from sentry.utils.email import send_mail >>> send_mail('subject', 'body message', 'email@example.com', ['firstname.lastname@example.org.']) Traceback (most recent call last): File "", line 1, in File "/home/sentry-env/lib/python2.7/site-packages/sentry/utils/email.py", line 393, in send_mail connection=get_connection(fail_silently=fail_silently), File "/home/sentry-env/lib/python2.7/site-packages/django/core/mail/__init__.py", line 50, in send_mail connection=connection).send() File "/home/sentry-env/lib/python2.7/site-packages/django/core/mail/message.py", line 276, in send return self.get_connection(fail_silently).send_messages([self]) File "/home/sentry-env/lib/python2.7/site-packages/django/core/mail/backends/smtp.py", line 87, in send_messages new_conn_created = self.open() File "/home/sentry-env/lib/python2.7/site-packages/django/core/mail/backends/smtp.py", line 48, in open local_hostname=DNS_NAME.get_fqdn()) File "/usr/local/lib/python2.7/smtplib.py", line 256, in __init__ (code, msg) = self.connect(host, port) File "/usr/local/lib/python2.7/smtplib.py", line 317, in connect (code, msg) = self.getreply() File "/usr/local/lib/python2.7/smtplib.py", line 365, in getreply + str(e)) SMTPServerDisconnected: Connection unexpectedly closed: timed out >>>
At the same time, I was able to see the usual lines in the SMTP server logs.
So, indeed there was a time out. Now, let's check the SMTP configuration. That server runs sendmail, which has an interesting feature called greet_pause, which basically makes the SMTP to hold on for some time before sending the greeting message to the client, after the initial connection. This is a nice spam protection measure, as most spam bots do not wait for that greeting message before starting to send commands, and sendmail will simply drop the connection if the client do not wait for that greeting message before start talking.
But this was not the case here, the SMTP logs should show a total different thing for that, something like
sm-mta: u5525oOE092223: rejecting commands from [220.127.116.11] [18.104.22.168] due to pre-greeting traffic after 1 seconds
In this case it seemed the timeout was happening on the client side, as if the connection were dropped by the client after wait for some time.
Interesting, let's go back to a sentry shell, check the default socket timeout there:
>>> import socket >>> socket.getdefaulttimeout() 5.0 >>>
5 seconds!, now let's look at the sendmail configuration file...
Exactly 5 seconds too. So, basically, python's smtplib was opening a connection with a time out of 5 seconds and sendmail was waiting for 5 seconds after the initial connection was established to send that greeting message. Obviously, python's smtplib was correctly and politely waiting for that greeting message before sending any commands to the SMTP server... but by the time the greeting message was about to be sent by sendmail, python closed the connection with a timeout.
Now, how to fix this?, easy, raise that timeout a bit on the client side. All we need is to use setdefaulttimeout to adjust it. As sentry is a django-based app, and still has a django-style configuration file, which is a python script that is loaded every time you run the app, all we need is to add the following two lines to sentry.conf.py
# Set the default socket timeout to a value that prevents connections # to our SMTP server from timing out, due to sendmail's greeting pause # feature. import socket socket.setdefaulttimeout(10)
(Yeah, better put a good comment there, for the next guy looking into the config file and wondering why the f*** we set that timeout there)
In this example I've raised it to 10 seconds, adjust that value to whatever fits for you.
A restart of the sentry server and et voilà, email notifications were back!