Mail sent twice

[Sayelna]

Hello, I use post office with wsgi as cron and the mail is sometimes sent twice as following :

My wsgi file :

application = get_wsgi_application()
logger = logging.getLogger(__name__)

# Send queued mails
try:
    import uwsgidecorators
    from django.core.management import call_command

    @uwsgidecorators.timer(10, target='spooler')
    def send_queued_mail(num):
        '''Send queued mail every 10 seconds'''
        call_command('send_queued_mail', processes=1)

    @uwsgidecorators.timer(86400, target='spooler')
    def cleanup_mail(num):
        '''clean mails older than 90 days database every day'''
        call_command('cleanup_mail --days=90', processes=1)

except ImportError:
    logger.error('uwsgidecorators not found. Cron and timers are disabled')

The mail sending :

mail.send(
                owner.user.email,
                settings.DEFAULT_FROM_EMAIL,
                template=template_owner,
                language=translation.get_language(),
                context={
                    'reciever': invitee,
                    'sender': owner,
                    'protocol': 'https',
                    'domain': domain,
                    'project': collaborative,
                },
            )

Any idea of how to fix it ? Thanks !

[jrief]

@Sayelna This is difficult to reproduce. Does it still happen? Is is possible that you have two or more workers calling send_queued_mail?

One solution which could solve your problem is to rewrite in post_office/mail.py the function

def get_queued():
    return Email.objects.select_for_update() \
        .filter(status=STATUS.queued) \
        ....

[Houtmann]

Same Thing with failed mail. I think mails are not sent twice, but it is logged twice...

[i-Kozyrev]

I have the same problem. Hi! I think it happen when we specify processes in uwsgi more than 1 and trying to use the post_office with uwsgi integration. In my uwsgi log i saw

[INFO]2020-07-29 19:16:11 PID 9: Acquiring lock for sending queued emails at /tmp/post_office.lock
[INFO]2020-07-29 19:16:11 PID 7: Acquiring lock for sending queued emails at /tmp/post_office.lock
[INFO]2020-07-29 19:16:11 PID 7: Failed to acquire lock, terminating now.
[INFO]2020-07-29 19:16:11 PID 9: Started sending 1 emails with 1 processes.
[INFO]2020-07-29 19:16:11 PID 9: Process started, sending 1 emails
[INFO]2020-07-29 19:16:11 PID 8: Started sending 1 emails with 1 processes.
[INFO]2020-07-29 19:16:11 PID 8: Process started, sending 1 emails
[INFO]2020-07-29 19:16:11 PID 8: Process finished, 1 attempted, 1 sent, 0 failed
[INFO]2020-07-29 19:16:11 PID 8: 1 emails attempted, 1 sent, 0 failed
[INFO]2020-07-29 19:16:11 PID 9: Process finished, 1 attempted, 1 sent, 0 failed
[INFO]2020-07-29 19:16:11 PID 9: 1 emails attempted, 1 sent, 0 failed
[INFO]2020-07-29 19:16:12 PID 10: Acquiring lock for sending queued emails at /tmp/post_office.lock
[INFO]2020-07-29 19:16:12 PID 10: Started sending 0 emails with 1 processes.
[INFO]2020-07-29 19:16:12 PID 10: 0 emails attempted, 0 sent, 0 failed

Multiple mails sending, but there is the single mail presented in the database.

how I can specify queue to execute post_mail processes synchronously?

UPD To synchronize multiple async uwsgi "send_mail" tasks, I use wsgi.lock(). Dear developers, could you please tell me, is it the correct solution?

    @uwsgidecorators.timer(60*1, target="mail_send_spool")
    def send_queued_mail(arguments):
        """Send queued mail every 1 minutes"""
        if uwsgi.is_locked():
            return
        uwsgi.lock()
        call_command('send_queued_mail', processes=2)
        uwsgi.unlock()

[juancresc]

I have the same issue, one email being sent multiple times

[jrief]

@juancrescente Could you please describe your setup.

[juancresc]

Email is sent in a regular way using mail function. Then I'm using celery:

Some opts are:

CELERYD_NODES=7 CELERYD_OPTS="--time-limit=300 --concurrency=3"

For the same email, we can see there's more than one log that indicates that the email was sent twice

[jrief]

Please try with CELERYD_NODES=1 and --concurrency=1. If you use Celery for other tasks, you can start one worker for Email only and other workers for your other tasks. Currently the concurrency locking does not work properly.

[wolph]

I can confirm the issue. I'm seeing some mails getting sent 5 times. This is while using celery with the default config

And it's not only in the logs, my mail provider shows multiple emails sent as well

[jrief]

@WoLpH could you please share the relevant configuration directives for post_office and Celery.

[wolph]

I don't think there is anything relevant to be honest... there is no celery configuration to speak off except the configuration of a redis broker, and there is no post office configuration either. These are the only configuration settings I have for post office and celery:

POST_OFFICE = {
    'TEMPLATE_ENGINE': 'post_office',
    'CONTEXT_FIELD_CLASS': 'django.db.models.JSONField',
}

