Closed kjnez closed 1 month ago
The logs you posted don't seem to show any significant delay. 08:37:16,955 minus 08:37:16,648 is 307 msec total from first to last log line:
DEBUG 2024-07-19 08:37:16,648 loaders 62693 140287951218368 Loading JSON file: … … DEBUG 2024-07-19 08:37:16,955 retryhandler 62693 140287951218368 No retry needed.
You might need to run some profiling to determine the actual culprit.
When you say "there's a significant delay," do you mean the call to Django's EmailMessage.send() or send_mail() or whatever blocks for 15 seconds? If the send call completes quickly, but then it takes 15 seconds for Amazon's email servers to actually get around to sending the message, that's not unusual. (And even if Amazon sends it instantly, but then it takes 15 seconds to arrive in the recipient's inbox, that's entirely normal. Email is rarely instantaneous.)
If your code is actually blocking for 15 seconds, then are you trying to send a large (1 MB+) email message or attachments and running in a CPU-limited environment? If so, there's a known issue that boto3 can be slow to sign large AWS API requests on constrained processors. (More details in boto/botocore#1561. The fix for that issue eliminated duplicated work in botocore, but couldn't do anything about the speed of Python's urlencode().)
If that's what you're running into, some options are:
[If you go with the SMTP workaround, be aware that Django's SMTP EmailBackend assumes all SMTP servers properly handle Content-Transfer-Encoding: 8bit. Amazon SES doesn't, so if your message or text attachments have any non-ASCII characters this can result in Amazon SES sending mojibake.]
Thanks for such a detailed explanation.
The delay happens before the terminal prints out anything. What I showed above is the printout immediately after the pause. The image message is not large at all (<<1MB).
One strange thing is that when logging in, there's no email sent, yet the same delay also happens. So I guess it is probably not boto's problem?
I used django-silk to profile a login POST and a signup POST. And besides /accounts/signup and /accounts/login taking more than 15s to load (there's no more granular decomposition of them in django-silk), everything else seems normal. So I guess that it probably has something to do with my django-allauth setup.
If the 15 second delay occurs on code paths that don't send email, then what you're seeing has nothing to do with django-anymail. I doubt it's a problem with django-allauth. 15 seconds is quite a long time, and suggests there may be a more fundamental problem with your code or the system where you're running it.
You've raised the same issue in at least three different projects now: anymail/django-anymail#386 (this issue), pennersr/django-allauth#3978, and cookiecutter/cookiecutter-django#5230. Before posting elsewhere, please try to isolate the actual root cause by simplifying your code.
django-allauth's maintainer gave you some great advice: remove complexity from your code, one thing at a time, and re-test at each step. (Examples: Try removing threading. Or your custom AccountAdapter. Or your custom LoginView. Is it possible that adding django-silk caused the delay? The only way to know is to work through systematically, one thing at a time.)
Once you narrow down what is or isn't relevant, you'll be able to ask a better question. Django's community page lists several places that can help with more general issues like this. (Look under "Get Help," and under "More Help" in the sidebar. But please pick only one place to post. And again, the more specific you can be about the problem, the more likely you are to get a helpful answer.)
Good hunting!
Thanks a lot for your help. I'll make an update once I figure out what's wrong with my code.
An update: it is not an email sending problem at all. I was able to get more info from the logger.
From the log it seems like certain queries are taking a lot of time:
DEBUG 2024-07-21 08:01:55,510 http_protocol 138190 140482276182912 HTTP b'POST' request for ['127.0.0.1', 50410] DEBUG 2024-07-21 08:01:55,877 utils 138190 140481993369280 (0.000) BEGIN; args=None; alias=default DEBUG 2024-07-21 08:02:03,882 utils 138190 140481993369280 (0.006) SELECT "account_emailaddress"."id", "account_emailaddress"."user_id", "account_emailaddress"."email", "account_emailaddress"."verified", "account_emailaddress"."primary", "users_user"."password", "users_user"."last_login", "users_user"."is_superuser", "users_user"."is_staff", "users_user"."is_active", "users_user"."date_joined", "users_user"."id", "users_user"."is_hibernating", "users_user"."subscription_id", "users_user"."customer_id", "users_user"."name", "users_user"."email" FROM "account_emailaddress" INNER JOIN "users_user" ON ("account_emailaddress"."user_id" = "users_user"."id") WHERE "account_emailaddress"."email" = 'me@example.com'; args=('me@example.com',); alias=default ... DEBUG 2024-07-21 08:02:04,093 utils 138190 140481993369280 (0.001) SELECT 1 AS "a" FROM "account_emailaddress" WHERE ("account_emailaddress"."user_id" = '3774a6c1426b4173a2dcfc7826117796'::uuid AND "account_emailaddress"."verified") LIMIT 1; args=(Int4(1), UUID('3774a6c1-426b-4173-a2dc-fc7826117796')); alias=default DEBUG 2024-07-21 08:02:11,966 utils 138190 140481993369280 (0.003) COMMIT; args=None; alias=default
But when I execute these queries directly in psql, they only take <10ms. I'm a little confused on why there's such a big discrepancy.
Reporting an error? It's helpful to know:
ANYMAIL = { "AMAZON_SES_CLIENT_PARAMS": { "aws_access_key_id": AWS_ACCESS_KEY_ID, "aws_secret_access_key": AWS_SECRET_ACCESS_KEY, "region_name": AWS_S3_REGION_NAME, }, }