[Mimedefang] MIMEdefang not executing mimedefang-filter?

Rolf E. Sonneveld R.E.Sonneveld at sonnection.nl
Thu Jan 24 11:24:45 EST 2013 

Hi, all,

running MD 2.71 (but the same problems shows up in 2.73)

I have a mimedefang-filter which has run fine for more than a year now 
on an old Solaris 10 system. I have installed MD and the same 
mimedefang-filter on a new system (both Solaris, old one sun4u 
architecture, the new one sun4v architecture). On both systems Postfix 
is talking to MD, with milter version = 6. The problem I see is, that 
the mimedefang-filter does not convert the message on the new system, 
while it does at the old system. All I see in the log file (when I 
enable debugging) is:

Jan 24 16:22:05 host01 mimedefang-multiplexor[9362]: [ID 268819 
mail.info] started; minSlaves=2, maxSlaves=10, maxRequests=500, 
maxIdleTime=300, busyTimeout=600, clientTimeout=10
Jan 24 16:22:05 host01 mimedefang-multiplexor[9362]: [ID 778059 
mail.info] Starting slave 0 (pid 9364) (1 running): Bringing slaves up 
to minSlaves (2)
Jan 24 16:22:05 host01 mimedefang[9379]: [ID 328151 mail.debug] 0: 
./mimedefang.c(2540): free(2ed70)
Jan 24 16:22:05 host01 mimedefang[9379]: [ID 255816 mail.info] 
MIMEDefang alive. slavesReservedForLoopback=-1 
AllowNewConnectionsToQueue=0 doRelayCheck=0 doHeloCheck=0 
doSenderCheck=1 doRecipientCheck=0
Jan 24 16:22:05 host01 mimedefang[9379]: [ID 936676 mail.info] 
Multiplexor alive - entering main loop
Jan 24 16:22:08 host01 mimedefang-multiplexor[9362]: [ID 778059 
mail.info] Starting slave 1 (pid 9380) (2 running): Bringing slaves up 
to minSlaves (2)
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(503): ENTER mfconnect
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1983): ENTER mfclose
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(2034): ENTER cleanup
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(2036): EXIT cleanup: SMFIS_CONTINUE
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(2000): EXIT mfclose: SMFIS_CONTINUE
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 100294 mail.debug] 33318: 
./mimedefang.c(546): malloc(56) = 2eeb8
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 977949 mail.debug] 33318: 
./mimedefang.c(580): strdup("host01") = 2f318
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 100294 mail.debug] 33318: 
./mimedefang.c(594): malloc(65) = 2eef8
Jan 24 16:22:15 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(699): EXIT mfconnect: SMFIS_CONTINUE
Jan 24 16:22:18 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(717): ENTER helo
Jan 24 16:22:18 host01 mimedefang[9379]: [ID 977949 mail.debug] 33318: 
./mimedefang.c(726): strdup("mail") = 2f378
Jan 24 16:22:18 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(760): EXIT helo: SMFIS_CONTINUE
Jan 24 16:23:00 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(789): ENTER envfrom
Jan 24 16:23:00 host01 mimedefang[9379]: [ID 977949 mail.debug] 33318: 
./mimedefang.c(823): strdup("<my.mailaddr at xy.companyx.") = 33438
Jan 24 16:23:00 host01 mimedefang[9379]: [ID 977949 mail.debug] 33318: 
./mimedefang.c(872): strdup("/data/mimedefang/spool/md") = 2ed70
Jan 24 16:23:00 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1003): EXIT envfrom: SMFIS_CONTINUE
Jan 24 16:23:06 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1098): ENTER rcptto
Jan 24 16:23:06 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1195): EXIT rcptto: SMFIS_CONTINUE or SMFIS_ACCEPT
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1218): ENTER header
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1329): EXIT header: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1347): ENTER eoh
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 977949 mail.debug] 33318: 
./mimedefang.c(1359): strdup("91D573CA46") = 2f810
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1392): EXIT eoh: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1415): ENTER body
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(1505): EXIT body: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1544): ENTER eom
Jan 24 16:23:14 host01 mimedefang.pl[9380]: [ID 702911 mail.info] 
MDLOG,91D573CA46,mail_in,,,<my.mailaddr at xy.companyx.nl>,<r.e.sonneveld at sonnection.nl>,New 
Message
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(2034): ENTER cleanup
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 590879 mail.info] 
91D573CA46: Not cleaning up /data/mimedefang/spool/mdefang-IPPn000 
because of command-line `-d' flag
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(2064): free(2ed70)
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(2068): free(33438)
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(2078): EXIT cleanup: SMFIS_CONTINUE
Jan 24 16:23:14 host01 mimedefang[9379]: [ID 173077 mail.debug] 33318: 
./mimedefang.c(1965): EXIT eom: 0
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(1983): ENTER mfclose
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 277548 mail.debug] 33318: 
./mimedefang.c(2034): ENTER cleanup
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(2078): EXIT cleanup: SMFIS_CONTINUE
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(1990): free(2f318)
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(1991): free(2eef8)
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(1995): free(2f378)
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(1996): free(2f810)
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 328151 mail.debug] 33318: 
./mimedefang.c(1997): free(2eeb8)
Jan 24 16:23:24 host01 mimedefang[9379]: [ID 173092 mail.debug] 33318: 
./mimedefang.c(2000): EXIT mfclose: SMFIS_CONTINUE

Now, even if I add a simple log statement as begin of the filter_begin 
routine, like:

my $filename = '/tmp/report.txt';
open(my $fh, '>>', $filename) or die "Could not open file '$filename' $!";
print $fh "This is a test of mimedefang\n";
close $fh;

and I send a message, the output file of these four lines is not 
written. So for some reason, it seems that mimedefang is not executing 
the mimedefang-filter script at all.

I checked file ownerships, permissions, umask etc. and compared with the 
old system and everything seems to be OK, except for the result of the 
mimdefang pass.

Any suggestions much appreciated!

/rolf

More information about the MIMEDefang mailing list