CELERY_BROKER_URL = f'redis://{WEBLIKER_REDIS_HOST}:6381/0'
CELERY_RESULT_BACKEND = f'redis://{WEBLIKER_REDIS_HOST}:6381/1'

What appears to fix it just fine (suggested by one of your earlier comments) is this:

diff --git a/post_office/mail.py b/post_office/mail.py
index 96e2cd5..0f85cee 100644
--- a/post_office/mail.py
+++ b/post_office/mail.py
@@ -186,11 +186,19 @@ def get_queued():
         (Q(scheduled_time__lte=now) | Q(scheduled_time__isnull=True)) &
         (Q(expires_at__gt=now) | Q(expires_at__isnull=True))
     )
-    return Email.objects.filter(query) \
+    return Email.objects.select_for_update(
+        skip_locked=True,
+        of=('self',),
+    ) \
+                .filter(query) \
                 .select_related('template') \
                 .order_by(*get_sending_order()).prefetch_related('attachments')[:get_batch_size()]

+from django.db import transaction
+
+
+@transaction.atomic
 def send_queued(processes=1, log_level=None):
     """
     Sends out all queued mails that has scheduled_time less than now or None

I'm not sure if there's a downside to this approach, but it appears flawless.

[e-Dan-K]

What appears to fix it just fine (suggested by one of your earlier comments) is this:

diff --git a/post_office/mail.py b/post_office/mail.py
index 96e2cd5..0f85cee 100644
--- a/post_office/mail.py
+++ b/post_office/mail.py
@@ -186,11 +186,19 @@ def get_queued():
         (Q(scheduled_time__lte=now) | Q(scheduled_time__isnull=True)) &
         (Q(expires_at__gt=now) | Q(expires_at__isnull=True))
     )
-    return Email.objects.filter(query) \
+    return Email.objects.select_for_update(
+        skip_locked=True,
+        of=('self',),
+    ) \
+                .filter(query) \
                 .select_related('template') \
                 .order_by(*get_sending_order()).prefetch_related('attachments')[:get_batch_size()]

+from django.db import transaction
+
+
+@transaction.atomic
 def send_queued(processes=1, log_level=None):
     """
     Sends out all queued mails that has scheduled_time less than now or None

I'm not sure if there's a downside to this approach, but it appears flawless.

This would work on most DBs, but not all. According to the docs, "Passing nowait=True, skip_locked=True, no_key=True, or of to select_for_update() using database backends that do not support these options, such as MySQL, raises a NotSupportedError. This prevents code from unexpectedly blocking."

But if it were coded to fall back to the "old" method on NotSupportedErrors, it'd at least work for many more users...

[xanderim]

I can confirm the issue. I'm seeing some mails getting sent 5 times. This is while using celery with the default config

And it's not only in the logs, my mail provider shows multiple emails sent as well

We have exactly the same issue. Are there any ways to fix it without reducing the concurrency?

[jrief]

@xanderim did you apply database locking? Ie. are you using the select_for_update patch shown above? I could ask the database which features are supported and write different statements with different functionality if that makes sense. What do you think?

[xanderim]

@jrief after applying the patch the issue was resolved. Thanks! Nevertheless, I think this patch should be a part of the library.

I could ask the database which features are supported and write different statements with different functionality if that > >makes sense.

It would be great!

[jrief]

@xanderim I also believe it should be part of the library. However, as @e-Dan-K noted, this has some minor issues with older versions of MySQL.

[domlysi]

@jrief I configured a separate worker for emails: "email_queue". But how do I explicitly only let the task send_queued_mail use this queue?

I tried following in my "celery.py"

# Define custom queues
app.conf.task_queues = (
    Queue('email_queue', Exchange('email'), routing_key='email_task'),
)

# Route post_office tasks to the email_queue
app.conf.task_routes = {
    'post_office.tasks.send_queued_mail': {
        'queue': 'email_queue',
        'routing_key': 'email_task',
    },
    # Add other post_office tasks if needed
}

# Default exchange and queue configuration
app.conf.task_default_exchange = 'tasks'
app.conf.task_default_exchange_type = 'topic'
app.conf.task_default_routing_key = 'task.default'

But when testing, it uses both worker I run randomly.

[jrief]

I added an alternative locking mechanism using the database instead of a mutex to lock sending jobs. This apparently solved the problems. See comments above.

[domlysi]

I added an alternative locking mechanism using the database instead of a mutex to lock sending jobs. This apparently solved the problems. See comments above.

Thank you for the quick reply. I'm running 3.8.0 and still having this issue with duplicate emails sent. Is it fixed in 3.9.0?

EDIT: But I'm not sure if this is caused by post_office. EDIT2: I realized I still have an active CRON Job besides Celery. Maybe that's the problem. I will get into it.

[jrief]

It is not my decision to not merge that pull request: https://github.com/ui/django-post_office/pull/351 . It actually would prevent this problem to happen.