Recipient_bcc_maps not working with verbosity 1

[notc]

I use the following settings in my postfix configuration to forward bcc-mails to piler: recipient_delimiter = + recipient_bcc_maps = pcre:/etc/postfix/bcc_map

This works as long as the verbosity option in the piler.conf is set to 5. If I change this setting to 1 (default) only "cc" and "to" recipients are displayed in the piler gui (Only 2 x-piler header lines with 3 recpients). I haven't tested other loglevels.

Maillog output when using verbosity 1:

#!
piler-smtp[3557]: connected from <IP-ADDRESS>:53166 on descriptor 6 (active connections: 1)
piler-smtp[3557]: received: TD434892SM8KNUBA, from=[e-mail], size=3206, client=<IP-ADDRESS>
piler-smtp[3557]: disconnected from <IP-ADDRESS> on descriptor 6 (0 active connections)
piler-smtp[3557]: connected from <IP-ADDRESS>:53170 on descriptor 6 (active connections: 1)
piler-smtp[3557]: received: 7Z2DRPB7T5T9WN2Z, from=[e-mail], size=3270, client=<IP-ADDRESS>
piler-smtp[3557]: disconnected from <IP-ADDRESS> on descriptor 6 (0 active connections)
piler[3568]: 0/TD434892SM8KNUBA: 400000005c530a103142f8340094ff613d5d, size=3282/1880, attachments=0, reference=, message-id=<[e-mail]>, retention=3660, folder=0, delay=0.2067, status=stored
piler[3569]: 1/7Z2DRPB7T5T9WN2Z: discarding: duplicate message, id: 36, message-id: <[e-mail]>
piler[3569]: 1/7Z2DRPB7T5T9WN2Z: 400000005c530a1130e0524c00df586b4daa, size=3313/0, attachments=0, reference=, message-id=<[e-mail]>, retention=0, folder=0, delay=0.1069, status=duplicate

Maillog output when using verbosity 5:

