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