search

bbottema / simple-java-mail

Simple API, Complex Emails (Jakarta Mail smtp wrapper)
http://www.simplejavamail.org
Apache License 2.0
1.2k stars 261 forks source link

[bug] error deallocating object already removed from the pool #535

Open lucasbasquerotto opened 3 weeks ago

lucasbasquerotto commented 3 weeks ago

Hi, we started using this library for some weeks after upgrading to Java 20 and it is working fine so far (thanks), except for an error that happens a few times a day (normally between 2 and 5 times).

Our mailer configuration is:

Mailer mailer = MailerBuilder
    .withSMTPServer(SMTP_HOST, SMTP_PORT, SMTP_USER, SMTP_PASSWORD)
    .withSessionTimeout(60* 1000)
    .withThreadPoolSize(20) // multi-threaded batch handling
    .async()
    .withConnectionPoolMaxSize(20)
    .withConnectionPoolClaimTimeoutMillis(60 * 1000) // wait max 1 minute for available connection (default forever)
    .withConnectionPoolExpireAfterMillis(30 * 1000) // keep connections spinning for 30 seconds (default 5 seconds)
    .withProperties(getProperties())
    .buildMailer();

With the properties:

private static Properties getProperties() {
    Properties props = new Properties();
    props.put("mail.transport.protocol", "smtp");
    props.put("mail.smtp.port", SMTP_PORT);
    props.put("mail.smtp.auth", "true");
    props.put("mail.smtp.ssl.enable", "true");
    props.put("mail.smtp.starttls.enable", "true");
    props.put("mail.smtp.ssl.ciphersuites","SSL_RSA_WITH_RC4_128_MD5 SSL_RSA_WITH_RC4_128_SHA TLS_RSA_WITH_AES_128_CBC_SHA TLS_DHE_RSA_WITH_AES_128_CBC_SHA TLS_DHE_DSS_WITH_AES_128_CBC_SHA SSL_RSA_WITH_3DES_EDE_CBC_SHA SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA SSL_RSA_WITH_DES_CBC_SHA SSL_DHE_RSA_WITH_DES_CBC_SHA SSL_DHE_DSS_WITH_DES_CBC_SHA SSL_RSA_EXPORT_WITH_RC4_40_MD5 SSL_RSA_EXPORT_WITH_DES40_CBC_SHA SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA TLS_EMPTY_RENEGOTIATION_INFO_SCSV");
    props.put("mail.smtp.connectiontimeout", "60000");
    props.put("mail.smtp.timeout", "60000");
    props.put("mail.smtp.writetimeout", "60000");
    return props;
}

And the libraries versions:

implementation 'org.simplejavamail:simple-java-mail:8.6.2'
implementation 'org.simplejavamail:batch-module:8.6.2'

We sometimes, almost every day, see the error in the logs:

2024-06-11 06:29:32,162 ERROR [org.bbottema.genericobjectpool.GenericObjectPool] (pool-15-thread-1) error deallocating object already removed from the pool, ignoring it from now one...: org.simplejavamail.smtpconnectionpool.TransportHandlingException: error closing transport connection
        at deployment.app.war//org.simplejavamail.smtpconnectionpool.TransportAllocator.deallocate(TransportAllocator.java:83)
        at deployment.app.war//org.simplejavamail.smtpconnectionpool.TransportAllocator.deallocate(TransportAllocator.java:28)
        at deployment.app.war//org.bbottema.genericobjectpool.GenericObjectPool$AutoAllocatorDeallocator.deallocate(GenericObjectPool.java:284)
        at deployment.app.war//org.bbottema.genericobjectpool.GenericObjectPool$AutoAllocatorDeallocator.allocatedCorePoolAndDeallocateOneOrPlanDeallocations(GenericObjectPool.java:270)
        at deployment.app.war//org.bbottema.genericobjectpool.GenericObjectPool$AutoAllocatorDeallocator.run(GenericObjectPool.java:256)
        at java.base/java.lang.Thread.run(Thread.java:1623)
