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.

Sign up for GitHub

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

Jump to bottom

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

Open
lucasbasquerotto opened this issue Jun 11, 2024 · 6 comments
Open

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

lucasbasquerotto opened this issue Jun 11, 2024 · 6 comments
Labels
bug dependencies Pull requests that update a dependency file need-user-input Priority-Low

Comments

@lucasbasquerotto
Copy link

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
Copy link
Owner

bbottema commented Jun 11, 2024 •
edited
Loading

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).

@bbottema bbottema added bug Priority-Low need-user-input dependencies Pull requests that update a dependency file labels Jun 11, 2024
@lucasbasquerotto
Copy link
Author

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
Copy link
Author

lucasbasquerotto commented Jun 14, 2024 •
edited
Loading

@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
Copy link
Author

@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
Copy link
Owner

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
Copy link
Author

@bbottema Ok, thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug dependencies Pull requests that update a dependency file need-user-input Priority-Low
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bbottema @lucasbasquerotto