Sending email reports complete success, but I can see from logs it partially failed

ABC · March 9, 2023, 4:44pm

I sent an email to 118 students from within the Instructor email interface. It showed complete success of sending 118 emails (not “X sent, Y failed”):

This is incorrect. I was running

tutor local logs -f --tail=1 | grep worker

on the server and watching the logs. For the first 86, everything worked fine…

lms-worker_1                 | 2023-03-09 15:42:14,957 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:564 - BulkEmail ==> Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 85/119, Recipient UserId: 893
lms-worker_1                 | 2023-03-09 15:42:15,946 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:601 - BulkEmail ==> Status: Success, Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 85/119, Recipient UserId: 893
lms-worker_1                 | 2023-03-09 15:42:15,950 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:564 - BulkEmail ==> Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 86/119, Recipient UserId: 941
lms-worker_1                 | 2023-03-09 15:42:16,882 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:601 - BulkEmail ==> Status: Success, Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 86/119, Recipient UserId: 941

However, on the 87th I started seeing errors:

lms-worker_1                 | 2023-03-09 15:42:16,885 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:564 - BulkEmail ==> Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 87/119, Recipient UserId: 453
lms-worker_1                 | 2023-03-09 15:42:17,090 ERROR 235 [edx_ace.channel.django_email] [user 453] [ip 127.0.0.1] django_email.py:70 - (421, b'4.7.0 Try again later, closing connection. (MAIL) c22-20020a379a16000000b0074233b15a72sm13573679qke.116 - gsmtp', 'info@mysite.com')
lms-worker_1                 | Traceback (most recent call last):
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/edx_ace/channel/django_email.py", line 68, in deliver
lms-worker_1                 |     mail.send()
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/django/core/mail/message.py", line 284, in send
lms-worker_1                 |     return self.get_connection(fail_silently).send_messages([self])
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/django/core/mail/backends/smtp.py", line 109, in send_messages
lms-worker_1                 |     sent = self._send(message)
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/django/core/mail/backends/smtp.py", line 125, in _send
lms-worker_1                 |     self.connection.sendmail(from_email, recipients, message.as_bytes(linesep='\r\n'))
lms-worker_1                 |   File "/opt/pyenv/versions/3.8.12/lib/python3.8/smtplib.py", line 885, in sendmail
lms-worker_1                 |     raise SMTPSenderRefused(code, resp, from_addr)
lms-worker_1                 | smtplib.SMTPSenderRefused: (421, b'4.7.0 Try again later, closing connection. (MAIL) c22-20020a379a16000000b0074233b15a72sm13573679qke.116 - gsmtp', 'info@mysite.com')
lms-worker_1                 | 2023-03-09 15:42:17,094 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:601 - BulkEmail ==> Status: Success, Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 87/119, Recipient UserId: 453
lms-worker_1                 | 2023-03-09 15:42:17,101 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:564 - BulkEmail ==> Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 88/119, Recipient UserId: 950
lms-worker_1                 | 2023-03-09 15:42:17,964 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:601 - BulkEmail ==> Status: Success, Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 88/119, Recipient UserId: 950
lms-worker_1                 | 2023-03-09 15:42:17,970 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:564 - BulkEmail ==> Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 89/119, Recipient UserId: 265
lms-worker_1                 | 2023-03-09 15:42:18,074 ERROR 235 [edx_ace.channel.django_email] [user 265] [ip 127.0.0.1] django_email.py:70 - Connection unexpectedly closed
lms-worker_1                 | Traceback (most recent call last):
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/edx_ace/channel/django_email.py", line 68, in deliver
lms-worker_1                 |     mail.send()
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/django/core/mail/message.py", line 284, in send
lms-worker_1                 |     return self.get_connection(fail_silently).send_messages([self])
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/django/core/mail/backends/smtp.py", line 102, in send_messages
lms-worker_1                 |     new_conn_created = self.open()
lms-worker_1                 |   File "/openedx/venv/lib/python3.8/site-packages/django/core/mail/backends/smtp.py", line 69, in open
lms-worker_1                 |     self.connection.login(self.username, self.password)
lms-worker_1                 |   File "/opt/pyenv/versions/3.8.12/lib/python3.8/smtplib.py", line 737, in login
lms-worker_1                 |     (code, resp) = self.auth(
lms-worker_1                 |   File "/opt/pyenv/versions/3.8.12/lib/python3.8/smtplib.py", line 640, in auth
lms-worker_1                 |     (code, resp) = self.docmd("AUTH", mechanism + " " + response)
lms-worker_1                 |   File "/opt/pyenv/versions/3.8.12/lib/python3.8/smtplib.py", line 430, in docmd
lms-worker_1                 |     return self.getreply()
lms-worker_1                 |   File "/opt/pyenv/versions/3.8.12/lib/python3.8/smtplib.py", line 403, in getreply
lms-worker_1                 |     raise SMTPServerDisconnected("Connection unexpectedly closed")
lms-worker_1                 | smtplib.SMTPServerDisconnected: Connection unexpectedly closed
lms-worker_1                 | 2023-03-09 15:42:18,075 INFO 235 [edx.celery.task] [user None] [ip None] tasks.py:601 - BulkEmail ==> Status: Success, Task: 26abd567-01d2-4625-b460-325cde8a1a94, SubTask: a0d3b840-e656-45dc-b3f3-1d61d986fbf9, EmailId: 52, Recipient num: 89/119, Recipient UserId: 265

Despite the fact that it was erroring out, each of these has a “BulkEmail ==> Status: Success” line, and as shown in the image above, the final sent count acts like everything succeeded.

I believe this is due to the fact that Open edX is known to sends emails too fast, and then only rate limit itself after it has errored out. (Something I think should be fixed / be configurable.) However, this thread implies that that should have been solved in Maple, and I’m running Nutmeg. So it doesn’t seem to be solved. More to the point, the UI currently acts like all emails were sent, when they were not! This means some unknown subset of the students haven’t been getting class update emails.

I am using the paid Google Workspaces, so I’m subject to its rate limits (which I believe is supposed to be not more than one mail per second, but I can’t find the citation for that anymore.) I checked my Google Workspaces email logs, and it shows that 88 emails were sent, not 118. I checked it 15 minutes after the incident, and the log count remained at 88, so there is no error-out-and-retry occurring.

Is this a known issue? Should I file a ticket? If so, where?

ghassan · March 9, 2023, 6:41pm

Hey,

First The Thread you are referring to resolve differen’t issue of which the error thrown was SMTPSenderRefused

Bulk emails sending too fast causing gmail to block account. Is there a way to rate limit?

[36;1mlms-worker_1     |[0m     raise SMTPSenderRefused(code, resp, from_addr)
[36;1mlms-worker_1     |[0m smtplib.SMTPSenderRefused: (421, b'4.7.0 Try again later, closing connection. (MAIL) r186sm3113766qkf.128 - gsmtp',

While qouting your logs above it’s SMTPServerDisconnected

ABC:

lms-worker_1                 |     raise SMTPServerDisconnected("Connection unexpectedly closed")
lms-worker_1                 | smtplib.SMTPServerDisconnected: Connection unexpectedly closed

Secondaly to resolve your issue, is to try to the error as I did in the thread you linked above, i.e.

This edx-platform/tasks.py at d7ca7c14cd2ea1177e464d3c386aa6918e9b0093 · openedx/edx-platform · GitHub
except (SMTPDataError, SMTPSenderRefused) as exc:
becomes

except (SMTPDataError, SMTPSenderRefused, SMTPServerDisconnected) as exc:

PS: I don’t the consequence of this nor did I try it, it’s just what I would do if I were in your place.

ABC · March 9, 2023, 7:59pm

That is a good idea. And given the fact that SMTPServerDisconnected is error 421, and the existing code says it is supposed to handle errors in the 400 range, it seems reasonable to try. I’ll make a change to this, and see if it helps next time I send emails to students. Thanks!

Edit: Nope, that didn’t work , and yielded the same result of incorrect statements about everything succeeding, when in reality things started failing around send 91.