2

I am running a Postfix mail-server, to scan mails I forward them to amavis, after the scanning amavis forward the mail to ciphermail (a program that automatically de- and encrypts emails). Ciphermail resent the mail to amavis and amavis resend the mail to Postfix.

Ciphermail is running on a different Server than postfix and amavis.

I want to archive all mails de- and encrypted, that means I want to archive them once before passing ciphermail and once after passing ciphermail. That for I inserted the following into the /etc/postfix/main.cf

    always_bcc=archiv@example.com

The problem is that each Mail is archived three times not twice. Twice before ciphermail and once after ciphermail. My question is why is the mail send twice before ciphermail and how can I adjust postfix to send the mail just once before ciphermail and once after ciphermail.

I already tried to insert in /etc/postfix/main.cf

    receive_override_options = no_address_mappings

But now the mail is just archived once after ciphermail And if I insert in /etc/postfix/master.cf

    127.0.0.1:10029 inet n - n - - smtpd
      # [...]
      -o receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_address_mappings

A copy of the mail is just send once before ciphermail en or decrypts the mail.

The mail.log of one send mail with the setting of 3 copies of the mail:

Feb  3 13:30:25 email1mail postfix/submission/smtpd[3319]: connect from somewhere[xxx.xxx.xxx.xxx]
Feb  3 13:30:25 email1mail postfix/submission/smtpd[3319]: 47F943003E: client=somewhere[xxx.xxx.xxx.xxx], sasl_method=PLAIN, sasl_username=alice@mail.example.com
Feb  3 13:30:25 email1mail postfix/cleanup[3323]: 47F943003E: message-id=<54D0BF62.6030008@mail.example.com>
Feb  3 13:30:25 email1mail postfix/qmgr[3313]: 47F943003E: from=<alice@mail.example.com>, size=611, nrcpt=2 (queue active)
Feb  3 13:30:25 email1mail amavis[3061]: () loaded policy bank "BCM"
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) ESMTP:[127.0.0.1]:10024 /var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE: <alice@mail.example.com> -> <archiv@archiv.example.com>,<carol@mail.example.com> SIZE=611 Received: from email1mail.localdomain ([127.0.0.1]) by localhost (mail.example.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP; Tue,  3 Feb 2015 13:30:25 +0100 (CET)
Feb  3 13:30:25 email1mail postfix/submission/smtpd[3319]: disconnect from somewhere[xxx.xxx.xxx.xxx]
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) Checking: XP5xmOE51_t2 BCM [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <archiv@archiv.example.com>,<carol@mail.example.com>
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) Open relay? Nonlocal recips but not originating: archiv@archiv.example.com
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) p001 1 Content-Type: text/plain, size: 7 B, name: 
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) (!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE/parts: lstat() failed: Permission denied. ERROR\n"
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) (!)ClamAV-clamd av-scanner FAILED: CODE(0x25d1328) unexpected , output="/var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE/parts: lstat() failed: Permission denied. ERROR\n" at (eval 136) line 899.
Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) (!)WARN: all primary virus scanners failed, considering backups
Feb  3 13:30:46 email1mail amavis[3061]: (03061-05) FWD from <alice@mail.example.com> -> <archiv@archiv.example.com>,<carol@mail.example.com>, 250 2.6.0 from MTA(smtp:[192.168.1.102]:10026): 250 2.6.0 Message received
Feb  3 13:30:46 email1mail amavis[3061]: (03061-05) Passed CLEAN {RelayedInbound,RelayedOpenRelay}, BCM [xxx.xxx.xxx.xxx]:59491 [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <archiv@archiv.example.com>,<carol@mail.example.com>, Queue-ID: 47F943003E, Message-ID: <54D0BF62.6030008@mail.example.com>, mail_id: XP5xmOE51_t2, Hits: -1, size: 611, queued_as: 250 2.6.0 Message received, 21204 ms
Feb  3 13:30:46 email1mail amavis[3061]: (03061-05) TIMING-SA total 5175 ms - parse: 1.41 (0.0%), extract_message_metadata: 2.9 (0.1%), get_uri_detail_list: 0.24 (0.0%), tests_pri_-1000: 4.1 (0.1%), tests_pri_-950: 1.82 (0.0%), tests_pri_-900: 1.60 (0.0%), tests_pri_-400: 1.12 (0.0%), tests_pri_0: 5127 (99.1%), check_spf: 0.44 (0.0%), check_dkim_adsp: 41 (0.8%), check_razor2: 5001 (96.6%), check_pyzor: 59 (1.1%), tests_pri_500: 4.2 (0.1%), learn: 20 (0.4%), b_learn: 17 (0.3%), b_count_change: 6 (0.1%), get_report: 0.42 (0.0%)
Feb  3 13:30:46 email1mail postfix/smtp[3324]: 47F943003E: to=<archiv@archiv.example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=21, delays=0.07/0.01/0/21, dsn=2.6.0, status=sent (250 2.6.0 from MTA(smtp:[192.168.1.102]:10026): 250 2.6.0 Message received)
Feb  3 13:30:46 email1mail postfix/smtp[3324]: 47F943003E: to=<carol@mail.example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=21, delays=0.07/0.01/0/21, dsn=2.6.0, status=sent (250 2.6.0 from MTA(smtp:[192.168.1.102]:10026): 250 2.6.0 Message received)
Feb  3 13:30:46 email1mail postfix/qmgr[3313]: 47F943003E: removed
Feb  3 13:30:46 email1mail amavis[3061]: (03061-05) size: 611, TIMING [total 21209 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 37 (0%)0, check_init: 0 (0%)0, digest_hdr: 1 (0%)0, digest_body_dkim: 0 (0%)0, mime_decode: 8 (0%)0, get-file-type1: 36 (0%)0, parts_decode: 0 (0%)0, check_header: 1 (0%)0, AV-scan-1: 23 (0%)1, AV-scan-2: 15812 (75%)75, spam-wb-list: 2 (0%)75, SA parse: 3 (0%)75, SA check: 5171 (24%)99, decide_mail_destiny: 4 (0%)100, notif-quar: 0 (0%)100, fwd-connect: 47 (0%)100, fwd-xforward: 2 (0%)100, fwd-mail-pip: 1 (0%)100, fwd-rcpt-pip: 37 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1 (0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 5 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 7 (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-1-files: 0 (0%)100, rundown: 1 (0%)100
Feb  3 13:30:47 email1mail amavis[3060]: () loaded policy bank "ACM"
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) ESMTP:[192.168.2.10]:10028 /var/lib/amavis/tmp/amavis-20150203T130722-03060-gusE2h0r: <alice@mail.example.com> -> <archiv@archiv.example.com> Received: from ciphermail ([192.168.1.102]) by localhost (mail.example.com [192.168.2.10]) (amavisd-new, port 10028) with ESMTP for <archiv@archiv.example.com>; Tue,  3 Feb 2015 13:30:47 +0100 (CET)
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) Checking: l6papfJwmT6R ACM [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <archiv@archiv.example.com>
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) Open relay? Nonlocal recips but not originating: archiv@archiv.example.com
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) p001 1 Content-Type: text/plain, size: 7 B, name: 
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) (!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/lib/amavis/tmp/amavis-20150203T130722-03060-gusE2h0r/parts: lstat() failed: Permission denied. ERROR\n"
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) (!)ClamAV-clamd av-scanner FAILED: CODE(0x25d1328) unexpected , output="/var/lib/amavis/tmp/amavis-20150203T130722-03060-gusE2h0r/parts: lstat() failed: Permission denied. ERROR\n" at (eval 136) line 899.
Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) (!)WARN: all primary virus scanners failed, considering backups
Feb  3 13:30:47 email1mail amavis[3061]: () loaded policy bank "ACM"
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) ESMTP:[192.168.2.10]:10028 /var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE: <alice@mail.example.com> -> <carol@mail.example.com> Received: from ciphermail ([192.168.1.102]) by localhost (mail.example.com [192.168.2.10]) (amavisd-new, port 10028) with ESMTP for <carol@mail.example.com>; Tue,  3 Feb 2015 13:30:47 +0100 (CET)
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) Checking: cD-pyG9zKnpK ACM [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <carol@mail.example.com>
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) p003 1 Content-Type: multipart/encrypted
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) p001 1/1 Content-Type: application/pgp-encrypted, size: 11 B, name: 
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) p002 1/2 Content-Type: application/octet-stream, size: 469 B, name: encrypted.asc
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) (!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE/parts: lstat() failed: Permission denied. ERROR\n"
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) (!)ClamAV-clamd av-scanner FAILED: CODE(0x25d1328) unexpected , output="/var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE/parts: lstat() failed: Permission denied. ERROR\n" at (eval 136) line 899.
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) (!)WARN: all primary virus scanners failed, considering backups
Feb  3 13:31:08 email1mail postfix/smtpd[3340]: connect from localhost[127.0.0.1]
Feb  3 13:31:08 email1mail postfix/smtpd[3340]: 96AC730057: client=localhost[127.0.0.1]
Feb  3 13:31:08 email1mail postfix/cleanup[3323]: 96AC730057: message-id=<54D0BF62.6030008@mail.example.com>
Feb  3 13:31:08 email1mail postfix/qmgr[3313]: 96AC730057: from=<alice@mail.example.com>, size=2357, nrcpt=2 (queue active)
Feb  3 13:31:08 email1mail amavis[3061]: (03061-06) FWD from <alice@mail.example.com> -> <carol@mail.example.com>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10029): 250 2.0.0 Ok: queued as 96AC730057
Feb  3 13:31:08 email1mail amavis[3061]: (03061-06) Passed UNCHECKED {RelayedTaggedInbound}, ACM [xxx.xxx.xxx.xxx] [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <carol@mail.example.com>, Message-ID: <54D0BF62.6030008@mail.example.com>, mail_id: cD-pyG9zKnpK, Hits: -1, size: 1860, queued_as: 96AC730057, 21510 ms
Feb  3 13:31:08 email1mail amavis[3061]: (03061-06) TIMING-SA total 5298 ms - parse: 1.68 (0.0%), extract_message_metadata: 4.6 (0.1%), get_uri_detail_list: 0.20 (0.0%), tests_pri_-1000: 4.0 (0.1%), tests_pri_-950: 1.78 (0.0%), tests_pri_-900: 1.46 (0.0%), tests_pri_-400: 1.19 (0.0%), tests_pri_0: 5241 (98.9%), check_spf: 0.50 (0.0%), check_dkim_adsp: 41 (0.8%), check_razor2: 5001 (94.4%), check_pyzor: 171 (3.2%), tests_pri_500: 4.3 (0.1%), learn: 24 (0.5%), b_learn: 23 (0.4%), b_count_change: 9 (0.2%), get_report: 0.40 (0.0%)
Feb  3 13:31:08 email1mail amavis[3061]: (03061-06) size: 1860, TIMING [total 21515 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 3 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA: 2 (0%)0, check_init: 0 (0%)0, digest_hdr: 1 (0%)0, digest_body_dkim: 0 (0%)0, mime_decode: 11 (0%)0, get-file-type2: 31 (0%)0, parts_decode: 0 (0%)0, check_header: 1 (0%)0, AV-scan-1: 4 (0%)0, AV-scan-2: 16064 (75%)75, spam-wb-list: 4 (0%)75, SA parse: 3 (0%)75, SA check: 5295 (25%)100, decide_mail_destiny: 4 (0%)100, notif-quar: 0 (0%)100, fwd-connect: 64 (0%)100, fwd-mail-pip: 3 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 0 (0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 4 (0%)100, prepare-dsn: 0 (0%)100, main_log_entry: 9 (0%)100, update_snmp: 1 (0%)100, SMTP pre-response: 1 (0%)100, SMTP response: 0 (0%)100, unlink-3-files: 0 (0%)100, rundown: 1 (0%)100
Feb  3 13:31:08 email1mail dovecot: lmtp(3344): Connect from local
Feb  3 13:31:08 email1mail dovecot: lmtp(3344, carol@mail.example.com): RXUSJ4y/0FQQDQAAXzmN0w: msgid=<54D0BF62.6030008@mail.example.com>: saved mail to INBOX
Feb  3 13:31:08 email1mail dovecot: lmtp(3344): Disconnect from local: Successful quit
Feb  3 13:31:08 email1mail postfix/lmtp[3342]: 96AC730057: to=<carol@mail.example.com>, relay=email1mail.localdomain[private/dovecot-lmtp], delay=0.05, delays=0.01/0.02/0.01/0.01, dsn=2.0.0, status=sent (250 2.0.0 <carol@mail.example.com> RXUSJ4y/0FQQDQAAXzmN0w Saved)
Feb  3 13:31:08 email1mail postfix/smtp[3343]: 96AC730057: to=<archiv@archiv.example.com>, relay=archiv.example.com[192.168.1.103]:25, delay=0.11, delays=0.01/0.02/0.06/0.02, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 2138426503)
Feb  3 13:31:08 email1mail postfix/qmgr[3313]: 96AC730057: removed
Feb  3 13:31:09 email1mail postfix/smtpd[3345]: connect from localhost[127.0.0.1]
Feb  3 13:31:09 email1mail postfix/smtpd[3345]: A4AEC3005E: client=localhost[127.0.0.1]
Feb  3 13:31:09 email1mail postfix/cleanup[3323]: A4AEC3005E: message-id=<54D0BF62.6030008@mail.example.com>
Feb  3 13:31:09 email1mail postfix/smtpd[3345]: disconnect from localhost[127.0.0.1]
Feb  3 13:31:09 email1mail postfix/qmgr[3313]: A4AEC3005E: from=<alice@mail.example.com>, size=1358, nrcpt=2 (queue active)
Feb  3 13:31:09 email1mail amavis[3060]: (03060-06) FWD from <alice@mail.example.com> -> <archiv@archiv.example.com>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10029): 250 2.0.0 Ok: queued as A4AEC3005E
Feb  3 13:31:09 email1mail amavis[3060]: (03060-06) Passed CLEAN {RelayedOpenRelay}, ACM [xxx.xxx.xxx.xxx] [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <archiv@archiv.example.com>, Message-ID: <54D0BF62.6030008@mail.example.com>, mail_id: l6papfJwmT6R, Hits: -1, size: 871, queued_as: A4AEC3005E, 22636 ms
Feb  3 13:31:09 email1mail amavis[3060]: (03060-06) TIMING-SA total 6377 ms - parse: 1.67 (0.0%), extract_message_metadata: 5 (0.1%), get_uri_detail_list: 1.71 (0.0%), tests_pri_-1000: 4.2 (0.1%), tests_pri_-950: 1.85 (0.0%), tests_pri_-900: 1.54 (0.0%), tests_pri_-400: 1.20 (0.0%), tests_pri_0: 5226 (81.9%), check_spf: 0.40 (0.0%), check_dkim_adsp: 41 (0.6%), check_razor2: 5001 (78.4%), check_pyzor: 158 (2.5%), tests_pri_500: 4.1 (0.1%), learn: 1120 (17.6%), b_learn: 1117 (17.5%), get_report: 0.43 (0.0%)
Feb  3 13:31:09 email1mail amavis[3060]: (03060-06) size: 871, TIMING [total 22642 ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 5 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA: 2 (0%)0, check_init: 0 (0%)0, digest_hdr: 1 (0%)0, digest_body_dkim: 0 (0%)0, mime_decode: 7 (0%)0, get-file-type1: 25 (0%)0, parts_decode: 0 (0%)0, check_header: 1 (0%)0, AV-scan-1: 3 (0%)0, AV-scan-2: 16164 (71%)72, spam-wb-list: 2 (0%)72, SA parse: 3 (0%)72, SA check: 6373 (28%)100, decide_mail_destiny: 4 (0%)100, notif-quar: 0 (0%)100, fwd-connect: 25 (0%)100, fwd-mail-pip: 2 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1 (0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 4 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 8 (0%)100, update_snmp: 3 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-1-files: 0 (0%)100, rundown: 1 (0%)100
Feb  3 13:31:09 email1mail postfix/smtp[3343]: A4AEC3005E: to=<archiv@archiv.example.com>, relay=archiv.example.com[192.168.1.103]:25, delay=0.08, delays=0.01/0/0.06/0.01, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 26BF726509)
Feb  3 13:31:09 email1mail postfix/qmgr[3313]: A4AEC3005E: removed

Here is the mail.log form the archive mailserver

Feb  3 15:03:28 archiv postfix/smtpd[3185]: connect from unknown[192.168.2.10]
Feb  3 15:03:28 archiv postfix/smtpd[3185]: 7A2A9265BA: client=unknown[192.168.2.10]
Feb  3 15:03:28 archiv postfix/cleanup[3192]: 7A2A9265BA: message-id=<54D0D505.6000702@email1mail.example.com>
Feb  3 15:03:28 archiv postfix/qmgr[3125]: 7A2A9265BA: from=<bob@email1mail.example.com>, size=1567, nrcpt=1 (queue active)
Feb  3 15:03:28 archiv postfix/smtpd[3185]: disconnect from unknown[192.168.2.10]
Feb  3 15:03:28 archiv dovecot: lmtp(3195): Connect from local
Feb  3 15:03:28 archiv dovecot: lmtp(3195, archiv@archiv.example.com): 4OXSHjDV0FR7DAAAKaROBA: msgid=<54D0D505.6000702@email1mail.example.com>: saved mail to INBOX
Feb  3 15:03:28 archiv postfix/lmtp[3194]: 7A2A9265BA: to=<archiv@archiv.example.com>, relay=archiv.localdomain[private/dovecot-lmtp], delay=0.05, delays=0.01/0.01/0/0.02, dsn=2.0.0, status=sent (250 2.0.0 <archiv@archiv.example.com> 4OXSHjDV0FR7DAAAKaROBA Saved)
Feb  3 15:03:28 archiv dovecot: lmtp(3195): Disconnect from local: Successful quit
Feb  3 15:03:28 archiv postfix/qmgr[3125]: 7A2A9265BA: removed
Feb  3 15:03:28 archiv postfix/smtpd[3185]: connect from unknown[192.168.2.10]
Feb  3 15:03:28 archiv postfix/smtpd[3185]: 96F93265BD: client=unknown[192.168.2.10]
Feb  3 15:03:28 archiv postfix/cleanup[3192]: 96F93265BD: message-id=<54D0D505.6000702@email1mail.example.com>
Feb  3 15:03:28 archiv postfix/qmgr[3125]: 96F93265BD: from=<bob@email1mail.example.com>, size=1536, nrcpt=2 (queue active)
Feb  3 15:03:28 archiv dovecot: lmtp(3195): Connect from local
Feb  3 15:03:28 archiv postfix/smtpd[3185]: disconnect from unknown[192.168.2.10]
Feb  3 15:03:28 archiv dovecot: lmtp(3195, archiv@archiv.example.com): 5OXSHjDV0FR7DAAAKaROBA: msgid=<54D0D505.6000702@email1mail.example.com>: saved mail to INBOX
Feb  3 15:03:28 archiv postfix/lmtp[3194]: 96F93265BD: to=<archiv@archiv.example.com>, relay=archiv.localdomain[private/dovecot-lmtp], delay=0.01, delays=0/0/0/0.01, dsn=2.0.0, status=sent (250 2.0.0 <archiv@archiv.example.com> 5OXSHjDV0FR7DAAAKaROBA Saved)
Feb  3 15:03:28 archiv postfix/lmtp[3194]: 96F93265BD: to=<archiv@archiv.example.com>, relay=archiv.localdomain[private/dovecot-lmtp], delay=0.02, delays=0/0/0/0.01, dsn=2.0.0, status=sent (250 2.0.0 <archiv@archiv.example.com> 5OXSHjDV0FR7DAAAKaROBA Saved)
Feb  3 15:03:28 archiv dovecot: lmtp(3195, archiv@archiv.example.com): 5OXSHjDV0FR7DAAAKaROBA: msgid=<54D0D505.6000702@email1mail.example.com>: saved mail to INBOX
Feb  3 15:03:28 archiv dovecot: lmtp(3195): Disconnect from local: Successful quit
Feb  3 15:03:28 archiv postfix/qmgr[3125]: 96F93265BD: removed
masegaloeh
  • 17,978
  • 9
  • 56
  • 104
Ulli
  • 97
  • 1
  • 9
  • Can you show us the complete maillog: *from postfix receive email - bcc it - send to amavis ... until line `qmgr[pid]: somequeueid: removed`* – masegaloeh Feb 03 '15 at 11:59
  • is amavis and ciphermail running on the same server using just one instance of postfix? Could you post main.cf and master.cf? – martijnbrinkers Feb 03 '15 at 12:17
  • Ciphermail is running on a different server than amavis and postfix. So there is an other instance of postfix on the ciphermail server, but it is not runnig I just installed it because ciphermail depends on it. – Ulli Feb 03 '15 at 13:04
  • From the maillog, I only see **two emails** bcc-ed to archiv **after** chipermail processes it (by issuing command `grep 192.168.1.103 /the/snippet/maillog`). I don't see any snippet that supported your statement *each Mail is archived three times: Twice before ciphermail and once after ciphermail* – masegaloeh Feb 03 '15 at 13:23
  • Are you 100% certain that amavis sends the email directly to Ciphermail and not first to postfix and then postfix to ciphermail? – martijnbrinkers Feb 04 '15 at 10:02
  • I am 99% certain, that amavis sends the email directly to cihermail, i customized it in the config.xml of ciphermail to do so. – Ulli Feb 05 '15 at 07:47

1 Answers1

3

Disclaimer: this answer doesn't contain the solution about how to make postfix bcc email twice. I'm just decipher the content of your maillog line.

Postfix part pre-content_filter

Feb  3 13:30:25 email1mail postfix/submission/smtpd[3319]: connect from somewhere[xxx.xxx.xxx.xxx]
Feb  3 13:30:25 email1mail postfix/submission/smtpd[3319]: 47F943003E: client=somewhere[xxx.xxx.xxx.xxx], sasl_method=PLAIN, sasl_username=alice@mail.example.com
Feb  3 13:30:25 email1mail postfix/cleanup[3323]: 47F943003E: message-id=<54D0BF62.6030008@mail.example.com>

Postfix receive email from alice@mail.example.com and assign a queue-ID 47F943003E

Feb  3 13:30:25 email1mail postfix/qmgr[3313]: 47F943003E: from=<alice@mail.example.com>, size=611, nrcpt=2 (queue active)

At this stage, postfix already make BCC of your email. That's why value of nrcpt is 2 instead 1.

Feb  3 13:30:46 email1mail postfix/smtp[3324]: 47F943003E: to=<archiv@archiv.example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=21, delays=0.07/0.01/0/21, dsn=2.6.0, status=sent (250 2.6.0 from MTA(smtp:[192.168.1.102]:10026): 250 2.6.0 Message received)
Feb  3 13:30:46 email1mail postfix/smtp[3324]: 47F943003E: to=<carol@mail.example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=21, delays=0.07/0.01/0/21, dsn=2.6.0, status=sent (250 2.6.0 from MTA(smtp:[192.168.1.102]:10026): 250 2.6.0 Message received)

Two lines above was another proof that postfix already BCC your email then sent it to content filter port.

Amavis part pre-chipermail

Feb  3 13:30:25 email1mail amavis[3061]: (03061-05) ESMTP:[127.0.0.1]:10024 /var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE: <alice@mail.example.com> -> <archiv@archiv.example.com>,<carol@mail.example.com> SIZE=611 Received: from email1mail.localdomain ([127.0.0.1]) by localhost (mail.example.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP; Tue,  3 Feb 2015 13:30:25 +0100 (CET)

This is the evidence that amavis receive email with two recipients.

Feb  3 13:30:46 email1mail amavis[3061]: (03061-05) Passed CLEAN {RelayedInbound,RelayedOpenRelay}, BCM [xxx.xxx.xxx.xxx]:59491 [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <archiv@archiv.example.com>,<carol@mail.example.com>, Queue-ID: 47F943003E, Message-ID: <54D0BF62.6030008@mail.example.com>, mail_id: XP5xmOE51_t2, Hits: -1, size: 611, queued_as: 250 2.6.0 Message received, 21204 ms

This is log when amavis forward email (with two recipients) to chipermail

Amavis part post-chipermail

The strange part is when chipermail forward back to amavis. Chipermail splits the the original email into two email with one recipient per email.

Feb  3 13:30:47 email1mail amavis[3060]: (03060-06) ESMTP:[192.168.2.10]:10028 /var/lib/amavis/tmp/amavis-20150203T130722-03060-gusE2h0r: <alice@mail.example.com> -> <archiv@archiv.example.com> Received: from ciphermail ([192.168.1.102]) by localhost (mail.example.com [192.168.2.10]) (amavisd-new, port 10028) with ESMTP for <archiv@archiv.example.com>; Tue,  3 Feb 2015 13:30:47 +0100 (CET)
Feb  3 13:30:47 email1mail amavis[3061]: (03061-06) ESMTP:[192.168.2.10]:10028 /var/lib/amavis/tmp/amavis-20150203T130744-03061-ZTBAQ9iE: <alice@mail.example.com> -> <carol@mail.example.com> Received: from ciphermail ([192.168.1.102]) by localhost (mail.example.com [192.168.2.10]) (amavisd-new, port 10028) with ESMTP for <carol@mail.example.com>; Tue,  3 Feb 2015 13:30:47 +0100 (CET)

Here the evidence of email splitting. Two emails was received by amavis from chipermail.

Feb  3 13:31:08 email1mail amavis[3061]: (03061-06) Passed UNCHECKED {RelayedTaggedInbound}, ACM [xxx.xxx.xxx.xxx] [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <carol@mail.example.com>, Message-ID: <54D0BF62.6030008@mail.example.com>, mail_id: cD-pyG9zKnpK, Hits: -1, size: 1860, queued_as: 96AC730057, 21510 ms

Amavis forward email (with recipient carol) to postfix with message ID 96AC730057

Feb  3 13:31:09 email1mail amavis[3060]: (03060-06) Passed CLEAN {RelayedOpenRelay}, ACM [xxx.xxx.xxx.xxx] [xxx.xxx.xxx.xxx] <alice@mail.example.com> -> <archiv@archiv.example.com>, Message-ID: <54D0BF62.6030008@mail.example.com>, mail_id: l6papfJwmT6R, Hits: -1, size: 871, queued_as: A4AEC3005E, 22636 ms

Amavis forward email (with recipient archiv) to postfix with message ID A4AEC3005E

Postfix part post-content_filter

Feb  3 13:31:08 email1mail postfix/smtpd[3340]: connect from localhost[127.0.0.1]
Feb  3 13:31:08 email1mail postfix/smtpd[3340]: 96AC730057: client=localhost[127.0.0.1]
Feb  3 13:31:08 email1mail postfix/cleanup[3323]: 96AC730057: message-id=<54D0BF62.6030008@mail.example.com>

Postfix receive email from amavis with message ID 96AC730057

Feb  3 13:31:08 email1mail postfix/qmgr[3313]: 96AC730057: from=<alice@mail.example.com>, size=2357, nrcpt=2 (queue active)

Postfix make BCC of your email again. You can spot that the value of nrcpt is 2.

Feb  3 13:31:08 email1mail postfix/lmtp[3342]: 96AC730057: to=<carol@mail.example.com>, relay=email1mail.localdomain[private/dovecot-lmtp], delay=0.05, delays=0.01/0.02/0.01/0.01, dsn=2.0.0, status=sent (250 2.0.0 <carol@mail.example.com> RXUSJ4y/0FQQDQAAXzmN0w Saved)
Feb  3 13:31:08 email1mail postfix/smtp[3343]: 96AC730057: to=<archiv@archiv.example.com>, relay=archiv.example.com[192.168.1.103]:25, delay=0.11, delays=0.01/0.02/0.06/0.02, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 2138426503)

Postfix doesn't send the email to content filter again. It send carol's email to dovecot and send archiv's email to archiv server

In another part

Feb  3 13:31:09 email1mail postfix/smtpd[3345]: connect from localhost[127.0.0.1]
Feb  3 13:31:09 email1mail postfix/smtpd[3345]: A4AEC3005E: client=localhost[127.0.0.1]
Feb  3 13:31:09 email1mail postfix/cleanup[3323]: A4AEC3005E: message-id=<54D0BF62.6030008@mail.example.com>

Postfix receive email from amavis with message ID A4AEC3005E

Feb  3 13:31:09 email1mail postfix/qmgr[3313]: A4AEC3005E: from=<alice@mail.example.com>, size=1358, nrcpt=2 (queue active)

Postfix make BCC of your email again to itself. You can spot that the value of nrcpt is 2.

Feb  3 13:31:09 email1mail postfix/smtp[3343]: A4AEC3005E: to=<archiv@archiv.example.com>, relay=archiv.example.com[192.168.1.103]:25, delay=0.08, delays=0.01/0/0.06/0.01, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 26BF726509)

Postfix send email with two duplicate recipients to archiv server

As you can see, postfix send three copy of email after pass it to chipermail. Your log in archiv server confirm this behavior.

So, how can we bcc the email before pass to chipermail?

Right now, I don't have an idea. The problem is, postfix always pass the bcc-ed email to content_filter (chipermail and amavis). This architecture prevents to send email to bcc address before pass it to content_filter.

Fine, how can we bcc the only one email after pass to chipermail?

You already have the solution, put receive_override_options = no_address_mappings on the main.cf.

Community
  • 1
masegaloeh
  • 17,978
  • 9
  • 56
  • 104
  • Thanks for your explanation, and let me know if you have any Idea to solve this problem completely. It wold save me some storage space and performance ;-) – Ulli Feb 05 '15 at 11:05