Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Symfony->Mailer additional Method: EsmtpTransport->setAuthenticators (because of Microsoft Authentification with OAuth for SMTP sending is slow) #49701

Closed
mpoetzsch opened this issue Mar 16, 2023 · 7 comments · Fixed by #49900

Comments

@mpoetzsch
Copy link

Description

I work with the Symfony/Mailer 5.4.7 and can send E-Mails with Microsoft Outlook and XOAuth2.
But the Problem is, its very slow.
This happens because Microsoft provides the possibility for
LoginAuthenticator and XOAUTH2Authenticator in the protocoll. And in the
symfony/mailer/Transport/Smtp/EsmtpTransport.php:38 constructor are the authenticators set to use both. What understandable is when you want to support most used Authenticators.

public function __construct(string $host = 'localhost', int $port = 0, bool $tls = null, EventDispatcherInterface $dispatcher = null, LoggerInterface $logger = null)
  {
      parent::__construct(null, $dispatcher, $logger);
      // order is important here (roughly most secure and popular first)
      $this->authenticators = [
          new Auth\CramMd5Authenticator(),
          new Auth\LoginAuthenticator(),
          new Auth\PlainAuthenticator(),
          new Auth\XOAuth2Authenticator(),
      ];

But through this order, it trys always at first the LoginAuthenticator and waits for a timeout, and after
that it uses the XOAUTH2Authenticator.

I copied the EsmtpTransport class and only changed the $this->authenticators, to hold only the XOAuth2Authenticator.
There is a difference in time for sending Mails between 22s with both Authenticators, and 5s with my own EsmtpTransport class (where I set the authenticators to use only XOAuth2Authenticator).

Because I dont get automatic securityfixes/bugfixes with my own EsmtpTransport class. I want to ask if we can create a possibility to set the $this->authenticators?

What I see there is only a possibility to add additional authenticators.

Example

No response

@mpoetzsch mpoetzsch changed the title Symfony->Mailer additional Method: EsmtpTransport->setAuthenticators (because of Microsoft OAuth while SMTP sending is slow) Symfony->Mailer additional Method: EsmtpTransport->setAuthenticators (because of Microsoft Authentification with OAuth for SMTP sending is slow) Mar 16, 2023
@xabbuh
Copy link
Member

xabbuh commented Mar 16, 2023

it trys always at first the LoginAuthenticator and waits for a timeout

This is the part I do not understand. Why does the transport have to wait for a timeout? Is that something that can be improved?

@mpoetzsch
Copy link
Author

mpoetzsch commented Mar 17, 2023

What I did see, the Mailer simply tries all possible Authenticators in the sequence like in the $this->authenticators array.
Microsoft provides the possibilities of Login and XOAuth. The Mailer tries at first the LoginAuthenticator with the accessToken in the password, this is not working and needs much time (ca. 14s) and than the mailer takes the XOAuth2Authenticator for authentification. This works and the E-Mail is send.

One Solution is to set the $this->authenticators with only the XOAuth2Authenticator.

Another really user-/developerfriendly solution would maybe be, if the EsmtpTransport checks if in the password-field is an access token (they have a special format) and than automaticly only uses the XOAUTH2Authenticator. (but not sure if this is possible, think it should be, but didnt look over the code again)

I think another solution is not possible, because the mailer can't know which of the possible authenticationmethods it should prefer, you have to tell him which Authentication he has to use.

I try to provide additional context, like Protocol. That you see, what happens.

@mpoetzsch
Copy link
Author

mpoetzsch commented Mar 17, 2023

Here the Client/Server-Communication while sending the Mail.

In line 21 the Microsoft server says which authentication methods it supports.

In line 26-33 you see that the LoginAuthenticator is used.
In line 28 the Username is sent to the server, the server answers 1.5 seconds later
in line 30 the password (access token). The server answers 7 seconds later with 535 5.7.139 Authentication unsuccessful,
in line 32 the Mailer sends the 'RSET' command and the server answers 5 seconds later.

So the time for the LoginAuthenticator is mostly bad because of these too long answers of the Microsoftservers (1.5s + 7s + 5s). So for that you can't do anything or fix anything.

But we could avoid these slow answers, when we can avoid the LoginAuthenticator, and only use the XOAuth2Authenticator.

After that, in Lines 34-44, the Mailer tries the XOAuth2Authenticator and sends the email.

2: [2023-03-17T14:30:02.115385+01:00] http.DEBUG: C: EHLO [127.0.0.1]
3: [2023-03-17T14:30:02.130963+01:00] http.DEBUG: S: 250-BE1P281CA0162.outlook.office365.com Hello [77.64.144.222]
4: 250-SIZE 157286400
5: 250-PIPELINING
6: 250-DSN
7: 250-ENHANCEDSTATUSCODES
8: 250-STARTTLS
9: 250-8BITMIME
10: 250-BINARYMIME
11: 250-CHUNKING
12: 250 SMTPUTF8
13: [2023-03-17T14:30:02.131881+01:00] http.DEBUG: C: STARTTLS
14: [2023-03-17T14:30:02.146749+01:00] http.DEBUG: S: 220 2.0.0 SMTP server ready
15: [2023-03-17T14:30:02.188760+01:00] http.DEBUG: C: EHLO [127.0.0.1]
16: [2023-03-17T14:30:02.204588+01:00] http.DEBUG: S: 250-BE1P281CA0162.outlook.office365.com Hello [77.64.144.222]
17: 250-SIZE 157286400
18: 250-PIPELINING
19: 250-DSN
20: 250-ENHANCEDSTATUSCODES
21: 250-AUTH LOGIN XOAUTH2
22: 250-8BITMIME
23: 250-BINARYMIME
24: 250-CHUNKING
25: 250 SMTPUTF8
26: [2023-03-17T14:30:02.205257+01:00] http.DEBUG: C: AUTH LOGIN
27: [2023-03-17T14:30:02.221339+01:00] http.DEBUG: S: 334 VXNlcm5hbWU6
28: [2023-03-17T14:30:02.221932+01:00] http.DEBUG: C: c7VwcG8ydEB0cmFzb0dtYmhMZWlwemlnLm0ubWljcm9zb2Z0LmNvbQ==
29: [2023-03-17T14:30:02.236138+01:00] http.DEBUG: S: 334 UGFzc3dvcmQ6
30: [2023-03-17T14:30:02.236923+01:00] http.DEBUG: C: ZXlKMGVYQWlPaUpLVjFRaUxDSnViMjVqWlNJNkltUmlUVWhRYnpBMU5scHdRak5GVldoVlNIaGlMV3hoVFhCYVoxVndYMVF6WWpCUVNERnhNRm8zY21NaUxDSmhiR2NpT2lKU1V6STFOaUlzSW5nMWRDSTZJaTFMU1ROUk9XNU9VamRpVW05bWVHMWxXbTlZY1dKSVdrZGxkeUlzSW10cFpDSTZJaTFMU1ROUk9XNU9VamRpVW05bWVHMWxXbTlZY1dKSVdrZGxkeUo5LmV5SmhkV1FpT2lKb2RIUndjemTDTDI5MWRHeHZiMnN1YjJabWFXTmxMbU52YlNJc0ltbHpjeUk2SW1oMGRIQnpPaTh2YzNSekxuZHBibVJ2ZDNNdWJtVjBMelJtWmpGak9HVTJMVFJtT0dFdE5EazROUzA0TmpWaUxUaG1aV0ZsWVRaak5tTXpNQzhpTENKcFlYUWlPakUyTnprd05UazFNREFzSW01aVppSTZNVFkzT1RBMU9UVXdNQ3dpWlhod0lqb3hOamM1TURZME5UQXdMQ0poWTJOMElqb3dMQ0poWTNJaU9pSXhJaXdpWVdsdklqb2lRVlJSUVhrdk9GUkJRVUZCTVc1Sk5YVkdOV1l5YURBM1pXNVBPQ3MxYkcxTWNsQmxhSEpFUzBGMk1qbFllRTFOTVc5RVMzQTBiV0owWkVwTloxVlhlR052YVVwUk4yMVNTWEIxZUNJc0ltRnRjaUk2V3lKd2QyUWlYU3dpWVhCd1gyUnBjM0JzWVhsdVlXMWxJam9pZUUxcFpDQnliM1Z1WkdOMVltVWlMQ0poY0hCcFpDSTZJbUUyTURFMU56YzJMVE5qT0RBdE5ESmpZaTA1TlRJekxUaGhOREk1T1RSaE4yWm1NQ0lzSW1Gd2NHbGtZV055SWpvaU1TSXNJbVZ1Wm5CdmJHbGtjeUk2VzEwc0ltWmhiV2xzZVY5dVlXMWxJam9pUjIxaVNDSXNJbWRwZG1WdVgyNWhiV1VpT2lKVWNtRnpieUlzSW1sd1lXUmtjaUk2SWpJMExqRXpOQzR4TlM0Mk1TSXNJbTVoYldVaU9pSlVjbUZ6YnlCSGJXSklJaXdpYjJsa0lqb2laV0ZtWm1WaE4yVXRPREJoTUMwME56QXlMV0prWm1JdE5UWTJOVFl6TXpBMllURXlJaXdpY0hWcFpDSTZJakV3TURNeU1EQXlOMEU1UkVVeE1VSWlMQ0p5YUNJNklqQXVRVlUwUVRWemFuaFVOSEJRYUZWdFIxYzBYM0UyYlhoelRVRkpRVUZCUVVGQlVFVlFlbWRCUVVGQlFVRkJRVU5FUVU1ckxpSXNJbk5qY0NJNklrbE5RVkF1UVdOalpYTnpRWE5WYzJWeUxrRnNiQ0JUVFZSUUxsTmxibVFpTENKemFXUWlPaUpsWlRneU1tTTNNeTAzTnpnNExUUXhZemd0T0daa05TMWpNVEUxTXpJME0yUTNORGtpTENKemFXZHVhVzVmYzNSaGRHVWlPbHNpYTIxemFTSmRMQ0p6ZFdJaU9pSlNUVGwwV1VoNlNEZDFRVk5JU2xKbGVWSm9ORmRGTlRoMVNYbExlVWhhZGsxdFFVRkJOWFZtVUhRMElpd2lkR2xrSWpvaU5HWm1NV000WlRZdE5HWTRZUzAwT1RnMUxUZzJOV0l0T0dabFlXVmhObU0yWXpNd0lpd2lkVzVwY1hWbFgyNWhiV1VpT2lKemRYQndiM0owUUhSeVlYTnZSMjFpYUV4bGFYQjZhV2N1YjI1dGFXTnliM052Wm5RdVkyOXRJaXdpZFhCdUlqb2ljM1Z3Y0c5eWRFQjBjbUZ6YjBkdFltaE1aV2x3ZW1sbkxtOXViV2xqY205emIyWjBMbU52YlNJc0luVjBhU0k2SW01VFRURnBOV2syVmxWWE0zQlFWRE5sZG5OVVFVRWlMQ0oyWlhJaU9pSXhMakFpTENKM2FXUnpJanBiSWpZeVpUa3dNemswTFRZNVpqVXROREl6TnkwNU1Ua3dMVEF4TWpFM056RTBOV1V4TUNJc0ltSTNPV1ppWmpSa0xUTmxaamt0TkRZNE9TMDRNVFF6TFRjMllqRTVOR1U0TlRVd09TSmRmUS5IZWFpN3F1Y3loV2pTNG94NDJOYnhfd3Vjc2ltM2tQSGtYbEo0LXNvZzNvbEFLWkgzU2ZzejQ1SE5LcGdBWGp5RVFHbDNsc3NfY3otMXVnMkR6SHRKdThXUDl5c0phOC1veFU2aHc3T2ZxT1J1dmtGVE0yN2VFY0kxX1N3ZlRhc2V5Mi1jNDFqNE9NVUlHV1ZnNHFWX1d1NXJFUVhoNk15Vjd0Zl9pSk41OUNYVENaVk1kOGJlWFBuM0ktN09XYWNNNE55aFpYLU9MUzM4VVdPNXc5WWNYRXZ4NHZYWGdYOXFRb2VZNUdiLVZPbGkzbVVrWWtIcUxxbkE0OVhPRFJNTXF6NmRyS05wdF9Qb0ZpMzZTdEtxUHYxcmpIYnRBTy05VEhmOXJFdmR2U3dNTGpzeVpSTUhoanF5Q1VIam5PN0xXLVJmV1c2ZlB5azM0MGRVVEJURmc=
31: [2023-03-17T14:30:09.823012+01:00] http.DEBUG: S: 535 5.7.139 Authentication unsuccessful, the request did not meet the criteria to be authenticated successfully. Contact your administrator. [BE1P281CA0162.DEUP281.PROD.OUTLOOK.COM 2023-03-17T13:30:09.804Z 08DB268AE2066018]
32: [2023-03-17T14:30:09.823815+01:00] http.DEBUG: C: RSET
33: [2023-03-17T14:30:14.943007+01:00] http.DEBUG: S: 250 2.0.0 Resetting
34: [2023-03-17T14:30:14.943611+01:00] http.DEBUG: C: AUTH XOAUTH2 dXNlcj1zdFOOBAJ0QHRyYXNvR21iaExlaXB6aWcub25taWNyb3NvZnQuY29tAWF1dGg9QmVhcmVyIGV5SjBlWEFpT2lKS1YxUWlMQ0p1YjI1alpTSTZJbVJpVFVoUWJ6QTFObHB3UWpORlZXaFZTSGhpTFd4aFRYQmFaMVZ3WDFRellqQlFTREZ4TUZvM2NtTWlMQ0poYkdjaU9pSlNVekkxTmlJc0luZzFkQ0k2SWkxTFNUTlJPVzVPVWpkaVVtOW1lRzFsV205WWNXSklXa2RsZHlJc0ltdHBaQ0k2SWkxTFNUTlJPVzVPVWpkaVVtOW1lRzFsV205WWNXSklXa2RsZHlKOS5leUpoZFdRaU9pSm9kSFJ3Y3pvdkwyOTFkR3h2YjJzdWIyWm1hV05sTG1OdmJTSXNJbWx6Y3lJNkltaDBkSEJ6T2k4dmMzUnpMbmRwYm1SdmQzTXVibVYwTHpSbVpqRmpPR1UyTFRSbU9HRXRORGs0TlMwNE5qVmlMVGhtWldGbFlUWmpObU16TUM4aUxDSnBZWFFpT2pFMk56a3dOVGsxTURBc0ltNWlaaUk2TVRZM09UQTFPVFV3TUN3aVpYaHdJam94TmpjNU1EWTBOVEF3TENKaFkyTjBJam93TENKaFkzSWlPaUl4SWl3aVlXbHZJam9pUVZSUlFYa3ZPRlJCUVVGQk1XNUpOWFZHTldZeWFEQTNaVzVQT0NzMWJHMU1jbEJsYUhKRVMwRjJNamxZZUUxTk1XOUVTM0EwYldKMFpFcE5aMVZYZUdOdmFVcFJOMjFTU1hCMWVDSXNJbUZ0Y2lJNld5SndkMlFpWFN3aVlYQndYMlJwYzNCc1lYbHVZVzFsSWpvaWVFMXBBB0J5YjNWdVpHTjFZbVVpTENKaGNIQnBaQ0k2SW1FMk1ERTFOemMyTFROak9EQXROREpqWWkwNU5USXpMVGhoTkRJNU9UUmhOMlptTUNJc0ltRndjR2xrWVdOeUlqb2lNU0lzSW1WdVpuQnZiR2xrY3lJNlcxMHNJbVpoYldsc2VWOXVZVzFsSWpvaVIyMWlTQ0lzSW1kcGRtVnVYMjVoYldVaU9pSlVjbUZ6YnlJc0ltbHdZV1JrY2lJNklqSTBMakV6TkM0eE5TNDJNU0lzSW01aGJXVWlPaUpVY21GemJ5QkhiV0pJSWl3aWIybGtJam9pWldGbVptVmhOMlV0T0RCaE1DMDBOekF5TFdKa1ptSXROVFkyTlRZek16QTJZVEV5SWl3aWNIVnBaQ0k2SWpFd01ETXlNREF5TjBFNVJFVXhNVUlpTENKeWFDSTZJakF1UVZVMFFUVnphbmhVTkhCUWFGVnRSMWMwWDNFMmJYaHpUVUZKUVVGQlFVRkJVRVZRZW1kQlFVRkJRVUZCUVVORVFVNXJMaUlzSW5OamNDSTZJa2xOUVZBdVFXTmpaWE56UVhOVmMyVnlMa0ZzYkNCVFRWUlFMbE5sYm1RaUxDSnphV1FpT2lKbFpUZ3lNbU0zTXkwM056ZzRMVFF4WXpndE9HWmtOUzFqTVRFMU16STBNMlEzTkRraUxDSnphV2R1YVc1ZmMzUmhkR1VpT2xzaWEyMXphU0pkTENKemRXSWlPaUpTVFRsMFdVaDZTRGQxUVZOSVNsSmxlVkpvTkZkRk5UaDFTWGxMZVVoYWRrMXRRVUZCTlhWbVVIUTBJaXdpZEdsa0lqb2lOR1ptTVdNNFpUWXROR1k0WVMwME9UZzFMVGcyTldJdE9HWmxZV1ZoTm1NMll6TXdJaXdpZFc1cGNYVmxYMjVoYldVaU9pSnpkWEJ3YjNKMFFIUnlZWE52UjIxaWFFeGxhWEI2YVdjdWIyNXRhV055YjNOdlpuUXVZMjl0SWl3aWRYQnVJam9pYzNWd2NHOXlkRUIwY21GemIwZHRZbWhNWldsd2VtbG5MbTl1YldsamNtOXpiMlowTG1OdmJTSXNJblYwYVNJNkltNVRUVEZwTldrMlZsVlhNM0JRVkRObGRuTlVRVUVpTENKMlpYSWlPaUl4TGpBaUxDSjNhV1J6SWpwYklqWXlaVGt3TXprMExUWTVaalV0TkRJek55MDVNVGt3TFRBeE1qRTNOekUwTldVeE1DSXNJbUkzT1daaVpqUmtMVE5sWmprdE5EWTRPUzA0TVRRekxUYzJZakU1TkdVNE5UVXdPU0pkZlEuSGVhaTdxdWN5aFdqUzRveDQyTmJ4X3d1Y3NpbTNrUEhrWGxKNC1zb2czb2xBS1pIM1Nmc3o0NUhOS3BnQVhqeUVRR2wzbHNzX2N6LTF1ZzJEekh0SnU4V1A5eXNKYTgtb3hVNmh3N09mcU9SdXZrRlRNMjdlRWNJMV9Td2ZUYXNleTItYzQxajRPTVVJR1dWZzRxVl9XdTVyRVFYaDZNeVY3dGZfaUpONTlDWFRDWlZNZDhiZVhQbjNJLTdPV2FjTTROeWhaWC1PTFMzOFVXTzV3OVljWEV2eDR2WFhnWDlxUW9lWTVHYi1WT2xpM21Va1lrSHFMcW5BNDlYT0RSTU1xejZkcktOcHRfUG9GaTM2U3RLcVB2MXJqSGJ0QU8tOVRIZjlyRXZkdlN3TUxqc3laUk1IaGpxeUNVSGpuTzdMVy1SZldXNmZQeWszNDBkVVRCVEZnAQE=
35: [2023-03-17T14:30:15.148705+01:00] http.DEBUG: S: 235 2.7.0 Authentication successful
36: [2023-03-17T14:30:15.149296+01:00] http.DEBUG: Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" started []
37: [2023-03-17T14:30:15.150213+01:00] http.DEBUG: C: MAIL FROM:<foo@ba.onmicrosoft.com>
38: [2023-03-17T14:30:15.174874+01:00] http.DEBUG: S: 250 2.1.0 Sender OK
39: [2023-03-17T14:30:15.175400+01:00] http.DEBUG: C: RCPT TO:<foo@ba.com>
40: [2023-03-17T14:30:15.189564+01:00] http.DEBUG: S: 250 2.1.5 Recipient OK
41: [2023-03-17T14:30:15.190049+01:00] http.DEBUG: C: DATA
42: [2023-03-17T14:30:15.204003+01:00] http.DEBUG: S: 354 Start mail input; end with <CRLF>.<CRLF>
43: [2023-03-17T14:30:15.206247+01:00] http.DEBUG: C: 
44: .
45: [2023-03-17T14:30:15.398333+01:00] http.DEBUG: S: 250 2.0.0 OK <f10f56f1a31366df8b244c1146eb535b@ba.onmicrosoft.com> [Hostname=BE1P281MB1425.DEUP281.PROD.OUTLOOK.COM]
46: [2023-03-17T14:30:15.398996+01:00] http.INFO: Mail sent
47: [2023-03-17T14:30:18.152805+01:00] http.DEBUG: Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" stopping
48: [2023-03-17T14:30:18.153348+01:00] http.DEBUG: C: QUIT
49: [2023-03-17T14:30:18.168573+01:00] http.DEBUG: S: 221 2.0.0 Service closing transmission channel
50: [2023-03-17T14:30:18.169185+01:00] http.DEBUG: Email transport "Symfony\Component\Mailer\Transport\Smtp\SmtpTransport" stopped

(All Data are anonymized, including access token)

@xabbuh
Copy link
Member

xabbuh commented Mar 17, 2023

Reading the code I do not really see a reason why the code should hang there. Can you try debugging the execution using Xdebug or some other debug?

@mpoetzsch
Copy link
Author

mpoetzsch commented Mar 17, 2023

Okay I updated the comment above, with the correct times and statements. Im sorry for first misleading statement. Now its correct and is also plausible.
So we cant improve the LoginAuthenticator, its good how it is :D

@cedric-anne
Copy link
Contributor

cedric-anne commented Mar 19, 2023

I recently experienced the same issue and I confirm it is slow. Problem here is that the Azure server takes a long time to execute first failing AUTH LOGIN (probably to prevent brute force attacks) and RSET commands. Having the ability to redefine authenticators could help to improve login time.

I can work on this part if everyone agrees to add this ability via a simple setter.

@cedric-anne
Copy link
Contributor

Done in #49900, waiting for reviews.

@fabpot fabpot closed this as completed Apr 14, 2023
fabpot added a commit that referenced this issue Apr 14, 2023
… (cedric-anne)

This PR was merged into the 6.3 branch.

Discussion
----------

[Mailer] Allow overriding default eSMTP authenticators

| Q             | A
| ------------- | ---
| Branch?       | 6.3
| Bug fix?      | no
| New feature?  | yes
| Deprecations? | no
| Tickets       | Fix #49701
| License       | MIT
| Doc PR        | symfony/symfony-docs#... TODO

SMTP authentication using OAuth token on Azure servers is really long, due to high latency responses from the SMTP server (probably to prevent brute-force attacks).
Indeed, a `AUTH LOGIN` command is sent first, and have to wait for about 5 seconds get the error response back. Then a `RSET` command is sent and also have to wait for about 5 seconds get a response back. The `AUTH XOAUTH2` command is then sent and all is fast after that.

Adding the ability to override default eSMTP authenticators will permit developers to explicitely define that only `XOAUTH2` authenticator has to be used, to prevent high latency in SMTP authentication.

I will update the documentation once new methods signatures will be validated.

Commits
-------

bb656d0 [Mailer] Allow overriding default eSMTP authenticators
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants