search

mailcow / mailcow-dockerized

mailcow: dockerized - 🐮 + 🐋 = 💕
https://mailcow.email
GNU General Public License v3.0
8.65k stars 1.16k forks source link

Duplicate DKIM signatures when using relayhost and forwarding #1802

Closed MarkOnDuty closed 5 years ago

MarkOnDuty commented 5 years ago

We use AWS SES as a relayhost for all email and it works fine except when forwarding (ie. the user has used SoGo to forward email to some other address). Here's the relevant bit of the Postfix log:

6ABEA7E0B7: to=<blah@example.com>, relay=email-smtp.us-east-1.amazonaws.com[54.221.234.119]:25, delay=4.4, delays=0.43/0.01/3.7/0.29, dsn=5.0.0, status=bounced (host email-smtp.us-east-1.amazonaws.com[54.221.234.119] said: 554 Transaction failed: Duplicate header 'DKIM-Signature'. (in reply to end of DATA command))

So it looks like Mailcow is applying DKIM signatures twice, once when sending the initial message, then again when it is forwarding. The relayhost may not be part of the problem, but perhaps it offers a the tools for a workaround.

Is there sensible solution here? Since all of our email is relayed through SES, could I not just disable DKIM signing of messages altogether, and leave DKIM to SES?

I'm happy with a short-term hack, but am also interested in doing the right thing here. I'm just not sure what that would be.

andryyy commented 5 years ago

Hm, I don't think Rspamd would sign twice.

Could you please run docker-compose logs --tail=20 -f rspamd-mailcow and do whatever you need to do to reproduce this issue?

andryyy commented 5 years ago

How was the relayhost set up?

MarkOnDuty commented 5 years ago

I'll try to log the issue shortly.

The relayhost was set up through the Mailcow GUI. Kudos for that feature, as it made it a piece of cake to set up.

andryyy commented 5 years ago

:-)

Can you catch a mail with multiple signatures somehow, too? That we can see it?

MarkOnDuty commented 5 years ago

Here's a captured email:

