James server doesn't accept emails with attachments

alexcustos commented 5 years ago

Hello, OpenPaaS and the James server are working very well for me except this issue. I'm pretty sure it's related to James project, but it seems Linagora took over development on that project, and I'm using linagora/james-ldap-project image (updated to the very last version), so I hope here's the right place for the issue.

Unfortunately, I found nothing specific, the James server silently swallows emails with any attachment and writes nothing helpful to the log file. I'll just describe symptoms in a list.

There are no issues with text, HTML, and combined emails at all.
IMAP clients have no issue to store emails with attachments to any folder including Sent folder.
James server properly sends emails with attachment to external email servers.
Attachment MIME type doesn't matter. I tried to send emails with TXT, PNG, PDF attachments, all of them are affected.
I faced the issue with Tika server disabled, then I ran it and enabled in the settings, but nothing was changed.
I have DNSBL and Spamassassin enabled, but disabling them change literally nothing. It doesn't even add or remove records to log file at interesting points.
James server refuses to deliver emails with attachments from external MTA as well as locally.

Here the log output from James server only:

esn_james        | 07:42:11.115 [INFO ] o.a.j.p.n.BasicChannelUpstreamHandler - Connection established from [Client_IP]
esn_james        | 07:42:12.163 [INFO ] o.a.j.s.SendMailHandler - Successfully spooled mail Mail1548834132095-941eeca1-cf38-45d8-89a1-d0192be3c75a from MaybeSender{mailAddress=Optional[alexcustos@example1.com]} on [Client_IP]/[Client_IP] for [admin@example2.com]
esn_james        | 07:42:12.304 [INFO ] o.a.j.p.n.BasicChannelUpstreamHandler - Connection closed for [Client_IP]
esn_james        | 07:42:13.025 [INFO ] o.a.j.m.e.e.ElasticSearchListeningMessageSearchIndex - Indexing mailbox Sent-CassandraId{id=707ddb00-2238-11e9-96b6-9b463fe2e7be} of user alexcustos@example1.com on message MessageUid{uid=61}
esn_james        | 07:42:13.569 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection closed for [Client_IP]
esn_james        | 07:42:13.680 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection established from [Client_IP]

Successfully spooled mail should be followed by Logging mail and Local delivered mail ... successfully from ..., but it doesn't happen for emails with attachments.

Here's complete Docker Compose output.