Caused by: jakarta.mail.MessagingException: Can't send command to SMTP host;
  nested exception is:
        java.net.SocketException: Connection or outbound has closed
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendCommand(SMTPTransport.java:2464)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendCommand(SMTPTransport.java:2451)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.close(SMTPTransport.java:1399)
        at deployment.app.war//org.simplejavamail.smtpconnectionpool.TransportAllocator.deallocate(TransportAllocator.java:81)
        ... 5 more
Caused by: java.net.SocketException: Connection or outbound has closed
        at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:1297)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.util.TraceOutputStream.write(TraceOutputStream.java:120)
        at java.base/[java.io](http://java.io/).BufferedOutputStream.flushBuffer(BufferedOutputStream.java:125)
        at java.base/[java.io](http://java.io/).BufferedOutputStream.implFlush(BufferedOutputStream.java:252)
        at java.base/[java.io](http://java.io/).BufferedOutputStream.flush(BufferedOutputStream.java:240)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendCommand(SMTPTransport.java:2462)
        ... 8 more

We can't even process those errors like we do for every other error log in our application because it doesn't happen when sending emails (Future<Void> future = mailer.sendMail(email); ... future.get()), it happens in background, probably in some background process that manages the email connection pool, so we can't format the error the way we want to show in the logs.

We send about 100.000 to 200.000 emails per day (SES), and I see that this error is more common in periods with more emails sent at the same time (although it might be this way because the chance for triggering this error increases when sending more emails).

Any suggestions on how to fix it?

bbottema commented 3 weeks ago

We did fix some issues recently that seem similar to what you're describing. The issues occurred in an upstream library used by the batch-module (generic-object-pool, clustered-object-pool and smtp-connection-pool, which all form a chain of dependencies).

It might be worth to try 8.11.1. I have a feeling this has been solved already (but these things are always difficult to pinpoint).

lucasbasquerotto commented 2 weeks ago

Thanks for the feedback. I will define the version 8.11.1 in the next website update, and will see if the issue is solved.

lucasbasquerotto commented 2 weeks ago

@bbottema I updated the website with the version 8.11.1 today, and about after 40 minutes I received the following error twice:

2024-06-14 09:22:47,282 ERROR [org.simplejavamail.internal.util.concurrent.NamedRunnable] (Simple Java Mail async mail sender, executor 1 / thread 14864) Failed to run sendMail process: org.simplejavamail.mailer.internal.MailerException: Failed to send email [ID: '<1009748286.14863.1718367766467@acb1a9b87474>'], reason: Third party error
        at deployment.app.war//org.simplejavamail.mailer.internal.SendMailClosure.handleException(SendMailClosure.java:85)
        at deployment.app.war//org.simplejavamail.mailer.internal.SendMailClosure.executeClosure(SendMailClosure.java:72)
        at deployment.app.war//org.simplejavamail.mailer.internal.AbstractProxyServerSyncingClosure.run(AbstractProxyServerSyncingClosure.java:59)
        at deployment.app.war//org.simplejavamail.internal.util.concurrent.NamedRunnable.run(NamedRunnable.java:40)
        at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1623)
Caused by: jakarta.mail.MessagingException: Exception reading response;
  nested exception is:
        java.net.SocketException: Connection reset
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:2509)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.issueSendCommand(SMTPTransport.java:2386)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.finishData(SMTPTransport.java:2128)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1306)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.lambda$sendMessage$0(TransportRunner.java:61)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.sendUsingConnectionPool(TransportRunner.java:92)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.runOnSessionTransport(TransportRunner.java:77)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.sendMessage(TransportRunner.java:56)
        at deployment.app.war//org.simplejavamail.mailer.internal.SendMailClosure.executeClosure(SendMailClosure.java:69)
        ... 6 more