Return-Path: <mark@example.com>
Received: from juggernaut.blah.com (mailcowdockerized_dovecot-mailcow_1.mailcowdockerized_mailcow-network [172.22.1.2])
    by juggernaut.blah.com (Postfix) with ESMTP id 111CC7E0B7
    for <info@rvgc.ca>; Wed, 26 Sep 2018 13:57:51 -0600 (MDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=example.com;
    s=dkim; t=1537991871; h=from:from:sender:reply-to:subject:subject:date:date:
     message-id:message-id:to:to:cc:mime-version:mime-version:
     content-type:content-type:
     content-transfer-encoding:content-transfer-encoding:in-reply-to:
     references; bh=CfMPTyVjH2mMbN1nYN7g6WzdKTqtrsKXlhhdmEZBhaM=;
    b=2HMdcT2kLgWtmszXLTHZzV347iuAzi+iNi/L0o4+lR/DOTnJ8uYbfNZ7HApUl5qAR9ut0l
    lsm7kCXlrzwa//HCVkDQS1R7kfnEPz3KwcloJqKMxFFhwpM0EmonF6sVBPNUb9xcgBzwBN
    j3mbTngs7/9E/XX06mfA3xiB02W5h6w=
X-Sieve: Pigeonhole Sieve 0.5.2 (7704de5e)
X-Sieve-Redirected-From: doink@example.com
Delivered-To: doink@example.com
Received: from juggernaut.blah.com ([172.22.1.6])
    by juggernaut.blah.com with LMTP
    id FhaFAb/kq1tkJQAAGat37w
    (envelope-from <mark@example.com>)
    for <doink@example.com>; Wed, 26 Sep 2018 13:57:51 -0600
Received: from [192.168.100.117] (unknown [184.70.193.246])
    (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits))
    (No client certificate requested)
    (Authenticated sender: mark@example.com)
    by juggernaut.blah.com (Postfix) with ESMTPSA id 4A0E07E092
    for <doink@example.com>; Wed, 26 Sep 2018 13:57:49 -0600 (MDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=example.com;
    s=dkim; t=1537991869; h=from:from:sender:reply-to:subject:subject:date:date:
     message-id:message-id:to:to:cc:mime-version:mime-version:
     content-type:content-type:
     content-transfer-encoding:content-transfer-encoding:in-reply-to:
     references; bh=CfMPTyVjH2mMbN1nYN7g6WzdKTqtrsKXlhhdmEZBhaM=;
    b=QhYXUhm9AqEan4ECtXzk0WnI7LHMqb0h4xMjSg7ZmXbAH62ZaU1mOvGF1TW78CYTAu1ROc
    M9hZz6IQB2FFQSa8WkaBGkW+9lQexiKXM8+pPqZlwUo0KSysDDNrfzF1jNZXLdw4EZ7dXT
    K8q+N86zfbkMLXpcXMUBdorL0nFdOPo=
To: doink@example.com
From: Mark <mark@example.com>
Subject: Test email sent through juggernaut.blah.com
Message-ID: <bd496c6a-d135-c36b-69f0-f0eefe99ca76@example.com>
Date: Wed, 26 Sep 2018 13:57:47 -0600
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101
 Thunderbird/60.0
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Content-Language: en-US
ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed;
    d=example.com; s=dkim; t=1537991869;
    h=from:from:sender:reply-to:subject:subject:date:date:
     message-id:message-id:to:to:cc:mime-version:mime-version:
     content-type:content-type:
     content-transfer-encoding:content-transfer-encoding:in-reply-to:
     references; bh=CfMPTyVjH2mMbN1nYN7g6WzdKTqtrsKXlhhdmEZBhaM=;
    b=BpHEmhW+7+vC+RWXs+BnqZll/G3x2Q8oo7lYXjvuzzNzQ9XafSKmLClIpYv30nvsBsdMeH
    DdpyNBm0VAakGbwRJqkaU96wiYz9xJfDbpjrTdRn8sJIeSogYaj0v+8ftwe3nUp360wP7E
    KIN4NWEJ+IAZtRH7VX7fCWk3u42vXE8=
ARC-Seal: i=1; s=dkim; d=example.com; t=1537991869; a=rsa-sha256;
    cv=none;
    b=4O8NmCWJDf+Dj7kw6tZ0KwntYLU1fTa8GmMgZtrGuPdM45iPKCxJg1ecbInYrrdJwJsOgyOAkVO0J8J1ho7ycu3TAeOnqNvY8EndCVwyJNQbOAqJ/BfPUtooyCl5VQv2A4Sj7aRCLWfhRIQGECh6D6E7lIR1Zp2v5NdAdhO+mwg=
ARC-Authentication-Results: i=1; juggernaut.blah.com;
    auth=pass smtp.auth=mark@example.com smtp.mailfrom=mark@example.com
ARC-Message-Signature: i=2; a=rsa-sha256; c=relaxed/relaxed;
    d=example.com; s=dkim; t=1537991871;
    h=from:from:sender:reply-to:subject:subject:date:date:
     message-id:message-id:to:to:cc:mime-version:mime-version:
     content-type:content-type:
     content-transfer-encoding:content-transfer-encoding:in-reply-to:
     references; bh=CfMPTyVjH2mMbN1nYN7g6WzdKTqtrsKXlhhdmEZBhaM=;
    b=eBx8it5NxVBn0UT5BB6qg2/6PiiMcwWY18uMihQuCf9ZBKWQjHoMtImbtIJYo3G4vy//HU
    38/U3IRmhz98OVZPcn3/FIECD0zJvBr9zmkJc3+b34hRglUrrQ384YwB5u9U1xVKaGVgUz
    DBolzfrjv6nNGGnUAKfyYaQwSqfZuvc=
ARC-Seal: i=2; s=dkim; d=example.com; t=1537991871; a=rsa-sha256;
    cv=pass;
    b=EF3K0hunIFJbZd9fG286sFlk8+RqoXzyx/goTdGahJ96oKkNaYXV22eZVXA1lJMLwA6aJBj38TGCiqkaLaQGx+2pHzunI1zM1fyL4a1u2z7f2wNwZ46OuXm1ctnrLCxfCZyC1xFcZ9RKICE5vUrwfdhL0z9pwOzaf1EM8l64Sq8=
ARC-Authentication-Results: i=2; juggernaut.blah.com;
    arc=pass (i=1)
Authentication-Results: juggernaut.blah.com
X-Spamd-Result: default: False [-0.70 / 15.00];
     RCVD_VIA_SMTP_AUTH(0.00)[];
     FORGED_RECIPIENTS_FORWARDING(0.00)[];
     URL_IN_SUBJECT(0.40)[juggernaut.blah.com];
     FROM_HAS_DN(0.00)[];
     FORWARDED(0.00)[doink@example.com];
     MIME_GOOD(-0.10)[text/plain];
     PREVIOUSLY_DELIVERED(0.00)[doink@example.com];
     TO_DN_NONE(0.00)[];
     RCPT_COUNT_ONE(0.00)[1];
     RCVD_COUNT_THREE(0.00)[3];
     ARC_SIGNED(0.00)[i=2];
     DKIM_SIGNED(0.00)[];
     RCVD_NO_TLS_LAST(0.00)[];
     FROM_EQ_ENVFROM(0.00)[];
     ARC_ALLOW(-1.00)[i=1];
     FORGED_RECIPIENTS(0.00)[doink@example.com,info@rvgc.ca];
     MID_RHS_MATCH_FROM(0.00)[];
     TO_DOM_EQ_FROM_DOM(0.00)[]
X-Rspamd-Queue-Id: 111CC7E0B7

This is a test email sent through juggernaut.blah.com, via 
Mark's account using Thunderbird.

I've sanitized the domain names and addresses where necessary, but consistently.

andryyy commented 5 years ago

Strange. We really need the logs then to start with.

Better run docker-compose logs --tail=1 -f postfix-mailcow rspamd-mailcow then. Just as long as your test takes.

MarkOnDuty commented 5 years ago

Here's the output from docker-compose logs --tail=1 -f postfix-mailcow rspamd-mailcow:

WARNING: The WATCHDOG_NOTIFY_EMAIL variable is not set. Defaulting to a blank string.
Attaching to mailcowdockerized_rspamd-mailcow_1, mailcowdockerized_postfix-mailcow_1
rspamd-mailcow_1     | 2018-09-26 14:25:29 #9(fuzzy) <rznbhc>; map; rspamd_radix_fin: read radix trie of 1 elements: ents=1 dup=0 tbm=0 lc=1 mem=1k free=0 waste=0
postfix-mailcow_1    | Sep 26 14:25:15 juggernaut postfix/postscreen[6019]: DISCONNECT [45.125.66.214]:56534
rspamd-mailcow_1     | 2018-09-26 14:25:36 #7(controller) <oxhd99>; map; http_map_finish: http://nginx:8081/settings.php(172.22.1.10:8081): read map data 896 bytes, next check at Wed, 26 Sep 2018 20:26:06 GMT
rspamd-mailcow_1     | 2018-09-26 14:25:36 #7(controller) <oxhd99>; map; rspamd_map_save_http_cached_file: saved data from http://nginx:8081/settings.php in /var/lib/rspamd/f0f1f1ff89a5a9c0c3050fcb9ad2426aeacf1fdf.map, 849 bytes
rspamd-mailcow_1     | 2018-09-26 14:25:36 #7(controller) <3gurte>; lua; settings.lua:636: loaded 4 elements of settings
rspamd-mailcow_1     | 2018-09-26 14:25:38 #7(controller) <oxhd99>; map; rspamd_map_cache_cb: cached data is now expired (gen mismatch 9803 != 9804) for http://nginx:8081/settings.php
rspamd-mailcow_1     | 2018-09-26 14:25:38 #6(rspamd_proxy) <oxhd99>; map; rspamd_map_read_cached: http://nginx:8081/settings.php: read map data cached 896 bytes
rspamd-mailcow_1     | 2018-09-26 14:25:38 #6(rspamd_proxy) <3gurte>; lua; settings.lua:636: loaded 4 elements of settings
rspamd-mailcow_1     | 2018-09-26 14:25:39 #7(controller) <rznbhc>; map; rspamd_map_cache_cb: cached data is now expired (gen mismatch 9859 != 9860) for http://nginx:8081/forwardinghosts.php
rspamd-mailcow_1     | 2018-09-26 14:25:40 #10(fuzzy) <oxhd99>; map; rspamd_map_read_cached: http://nginx:8081/settings.php: read map data cached 896 bytes
rspamd-mailcow_1     | 2018-09-26 14:25:40 #10(fuzzy) <3gurte>; lua; settings.lua:636: loaded 4 elements of settings
rspamd-mailcow_1     | 2018-09-26 14:25:40 #8(normal) <oxhd99>; map; rspamd_map_read_cached: http://nginx:8081/settings.php: read map data cached 896 bytes
rspamd-mailcow_1     | 2018-09-26 14:25:40 #8(normal) <3gurte>; lua; settings.lua:636: loaded 4 elements of settings
rspamd-mailcow_1     | 2018-09-26 14:25:40 #9(fuzzy) <oxhd99>; map; rspamd_map_read_cached: http://nginx:8081/settings.php: read map data cached 896 bytes
rspamd-mailcow_1     | 2018-09-26 14:25:40 #9(fuzzy) <3gurte>; lua; settings.lua:636: loaded 4 elements of settings
postfix-mailcow_1    | Sep 26 14:25:43 juggernaut postfix/smtpd[6032]: connect from unknown[184.70.193.246]
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/smtpd[6032]: Anonymous TLS connection established from unknown[184.70.193.246]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
rspamd-mailcow_1     | 2018-09-26 14:25:44 #6(rspamd_proxy) <9f45d4>; proxy; proxy_accept_socket: accepted milter connection from 172.22.1.6 port 41948
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/smtpd[6032]: 655307E092: client=unknown[184.70.193.246], sasl_method=PLAIN, sasl_username=mark@example.com
rspamd-mailcow_1     | 2018-09-26 14:25:44 #6(rspamd_proxy) <9f45d4>; milter; rspamd_milter_process_command: got connection from 184.70.193.246:8823
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/cleanup[6038]: 655307E092: message-id=<0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; accept_socket: accepted connection from 172.22.1.12 port 56866, task ptr: 00007F408086D600
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; rspamd_message_parse: loaded message; id: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>; queue-id: <655307E092>; size: 631; checksum: <25cad003908b1eb4dd3338a515136b19>
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; lua_redis.lua:193: using default redis server for module dyn_rl
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; rspamd.local.lua:135: dynamic ratelimit request for user mark@example.com returned invalid or empty data ("") or error ("nil") - trying dynamic ratelimit for domain...
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; rspamd.local.lua:139: dynamic ratelimit request for domain example.com returned invalid or empty data ("") or error ("nil")
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; lua; settings.lua:335: check for settings
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; rspamd_mime_part_detect_language: detected part language: en
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; spf_symbol_callback: skip SPF checks for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; dkim_symbol_callback: skip DKIM checks for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; lua; once_received.lua:95: Skipping once_received for authenticated user or local network
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; lua; dmarc.lua:220: skip DMARC checks for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; lua; dkim_signing.lua:125: Using selector prefix DKIM_SELECTORS for domain example.com
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; fuzzy_generate_commands: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>, part is shorter than 1000 bytes: 360 (180 * 2.00 bytes), skip fuzzy check
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; fuzzy_generate_commands: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>, part is shorter than 1000 bytes: 360 (180 * 2.00 bytes), use direct hash
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; lua; ip_score.lua:318: skip IP Score for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; arc.lua:525: Using selector prefix DKIM_SELECTORS for domain example.com
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; lua; greylist.lua:258: Score too low - skip greylisting
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; rspamd_task_write_log: id: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>, qid: <655307E092>, ip: 184.70.193.246, user: mark@example.com, from: <mark@example.com>, (default: F (no action): [-20.10/15.00] [MAILCOW_AUTH(-20.00){},MIME_GOOD(-0.10){text/plain;},ARC_NA(0.00){},ARC_SIGNED(0.00){i=1;},ASN(0.00){asn:6327, ipnet:184.68.0.0/14, country:CA;},DKIM_SIGNED(0.00){},DYN_RL_CHECK(0.00){},FROM_EQ_ENVFROM(0.00){},FROM_HAS_DN(0.00){},MID_RHS_MATCH_FROM(0.00){},RCPT_COUNT_ONE(0.00){1;},RCPT_MAILCOW_DOMAIN(0.00){example.com;},RCVD_COUNT_ZERO(0.00){0;},RCVD_TLS_ALL(0.00){},TO_DN_NONE(0.00){},TO_DOM_EQ_FROM_DOM(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){}]), len: 631, time: 171.515ms real, 14.355ms virtual, dns req: 0, digest: <25cad003908b1eb4dd3338a515136b19>, rcpts: <doink@example.com>, mime_rcpts: <doink@example.com>
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/qmgr[357]: 655307E092: from=<mark@example.com>, size=1043, nrcpt=1 (queue active)
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <62f562>; task; rspamd_protocol_http_reply: regexp statistics: 0 pcre regexps scanned, 4 regexps matched, 175 regexps total, 96 regexps cached, 0B bytes scanned using pcre, 1.04k bytes scanned total
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/smtpd[6040]: connect from mailcowdockerized_dovecot-mailcow_1.mailcowdockerized_mailcow-network[172.22.1.2]
rspamd-mailcow_1     | 2018-09-26 14:25:44 #6(rspamd_proxy) <67b9d0>; proxy; proxy_accept_socket: accepted milter connection from 172.22.1.6 port 41992
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/smtpd[6040]: D2D767E0B7: client=mailcowdockerized_dovecot-mailcow_1.mailcowdockerized_mailcow-network[172.22.1.2]
rspamd-mailcow_1     | 2018-09-26 14:25:44 #6(rspamd_proxy) <67b9d0>; milter; rspamd_milter_process_command: got connection from 172.22.1.2:45030
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; accept_socket: accepted connection from 172.22.1.12 port 56898, task ptr: 00007F408086D600
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; rspamd_message_parse: loaded message; id: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>; queue-id: <D2D767E0B7>; size: 2959; checksum: <25cad003908b1eb4dd3338a515136b19>
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/cleanup[6038]: D2D767E0B7: message-id=<0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>
postfix-mailcow_1    | Sep 26 14:25:44 juggernaut postfix/smtpd[6032]: disconnect from unknown[184.70.193.246] ehlo=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=6
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; lua_redis.lua:193: using default redis server for module dyn_rl
rspamd-mailcow_1     | 2018-09-26 14:25:44 #6(rspamd_proxy) <925f70>; proxy; proxy_milter_finish_handler: finished milter connection
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; lua_redis.lua:193: using default redis server for module keep_spam
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; lua; settings.lua:335: check for settings
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; rspamd_mime_part_detect_language: detected part language: en
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; spf_symbol_callback: skip SPF checks for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; dkim_symbol_callback: skip DKIM checks for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; lua; once_received.lua:95: Skipping once_received for authenticated user or local network
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; lua; dmarc.lua:220: skip DMARC checks for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; lua; dkim_signing.lua:125: Using selector prefix DKIM_SELECTORS for domain example.com
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; fuzzy_generate_commands: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>, part is shorter than 1000 bytes: 360 (180 * 2.00 bytes), skip fuzzy check
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; task; fuzzy_generate_commands: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>, part is shorter than 1000 bytes: 360 (180 * 2.00 bytes), use direct hash
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <b31ce7>; lua; ip_score.lua:318: skip IP Score for local networks and authorized users
rspamd-mailcow_1     | 2018-09-26 14:25:44 #8(normal) <3gurte>; lua; arc.lua:525: Using selector prefix DKIM_SELECTORS for domain example.com
rspamd-mailcow_1     | 2018-09-26 14:25:45 #8(normal) <b31ce7>; lua; greylist.lua:258: Score too low - skip greylisting
rspamd-mailcow_1     | 2018-09-26 14:25:45 #8(normal) <b31ce7>; task; rspamd_task_write_log: id: <0ea2b7ae-4d85-91cd-3987-1170a8672044@example.com>, qid: <D2D767E0B7>, ip: 172.22.1.2, from: <mark@example.com>, (default: F (no action): [-1.10/15.00] [ARC_ALLOW(-1.00){i=1;},MIME_GOOD(-0.10){text/plain;},ARC_SIGNED(0.00){i=2;},DKIM_SIGNED(0.00){},FORGED_RECIPIENTS(0.00){doink@example.com;info@something.com;},FORGED_RECIPIENTS_FORWARDING(0.00){},FORWARDED(0.00){doink@example.com;},FROM_EQ_ENVFROM(0.00){},FROM_HAS_DN(0.00){},MID_RHS_MATCH_FROM(0.00){},PREVIOUSLY_DELIVERED(0.00){doink@example.com;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_THREE(0.00){3;},RCVD_NO_TLS_LAST(0.00){},RCVD_VIA_SMTP_AUTH(0.00){},TO_DN_NONE(0.00){},TO_DOM_EQ_FROM_DOM(0.00){}]), len: 2959, time: 160.647ms real, 9.610ms virtual, dns req: 0, digest: <25cad003908b1eb4dd3338a515136b19>, rcpts: <info@something.com>, mime_rcpts: <doink@example.com>
rspamd-mailcow_1     | 2018-09-26 14:25:45 #8(normal) <b31ce7>; task; rspamd_protocol_http_reply: regexp statistics: 0 pcre regexps scanned, 4 regexps matched, 175 regexps total, 96 regexps cached, 0B bytes scanned using pcre, 2.22k bytes scanned total
postfix-mailcow_1    | Sep 26 14:25:45 juggernaut postfix/qmgr[357]: D2D767E0B7: from=<mark@example.com>, size=3290, nrcpt=1 (queue active)
postfix-mailcow_1    | Sep 26 14:25:45 juggernaut postfix/smtpd[6040]: disconnect from mailcowdockerized_dovecot-mailcow_1.mailcowdockerized_mailcow-network[172.22.1.2] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
postfix-mailcow_1    | Sep 26 14:25:45 juggernaut postfix/lmtp[6039]: 655307E092: to=<doink@example.com>, relay=dovecot[fd4d:6169:6c63:6f77::3]:24, delay=0.75, delays=0.41/0.03/0.06/0.26, dsn=2.0.0, status=sent (250 2.0.0 <doink@example.com> MhcHMUjrq1vzJgAAGat37w Saved)
postfix-mailcow_1    | Sep 26 14:25:45 juggernaut postfix/qmgr[357]: 655307E092: removed
rspamd-mailcow_1     | 2018-09-26 14:25:45 #6(rspamd_proxy) <40ed2f>; proxy; proxy_milter_finish_handler: finished milter connection
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/smtp[6041]: Trusted TLS connection established to email-smtp.us-east-1.amazonaws.com[23.21.45.252]:25: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/smtp[6041]: D2D767E0B7: to=<info@something.com>, relay=email-smtp.us-east-1.amazonaws.com[23.21.45.252]:25, delay=6.1, delays=0.19/0.06/5.5/0.27, dsn=5.0.0, status=bounced (host email-smtp.us-east-1.amazonaws.com[23.21.45.252] said: 554 Transaction failed: Duplicate header 'DKIM-Signature'. (in reply to end of DATA command))
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/cleanup[6038]: E8A4F7E0AB: message-id=<20180926202550.E8A4F7E0AB@juggernaut.blah.com>
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/qmgr[357]: E8A4F7E0AB: from=<>, size=7662, nrcpt=1 (queue active)
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/bounce[6042]: D2D767E0B7: sender non-delivery notification: E8A4F7E0AB
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/qmgr[357]: D2D767E0B7: removed
postfix-mailcow_1    | Sep 26 14:25:50 juggernaut postfix/lmtp[6039]: E8A4F7E0AB: to=<mark@example.com>, relay=dovecot[fd4d:6169:6c63:6f77::3]:24, delay=0.05, delays=0.01/0/0.02/0.01, dsn=2.0.0, status=sent (250 2.0.0 <mark@example.com> oFTLOk7rq1vzJgAAGat37w Saved)
postfix-mailcow_1    | Sep 26 14:25:51 juggernaut postfix/qmgr[357]: E8A4F7E0AB: removed
rspamd-mailcow_1     | 2018-09-26 14:25:59 #7(controller) <pr5857>; map; http_map_finish: data is not modified for server updates.rspamd.com, next check at Wed, 26 Sep 2018 20:26:29 GMT

That has the whole story, including bounce message.

andryyy commented 5 years ago

Heh. That's funny. Can we remove other DKIM/ARC headers on matching domains somehow, @vstakhov?

MarkOnDuty commented 5 years ago

I'd be happy to test that out.

But if a fix isn't forthcoming, would it be unwise to disable DKIM/ARC altogether? Amazon SES will apply it's own signature anyway, and SES is allowed by SPF, so I don't think it will hurt deliverability. Maybe my thinking is wrong?

MarkOnDuty commented 5 years ago

We did a bit more investigation of this. The problem only occurs when the email is sent from an email on our Mailcow server, to a local account, and then forwarded on from there. Email sent from outside services, to the local account, are forwarded just fine.

Looking over RSPAMD's DKIM signing options, it looks like setting sign_local to false would help. There are sign_local = true lines in local.d/arc.conf and local.d/dkim_signing.conf, which seems strange. Are these applied selectively? It seems like one would override the other if they aren't.

I would mess around without hesitation, but I have to get my head wrapped around Docker first. Is it as simple as changing one or both of those lines and restarting the service (docker-compose restart)?

MarkOnDuty commented 5 years ago

Changing sign_local to false for RSPAMD (local.d/dkim_signing.conf) seems to have fixed the issue... At least, the forwarded emails are accepted by SES and arrive at their destination.

But my understanding of all of this is less than full. I'm not at all sure if this is the ultimate solution that should be integrated into Mailcow. (The way DKIM signatures are applied seems incompatible with forwarded email, meaning there doesn't seem to be a general solution at all.) I'm open to an explanation of the implications from anyone with a better understanding.

andryyy commented 5 years ago

You can do that as workaround, yes. But this still needs to be fixed. I cannot prioritize this at the moment. :-(

stale[bot] commented 5 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.