``` esn_james | 08:16:42.905 [INFO ] o.a.j.p.n.BasicChannelUpstreamHandler - Connection established from [Client_IP] esn_james | 08:16:43.976 [INFO ] o.a.j.s.SendMailHandler - Successfully spooled mail Mail1548836203906-55087c15-81e1-423c-af93-1fcddd629b67 from MaybeSender{mailAddress=Optional[alexcustos@example1.com]} on [Client_IP]/[Client_IP] for [admin@example2.com] esn_rabbitmq | esn_rabbitmq | =INFO REPORT==== 30-Jan-2019::08:16:44 ===b esn_rabbitmq | accepting AMQP connection <0.31292.1> (172.26.0.11:54068 -> 172.26.0.2:5672) esn | 2019-01-30T08:16:44.088Z debug ContactCollector [0b6302b8-39ba-4e5a-9085-d422c8e52b54] - New contacts to collect from: {"userEmail":"alexcustos@example1.com","emails":["admin@example2.com"]} esn | 2019-01-30T08:16:44.091Z debug Collecting contacts from: {"userEmail":"alexcustos@example1.com","emails":["admin@example2.com"]} esn_rabbitmq | esn_rabbitmq | =INFO REPORT==== 30-Jan-2019::08:16:44 === esn_rabbitmq | closing AMQP connection <0.31292.1> (172.26.0.11:54068 -> 172.26.0.2:5672) esn | 2019-01-30T08:16:44.095Z debug Collecting emails admin@example2.com for user 5c4db3a47ff638001b8cbb5f esn | 2019-01-30T08:16:44.095Z debug Collecting email admin@example2.com for user 5c4db3a47ff638001b8cbb5f esn_james | 08:16:44.106 [INFO ] o.a.j.p.n.BasicChannelUpstreamHandler - Connection closed for [Client_IP] esn_rabbitmq | esn_rabbitmq | =INFO REPORT==== 30-Jan-2019::08:16:44 === esn_rabbitmq | accepting AMQP connection <0.31321.1> (172.26.0.10:59130 -> 172.26.0.2:5672) esn | 2019-01-30T08:16:44.191Z info ::ffff:172.26.0.10 - - [30/Jan/2019:08:16:44 +0000] "GET /api/authenticationtoken/6decd642-c912-432d-b7d5-edd59992c5fe/user HTTP/1.1" 200 555 "-" "sabre-http/4.2.4 (http://sabre.io/)" esn_rabbitmq | esn_rabbitmq | =INFO REPORT==== 30-Jan-2019::08:16:44 === esn_rabbitmq | closing AMQP connection <0.31321.1> (172.26.0.10:59130 -> 172.26.0.2:5672) esn_sabre | 172.26.0.12 - - [30/Jan/2019:08:16:44 +0000] "GET /addressbooks/5c4db3a47ff638001b8cbb5f.json?personal=true&subscribed=true&shared=true&inviteStatus=2 HTTP/1.1" 200 849 "-" "-" esn | 2019-01-30T08:16:44.221Z debug ContactCollector [0b6302b8-39ba-4e5a-9085-d422c8e52b54] - Successfully processed: esn | 2019-01-30T08:16:44.221Z debug ContactCollector [0b6302b8-39ba-4e5a-9085-d422c8e52b54] - admin@example2.com has been collected: false Error: admin@example2.com is a user and will not be collected: esn | 2019-01-30T08:16:44.221Z info core.amqp#getClient() is deprecated, use core.amqp#getPubsubClient() instead esn_james | 08:16:44.791 [INFO ] o.a.j.m.e.e.ElasticSearchListeningMessageSearchIndex - Indexing mailbox Sent-CassandraId{id=707ddb00-2238-11e9-96b6-9b463fe2e7be} of user alexcustos@example1.com on message MessageUid{uid=62} esn_tika | INFO rmeta/text (image/png) esn_james | 08:16:45.199 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection closed for [Client_IP] esn_james | 08:16:45.319 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection established from [Client_IP] esn_james | 08:16:46.693 [INFO ] o.a.j.i.n.ImapChannelUpstreamHandler - Connection closed for [Client_IP] ```

rouazana commented 5 years ago

Hello and thanks for the detailed report.

Indeed this bug seems strange. Can you just check if you can see the mails with attachments via the IMAP protocol? Try for example to connect with Thunderbird.

Regards, Raphaël Ouazana.

alexcustos commented 5 years ago

@rouazana Hello, Thank you for your quick response. I don't have any trouble with stored emails. I imported a lot of them from Postfix (Maildir+ format) with isync/mbsync. I see all attachments in place, and there is no issue to open/download them from OpenPaaS and Thunderbird.

Moreover, when I'm trying to send email from Thunderbird, it doesn't show errors and moves email to Sent folder with perfectly normal attachments.

When I'm using OpenPaaS, such emails get stuck in the Outbox folder with attachments that also look perfectly normal. So I already have no idea what part of the system I should suspect.

alexcustos commented 5 years ago

I'm sorry, I completely missed the fact that I tried to get ClamAVScan mailet working with the host's ClamAV daemon and left it enabled. The issue resolved when I disabled it. But if someone knows how to point the mailet to a specific host could you please advise me. I used this Wiki article: https://wiki.apache.org/james/ClamAVScan with this mailet in the root processor:

<mailet match="All" class="ClamAVScan" onMailetException="ignore">
    <debug>true</debug>
    <host>10.0.0.10</host>
    <port>3310</port>
</mailet>

rouazana commented 5 years ago

Thank you for your update. Sorry, I'm not familiar at all with ClamAV mailet.

alexcustos commented 5 years ago

I'm closing this issue. It was neither related to ClamAV nor other mailets. They all work well separately. I didn't dig too deep because the suggested mailets order makes no sense to me. There is no reason to put file through ClamAV then reject it by extension name, so I swapped those mailets and found everything is working perfectly. It might be because I used mailet for AttachmentFileNameIs from this Wiki article https://wiki.apache.org/james/HandlingExceptions.

linagora / openpaas-esn

James server doesn't accept emails with attachments #54