#!
piler-smtp[13470]: connected from <IP-ADDRESS>:54456 on descriptor 6 (active connections: 1)
piler-smtp[13470]: processing command: *EHLO mx.test.de#015#012*
piler-smtp[13470]: sent: 250-piler.test.local#015#012250-PIPELINING#015#012250-STARTTLS#015#012250-SIZE#015#012250 8BITMIME
piler-smtp[13470]: processing command: *STARTTLS#015#012*
piler-smtp[13470]: starttls request from client
piler-smtp[13470]: sent: 220 Ready to start TLS
piler-smtp[13470]: waiting for ssl handshake
piler-smtp[13470]: SSL_accept() result, rc=-1, errorcode: 2, error text: error:00000000:lib(0):func(0):reason(0)
piler-smtp[13470]: processing command: *EHLO mx.test.de#015#012*
piler-smtp[13470]: sent: 250-piler.test.local#015#012250-PIPELINING#015#012250-SIZE#015#012250 8BITMIME
piler-smtp[13470]: processing command: *MAIL FROM:<[e-mail]> SIZE=2915#015#012*
piler-smtp[13470]: sent: 250 Ok
piler-smtp[13470]: processing command: *RCPT TO:<archive+bcc-test=[e-mail]>#015#012*
piler-smtp[13470]: sent: 250 Ok
piler-smtp[13470]: processing command: *DATA#015#012*
piler-smtp[13470]: sent: 354 Send mail data; end it with <CRLF>.<CRLF>
piler-smtp[13470]: received: ZWBD9ZHFZFHTKCDG, from=[e-mail], size=3285, client=<IP-ADDRESS>
piler-smtp[13470]: sent: 250 OK <ZWBD9ZHFZFHTKCDG>
piler-smtp[13470]: processing command: *QUIT#015#012*
piler-smtp[13470]: sent: 221 piler.test.local Goodbye
piler-smtp[13470]: disconnected from <IP-ADDRESS> on descriptor 6 (0 active connections)
piler[13474]: 400000005c5316300b7c0e4c007dee16ac18: hdr_len: 3103, offset: 3
piler[13474]: 400000005c5316300b7c0e4c007dee16ac18: touch ec6d1631f8c28b87148f92c2e05b52aa03a77ea544d5069fb72a91aa3c4d0775 OK (<[e-mail]>)
piler[13474]: 400000005c5316300b7c0e4c007dee16ac18: stored '400000005c5316300b7c0e4c007dee16ac18.m' 3328/1912 bytes
piler[13474]: 400000005c5316300b7c0e4c007dee16ac18: stored 3 recipients, rc=0
piler[13474]: 400000005c5316300b7c0e4c007dee16ac18: stored metadata, rc=0
piler[13474]: 0/ZWBD9ZHFZFHTKCDG: 400000005c5316300b7c0e4c007dee16ac18, size=3328/1912, attachments=0, reference=, message-id=<[e-mail]>, retention=3660, folder=0, delay=0.0765, status=stored
piler-smtp[13470]: connected from <IP-ADDRESS>:54464 on descriptor 6 (active connections: 1)
piler-smtp[13470]: processing command: *EHLO mx.test.de#015#012*
piler-smtp[13470]: sent: 250-piler.test.local#015#012250-PIPELINING#015#012250-STARTTLS#015#012250-SIZE#015#012250 8BITMIME
piler-smtp[13470]: processing command: *STARTTLS#015#012*
piler-smtp[13470]: starttls request from client
piler-smtp[13470]: sent: 220 Ready to start TLS
piler-smtp[13470]: waiting for ssl handshake
piler-smtp[13470]: SSL_accept() result, rc=-1, errorcode: 2, error text: error:00000000:lib(0):func(0):reason(0)
piler-smtp[13470]: processing command: *EHLO mx.test.de#015#012*
piler-smtp[13470]: sent: 250-piler.test.local#015#012250-PIPELINING#015#012250-SIZE#015#012250 8BITMIME
piler-smtp[13470]: processing command: *MAIL FROM:<[e-mail]> SIZE=2860#015#012*
piler-smtp[13470]: sent: 250 Ok
piler-smtp[13470]: processing command: *RCPT TO:<archive+to-test=[e-mail]>#015#012*
piler-smtp[13470]: sent: 250 Ok
piler-smtp[13470]: processing command: *RCPT TO:<archive+cc-test=[e-mail]>#015#012*
piler-smtp[13470]: sent: 250 Ok
piler-smtp[13470]: processing command: *DATA#015#012*
piler-smtp[13470]: sent: 354 Send mail data; end it with <CRLF>.<CRLF>
piler-smtp[13470]: received: 4Z2O31H6CL2ZCWS2, from=[e-mail], size=3238, client=<IP-ADDRESS>
piler-smtp[13470]: sent: 250 OK <4Z2O31H6CL2ZCWS2>
piler-smtp[13470]: processing command: *QUIT#015#012*
piler-smtp[13470]: sent: 221 piler.test.local Goodbye
piler-smtp[13470]: disconnected from <IP-ADDRESS> on descriptor 6 (0 active connections)
piler[13474]: 400000005c5316311031706c0046ab0beb83: hdr_len: 3089, offset: 3
piler[13474]: 0/4Z2O31H6CL2ZCWS2: discarding: duplicate message, id: 187, message-id: <[e-mail]>
piler[13474]: 0/4Z2O31H6CL2ZCWS2: 400000005c5316311031706c0046ab0beb83, size=3314/0, attachments=0, reference=, message-id=<[e-mail]>, retention=0, folder=0, delay=0.0189, status=duplicate

[Janos SUTO]

I disagree. I've just checked the code for LOG_DEBUG entries and only syslog() calls are affected. The purpose of verbosity=5 is to provide very detailed logging of what's happening inside piler, however it doesn't affect how piler processes the emails.

If you still insist that there's a bug related, then I need some proof to see what's going on, eg. mysql metadata and the stored email (I assume these are test emails only).

[notc]

I rechecked and have to admit, that you are right. There is no problem with the "bcc" function, but with how gmail is handling sent emails using "bcc" and "cc". The initial email is split and send through different mailservers. In my postfix log I can see connections from different google mailservers for one mail. This problem doesn't occur with a self hosted Postfix as sender. Could you try to reproduce this problem?

[Janos SUTO]

As I said I seriously doubt that this issue is real. Anyway, tell me what to do exactly.

[notc]

• Configure the following options in your postfix main.cf:

#!
recipient_delimiter = + 
recipient_bcc_maps = pcre:/etc/postfix/bcc_map

• Create a bcc_map in your postfix configuration directory

#!
/^(.*)@(.*)$/      archive+$1=$2@<PILER HOSTNAME>

• Set process_rcpt_to_addresses to 1 in your piler.conf
• Use a gmail account to send an email with "to", "cc" and "bcc" to your postfix
• Review the sent mails in the GUI or via MySQL -> Only "to" and "cc" appear

[Janos SUTO]

I didn't have time to investigate this. As I claimed before, I still doubt that the verbosity level affects what you think. Case is closed.