[Dovecot] Strange behavior of header_filter_callback

8 Apr 2009

      Hello. I asked about the problem in http://markmail.org/message/zsry62fcig5hqka3
. And I created simple example plug-in for deliver. It is attached

(I don't want to paste so much code)
For compile in command-line run:
# DOVECOT=<path to dovecot> gmake
...send mail...
...view dovecot lda log...
# gmake clean
# WITH_ONLY_HEADERS=1 DOVECOT=<path to dovecot> gmake
...send mail...
...view dovecot lda log...
My log (notice strings start with #):
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: Loading

modules from directory: /usr/local/lib/dovecot/lda
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: Module

loaded: /usr/local/lib/dovecot/lda/lib90_example_plugin.so
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: auth input:

uid=1002
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: auth input:

gid=1002
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: auth input: home=/var/spool/mail/pitman@virtualworld.com
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_plugin_init is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: mbox: data=/var/spool/mail/pitman@virtualworld.com
:INDEX=/var/indexes/pitman@virtualworld.com
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: mbox: INBOX

defaulted to /var/spool/mail/pitman@virtualworld.com/inbox
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: fs: root=/var/spool/mail/pitman@virtualworld.com
, index=/var/indexes/pitman@virtualworld.com, control=, inbox=/var/spool/mail/pitman@virtualworld.com
/inbox
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_deliver_mail is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_get_stream is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

make_header_filter is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

create_header_stream is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

create_stream_for_msgbody is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: #Message 1:
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_get_stream is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

make_header_filter is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

create_header_stream is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

create_stream_for_msgbody is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: #Message 1:
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: msgid=: saved

mail to INBOX
deliver(pitman@virtualworld.com): Apr 08 13:52:39 Info: example: func

example_plugin_deinit is called
My log (WITH_ONLY_HEADERS=1):
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: Loading

modules from directory: /usr/local/lib/dovecot/lda
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: Module

loaded: /usr/local/lib/dovecot/lda/lib90_example_plugin.so
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: auth input:

uid=1002
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: auth input:

gid=1002
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: auth input: home=/var/spool/mail/pitman@virtualworld.com
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_plugin_init is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: mbox: data=/var/spool/mail/pitman@virtualworld.com
:INDEX=/var/indexes/pitman@virtualworld.com
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: mbox: INBOX

defaulted to /var/spool/mail/pitman@virtualworld.com/inbox
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: fs: root=/var/spool/mail/pitman@virtualworld.com
, index=/var/indexes/pitman@virtualworld.com, control=, inbox=/var/spool/mail/pitman@virtualworld.com
/inbox
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_deliver_mail is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_get_stream is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

make_header_filter is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Return-Path: 
...
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Delivered-To: pitman@virtualworld.comm
...
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Received:

from localhost.virtualworld.com (localhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info:

#Received:      by bsdman.virtualworld.com (Postfix) with ESMTP id

3B3E11FE
for pitman@virtualworld.com; Wed,  8 Apr 2009 13:53:51

+0400 (MSD)
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: 2009-04-08T13:53:51.199182+1
From: pupkin@virtualworld.com
Reply-to: Konstantin@bsdman.virtualworld.com,
Lepa@bsdman.virtualworld.com
To: pitman@virtualworld.com
Message-Id: 20090408095351.3B3E11FE@bsdman.virtualworld.com
Date: Wed,  8 Apr 2009 13:53:51 +0400 (MSD)
Message 1
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info:

#Received:      for pitman@virtualworld.com; Wed,  8 Apr 2009

13:53:51 +0400 (MSD)
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: 2009-04-08T13:53:51.199182+1
From: pupkin@virtualworld.com
Reply-to: Konstantin@bsdman.virtualworld.com,
Lepa@bsdman.virtualworld.com
To: pitman@virtualworld.com
Message-Id: 20090408095351.3B3E11FE@bsdman.virtualworld.com
Date: Wed,  8 Apr 2009 13:53:51 +0400 (MSD)
Message 1
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Content-Type:

text/plain; charset="us-ascii"m (localhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #MIME-Version:

1.0t/plain; charset="us-ascii"m (localhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Content-
Transfer-Encoding: 7bit/plain; charset="us-ascii"m (localhost

[127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Subject:

2009-04-08T13:53:51.199182+1i"m (localhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #From: pupkin@virtualworld.com182+1i
"m (localhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Reply-to: Konstantin@bsdman.virtualworld.com
,calhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Reply-
to:      Lepa@bsdman.virtualworld.com
To: pitman@virtualworld.com
Message-Id: 20090408095351.3B3E11FE@bsdman.virtualworld.com
Date: Wed,  8 Apr 2009 13:53:51 +0400 (MSD)
Message 1
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #To: pitman@virtualworld.comalworld.com
,calhost [127.0.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Message-Id: <20090408095351.3B3E11FE@bsdman.virtualworld.com
...
.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #Date: Wed,  8

Apr 2009 13:53:51 +0400 (MSD)alworld.com>.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: #: Wed,  8 Apr

2009 13:53:51 +0400 (MSD)alworld.com>.0.1])
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_header_filter_callback is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_get_stream is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

make_header_filter is called
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: msgid=<20090408095351.3B3E11FE@bsdman.virtualworld.com
: saved mail to INBOX
deliver(pitman@virtualworld.com): Apr 08 13:53:51 Info: example: func

example_plugin_deinit is called

[Dovecot] Strange behavior of header_filter_callback

Konstantin Lepa