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?