[JAMES-3451] james 3.5.0 OutOfMemoryError

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Not A Bug
• Affects Version/s: 3.5.0
• Component/s: mailbox
• Environment: aliyun linux & mysql 8 & jpa-guice
• Assignee: Unassigned
• Reporter: owenzhu
• Created: 18/Nov/20 06:59
• Updated: 30/Nov/20 17:40
• Resolved: 27/Nov/20 10:37

Description

database: mysql8

platform: aliyun linux 

jvm params: -Xms128m -Xmx2560m 

When I run the James for a long time, the james server used more and more heap memory, eventually it runs out of memory  and refuse to receive email. only restart the james will work.

java.lang.OutOfMemoryError: Java heap spacejava.lang.OutOfMemoryError: Java heap space at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2173) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1992) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3413) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:471) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3115) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2344) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2739) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966) at org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:302) at org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeQuery(LoggingConnectionDecorator.java:1169) at org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:300) at org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeQuery(JDBCStoreManager.java:1866) at org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:290) at org.apache.openjpa.jdbc.sql.SelectImpl.executeQuery(SelectImpl.java:530) at org.apache.openjpa.jdbc.sql.SelectImpl.execute(SelectImpl.java:455) at org.apache.openjpa.jdbc.sql.SelectImpl.execute(SelectImpl.java:422) at org.apache.openjpa.jdbc.sql.LogicalUnion$UnionSelect.execute(LogicalUnion.java:472) at org.apache.openjpa.jdbc.sql.LogicalUnion.execute(LogicalUnion.java:254) at org.apache.openjpa.jdbc.sql.LogicalUnion.execute(LogicalUnion.java:243) at org.apache.openjpa.jdbc.kernel.SelectResultObjectProvider.open(SelectResultObjectProvider.java:95) at org.apache.openjpa.lib.rop.EagerResultList.<init>(EagerResultList.java:36) at org.apache.openjpa.kernel.QueryImpl.toResult(QueryImpl.java:1311) at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:1062) at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:912) at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:843) at org.apache.openjpa.kernel.DelegatingQuery.execute(DelegatingQuery.java:601) at org.apache.openjpa.persistence.QueryImpl.execute(QueryImpl.java:297) at org.apache.openjpa.persistence.QueryImpl.getResultList(QueryImpl.java:314) at org.apache.james.mailbox.jpa.mail.JPAMessageMapper.findMessagesInMailbox(JPAMessageMapper.java:421) at org.apache.james.mailbox.jpa.mail.JPAMessageMapper.findAsList(JPAMessageMapper.java:113)

I used jProfile to parse the dump file and found that many transactions were waiting.See the attached screenshot for details.

In addition, I will find the following error in the log, I don't know whether it is the cause of OOM, ApplicableFlags is null in debug :

2020-11-17 21:41:00.390 [ERROR] [elastic-1226] (o.a.j.i.p.base.SelectedMailboxImpl:367) - applicableFlags is null, boxId=130656, mail=[e-mail]2020-11-17 21:41:00.390 [ERROR] [elastic-1226] (o.a.j.i.p.base.SelectedMailboxImpl:367) - applicableFlags is null, boxId=130656, mail=[e-mail]2020-11-17 21:41:00.391 [ERROR] [elastic-1226] (o.a.j.m.e.delivery.InVmEventDelivery:71) - Error while processing listenerjava.lang.RuntimeException: java.lang.NullPointerException at org.apache.james.mailbox.events.delivery.InVmEventDelivery.doDeliverToListener(InVmEventDelivery.java:86) at org.apache.james.mailbox.events.delivery.InVmEventDelivery.lambda$deliverByOption$1(InVmEventDelivery.java:69) at org.apache.james.mailbox.events.delivery.InVmEventDelivery$$Lambda$866/2127037983.run(Unknown Source) at reactor.core.publisher.MonoRunnable.subscribe(MonoRunnable.java:49) at reactor.core.publisher.Mono.subscribe(Mono.java:4087) at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:124) at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84) at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)Caused by: java.lang.NullPointerException: null at org.apache.james.imap.processor.base.SelectedMailboxImpl.mailboxEvent(SelectedMailboxImpl.java:369) at org.apache.james.imap.processor.base.SelectedMailboxImpl.event(SelectedMailboxImpl.java:312) at org.apache.james.mailbox.events.delivery.InVmEventDelivery.doDeliverToListener(InVmEventDelivery.java:83) ... 13 common frames omitted

Here is my debugging code :

if (applicableFlags == null) {
LOGGER.error("applicableFlags is null, boxId={}, mail={}", mailboxId.serialize(), mailboxEvent.getUsername().asString());
}
int size = applicableFlags.getUserFlags().length;

Issue Links

• is related to: JAMES-3026 OpenJPA memory leak