Caused by: java.net.SocketException: Connection reset
        at java.base/[sun.nio.ch](http://sun.nio.ch/).NioSocketImpl.implRead(NioSocketImpl.java:318)
        at java.base/[sun.nio.ch](http://sun.nio.ch/).NioSocketImpl.read(NioSocketImpl.java:345)
        at java.base/[sun.nio.ch](http://sun.nio.ch/).NioSocketImpl$1.read(NioSocketImpl.java:794)
        at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1025)
        at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:483)
        at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:477)
        at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
        at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1461)
        at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1066)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.util.TraceInputStream.read(TraceInputStream.java:107)
        at java.base/[java.io](http://java.io/).BufferedInputStream.fill(BufferedInputStream.java:258)
        at java.base/[java.io](http://java.io/).BufferedInputStream.implRead(BufferedInputStream.java:292)
        at java.base/[java.io](http://java.io/).BufferedInputStream.read(BufferedInputStream.java:279)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.util.LineInputStream.readLine(LineInputStream.java:104)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:2489)
        ... 14 more

It seems an error about sending a specific email, which could be fine, the issue is that it logs the error instead of just throwing an exception that can be caught after calling future.get() (I don't know if future.get() throws the exception tough).

This is not about the original error of this issue, but the original error (dealocating) only happened rarely, some days it didn't even happen, so I wait a few days to see if that error happens.

But regarding this new error, is there something that I can do so that it's not directly logged as error, and just throw an exception that I can handle when calling future.get()?

lucasbasquerotto commented 2 weeks ago

@bbottema Another exception that happened after updating (Can't send command to SMTP host):

2024-06-14 09:43:29,356 ERROR [org.simplejavamail.internal.util.concurrent.NamedRunnable] (Simple Java Mail async mail sender, executor 1 / thread 24981) Failed to run sendMail process: org.simplejavamail.mailer.internal.MailerException: Failed to send email [ID: '<452494817.24980.1718369008650@acb1a9b87474>'], reason: Third party error
        at deployment.app.war//org.simplejavamail.mailer.internal.SendMailClosure.handleException(SendMailClosure.java:85)
        at deployment.app.war//org.simplejavamail.mailer.internal.SendMailClosure.executeClosure(SendMailClosure.java:72)
        at deployment.app.war//org.simplejavamail.mailer.internal.AbstractProxyServerSyncingClosure.run(AbstractProxyServerSyncingClosure.java:59)
        at deployment.app.war//org.simplejavamail.internal.util.concurrent.NamedRunnable.run(NamedRunnable.java:40)
        at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1623)
Caused by: jakarta.mail.MessagingException: Can't send command to SMTP host;
  nested exception is:
        java.net.SocketException: Connection or outbound has closed
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendCommand(SMTPTransport.java:2464)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendCommand(SMTPTransport.java:2451)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.issueCommand(SMTPTransport.java:2367)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.issueSendCommand(SMTPTransport.java:2404)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.finishData(SMTPTransport.java:2128)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1306)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.lambda$sendMessage$0(TransportRunner.java:61)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.sendUsingConnectionPool(TransportRunner.java:92)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.runOnSessionTransport(TransportRunner.java:77)
        at deployment.app.war//org.simplejavamail.mailer.internal.util.TransportRunner.sendMessage(TransportRunner.java:56)
        at deployment.app.war//org.simplejavamail.mailer.internal.SendMailClosure.executeClosure(SendMailClosure.java:69)
        ... 6 more
Caused by: java.net.SocketException: Connection or outbound has closed
        at java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:1297)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.util.TraceOutputStream.write(TraceOutputStream.java:120)
        at java.base/[java.io](http://java.io/).BufferedOutputStream.flushBuffer(BufferedOutputStream.java:125)
        at java.base/[java.io](http://java.io/).BufferedOutputStream.implFlush(BufferedOutputStream.java:252)
        at java.base/[java.io](http://java.io/).BufferedOutputStream.flush(BufferedOutputStream.java:240)
        at org.eclipse.angus.mail//org.eclipse.angus.mail.smtp.SMTPTransport.sendCommand(SMTPTransport.java:2462)
        ... 16 more

The main issue is that I can't handle these errors. I send lots of emails every day and it's expected that some of them fail, so is there a way to make it just throw the error so that I can handle it instead of logging the error and bloating our error logs? (maybe changing some setting to not log errors and just throw them or something similar)

bbottema commented 2 weeks ago

Yes, I will give it some thought. It will take at least a week or two to come up with a fix, since I'm on (a short) vacation starting this weekend.

lucasbasquerotto commented 2 weeks ago

@bbottema Ok, thanks!