More logging of SMTP timeout exceptions

[mooreds]

Version observed on: 1.51 SMTP server information: Paubox.com

Catching and logging the timeout exceptions for an SMTP connection would be helpful.

In this case, the "Debug Enabled" SMTP setting didn't log anything, presumably because it didn't get connected.

Improvement opportunity: Even if SMTP debug is enabled, when this particular timeout occurs, no additional debug information is logged. Only the same Java exceptions are logged whether debug is on or off.

The SMTP debug logging should log something before it does anything to make it clear that a connection is in progress. And when a timeout exception occurs the debug logging should indicate what it was doing when it timed out.

It would have been helpful to see "Connecting" and "Timeout" in the logs.

Originally posted by @cah-dsaar in https://github.com/FusionAuth/fusionauth-issues/issues/2816#issuecomment-2296811987

[robotdan]

We always create an event log of type Error when we are unable to send an email.

Needs more information.

• Version this was observed on.
• SMTP server information, type, version, vendor, etc.
• How does the user know the SMTP server connection is timing out if we do not show any errors?

[mooreds]

@cah-dsaar do you have any more details about this request? Happy to re-open if you share them in a comment.

[cah-dsaar]

Version observed on: 1.51 SMTP server information: Paubox.com

Improvement opportunity: Even if SMTP debug is enabled, when this particular timeout occurs, no additional debug information is logged. Only the same Java exceptions are logged whether debug is on or off. The SMTP debug logging should log something before it does anything to make it clear that a connection is in progress. And when a timeout exception occurs the debug logging should indicate what it was doing when it timed out.

FYI, our backend also sends emails via Paubox, so I instrumented the backend code and did some ad hoc testing which resulted in sending 50 emails over the course of an hour. Average time to send the whole email was 7.2 seconds, minimum was 4.2s, max was 10.8s. Granted that was one day, running on my laptop. But times like those explain the timeouts completely.

[mooreds]

Thank you @cah-dsaar !

[robotdan]

Thanks @cah-dsaar - I'm still not sure I understand how you know a connection timeout is occurring.

When you enable debug, we are enabling debug in the jakarta.mail.Session object and then capturing the debug output from that session in an event log.

That is just to say, this is fairly low level in the Java Mail API -and if the Java Mail API is not producing the output we want, there is not much we can do about that.

Separate from the debugging, anytime the Java Mail API throws and exception, we catch it and create an Event Log of type Error. If the event log isn't created, that means we didn't receive and exception from the Java Mail API.

Maybe we can wire up a test to force a connection timeout with debug enabled and see if we can recreate what you are seeing. Any additional information you can provide about how you know a connection timeout is occurring when FusionAuth connects tot he SMTP server that would be helpful to know if we can improve this behavior.

Average time to send the whole email was 7.2 seconds, minimum was 4.2s, max was 10.8s. Granted that was one day, running on my laptop. But times like those explain the timeouts completely.

I agree... this is super slow. 😎

If this occurs from time to time.. you could increase the configured timeouts and see if that changes anything as well. They are defaulted to 2s / 2000ms, but they can be modified by adding this to the Advancced SMTP config in the admin UI.

Tenants > Edit > Advanced > SMTP settings > Additional properties

mail.smtp.connectiontimeout=2000
mail.smtp.timeout=2000

Additional detail on available Java Mail configuration: https://javaee.github.io/javamail/docs/api/com/sun/mail/smtp/package-summary.html

mail.smtp.connectiontimeout
   Socket connection timeout value in milliseconds. 
   This timeout is implemented by java.net.Socket. Default is infinite timeout.

mail.smtp.timeout
   Socket read timeout value in milliseconds. 
   This timeout is implemented by java.net.Socket. Default is infinite timeout.

Thanks!