Sentry email notifications not arriving?
August 2017
Sun Mon Tue Wed Thu Fri Sat
    1 2 3 4 5
6 7 8 9 10 11 12
13 14 15 16 17 18 19
20 21 22 23 24 25 26
27 28 29 30 31    
About
This site is an effort to share some of the base knowledge I have gathered through all this years working with Linux, FreeBSD, OpenBSD, Python or Zope, among others. So, take a look around and I hope you will find the contents useful.
Recent Entries
Recent Comments
Recent Trackbacks
Categories
OpenBSD (9 items)
BSD (0 items)
FreeBSD (19 items)
Linux (3 items)
Security (3 items)
Python (22 items)
Zope (13 items)
Daily (144 items)
e-shell (9 items)
Hacks (14 items)
PostgreSQL (3 items)
OSX (8 items)
Nintendo DS (0 items)
enlightenment (0 items)
Apache (3 items)
Nintendo Wii (1 items)
Django (24 items)
Music (12 items)
Plone (7 items)
Varnish (0 items)
Lugo (2 items)
Sendmail (0 items)
europython (7 items)
Cherokee (1 items)
self (1 items)
Nature (1 items)
Hiking (0 items)
uwsgi (0 items)
nginx (0 items)
cycling (9 items)
Networking (1 items)
DNS (0 items)
Archives

Syndicate this site (XML)

RSS/RDF 0.91

10 junio
2016

Sentry email notifications not arriving?

Hint: the timeout is the key!

Getsentry logo

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[1534]: NOQUEUE: connect from my.sentry.server [xxx.xxx.xxx.xxx]
12:53:12 sm-mta[1534]: AUTH: available mech=SCRAM-SHA-1 DIGEST-MD5 OTP CRAM-MD5 ANONYMOUS, allowed mech=LOGIN PLAIN
12:53:12 sm-mta[1534]: u4JArC4c001534: Milter (bogom): init success to negotiate
12:53:12 sm-mta[1534]: u4JArC4c001534: Milter (opendkim): init success to negotiate
12:53:12 sm-mta[1534]: u4JArC4c001534: Milter (opendmarc): init success to negotiate
12:53:12 sm-mta[1534]: u4JArC4c001534: Milter: connect to filters
12:53:12 sm-mta[1534]: u4JArC4c001534: milter=bogom, action=connect, continue
12:53:12 sm-mta[1534]: u4JArC4c001534: milter=opendkim, action=connect, continue
12:53:13 sm-mta[1534]: u4JArC4c001534: milter=opendmarc, action=connect, continue
12:53:17 sm-mta[1534]: 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.

Weird.

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:

https://github.com/getsentry/sentry/blob/8.1.3/src/sentry/utils/email.py

It seems that, to open the SMTP connection, it relies on the get_connection method from django, available here:

https://github.com/django/django/blob/1.6.11/django/core/mail/__init__.py

which, in this case, will use the code from the smtp backend from here:

https://github.com/django/django/blob/1.6.11/django/core/mail/backends/smtp.py

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.

A bit further down the chain, django uses smtplib.SMTP from the base library of python 2. Now, looking at the documentation, it mentions a socket timeout:

" ... 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', 'from@my.domain', ['to@my-other.domain.'])
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[92223]: u5525oOE092223: rejecting commands from [113.132.2.5]
[113.132.2.5] 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...

FEATURE(`greet_pause', 5000)

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.

WOW

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!

Posted by wu at 06:35 | Comments (0) | Trackbacks (0)
<< Store python PersistentMapping objects into an objects TreeSet | Main | Cyberpunk cycling >>
Comments
There are no comments.
Trackbacks
Please send trackback to:http://blog.e-shell.org/323/tbping
There are no trackbacks.
Post a comment