Milter-greylist

Hello,

Is it only me the unfortunate to whom milter-greylist 4.0 alpha 4 stops with syslog message:

mg_setreply(): invoked twice

or is there anybody else having the same problem?

Bests,
Attila

<attila.bruncsak@...> wrote:

> Is it only me the unfortunate to whom milter-greylist 4.0 alpha 4 stops
> with syslog message:
> 
> mg_setreply(): invoked twice
> 
> or is there anybody else having the same problem?

I never experienced it. Does it happen often? In what situation:
multiple recipients or single recipient? Do you use DATA stage ACL?

The logs says that sanity check was introduced by Fredrik Pettai on
2006/02/17. That's rather old, I don't see why it would break now.

>       Cosmetic changes in debug logs (Fredrik Pettai)

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> > Is it only me the unfortunate to whom milter-greylist 4.0 
> alpha 4 stops
> > with syslog message:
> > 
> > mg_setreply(): invoked twice
> > 
> > or is there anybody else having the same problem?
> 
> I never experienced it. Does it happen often? In what situation:
> multiple recipients or single recipient? Do you use DATA stage ACL?

It already happened with previous 4.0 alpha versions.
With 4.0a2 it stops very fast in some minutes time.
I actually upgraded yesterday to 4.0a4 on Tru64 UNIX.
With this version it stopped only once today around noon,
after running 4 hours.

The message is not very extensive so I cannot tell that the
actual aborter thread has single or multiple recipients with single
or multiple mail in one session.
I do not use explicit data stage ACL,
but I use the delayedreject option for the <> sender.

> > > Is it only me the unfortunate to whom milter-greylist 4.0 
> > alpha 4 stops
> > > with syslog message:
> > > 
> > > mg_setreply(): invoked twice
> > > 
> > > or is there anybody else having the same problem?
> > 
> > I never experienced it. Does it happen often? In what situation:
> > multiple recipients or single recipient? Do you use DATA stage ACL?
> 
> It already happened with previous 4.0 alpha versions.
> With 4.0a2 it stops very fast in some minutes time.
> I actually upgraded yesterday to 4.0a4 on Tru64 UNIX.
> With this version it stopped only once today around noon,
> after running 4 hours.
> 
> The message is not very extensive so I cannot tell that the
> actual aborter thread has single or multiple recipients with single
> or multiple mail in one session.
> I do not use explicit data stage ACL,
> but I use the delayedreject option for the <> sender.
> 

One more information: I have the same problem both on Tru64 UNIX and on SuSe LINUX,
so I do not think that the problem is platform specific.

I have inserted in smtp_reply_free() after the line
        free(sr->sr_msg_x);
the following:
       sr->sr_msg_x = NULL;
This is just for precaution but it does not change anything.

The configuration parameters cannot be simpler, I just specify the libmilter location
and nothing else.

I tried to link both with libmilter coming with sendmail version 8.13.8 and 8.14.0,
the same failure either case.

Still only me is having this problem, or everybody is waiting for 4.0 alpha release
replaced with beta?

Bests,
Attila

On Tue, May 15, 2007 at 05:01:25PM +0200, attila.bruncsak@... wrote:
> Still only me is having this problem, or everybody is waiting for 4.0 alpha release
> replaced with beta?

I couldn't say if I have it, as my milter is restarted every 24 hours by
a crontab. A safety net that should not exist for a beta, but was actually
very useful for earlier developement versions.

I wouldn't be surprised if we had a memory leak somewhere.

-- 
Emmanuel Dreyfus
manu@...

> 
> I couldn't say if I have it, as my milter is restarted every 
> 24 hours by
> a crontab. A safety net that should not exist for a beta, but 
> was actually
> very useful for earlier developement versions.
> 
> I wouldn't be surprised if we had a memory leak somewhere.
> 

At my side the version 3.0 was running fine in production
for 5 months without restarting.
There is no sign of any significant memory leek.
If you wish I can provide the log of the command:
ps vax | grep /usr/local/bin/milter-greylist | grep -v grep >> /var/milter-greylist/runningsize.log
That is scheduled to run from crontab once an hour.
I stopped the milter-greylist v3.0 just to participate in the 4.O alpha testing.
Otherwise it would still run fine I am convinced.

Bests,
Attila

<attila.bruncsak@...> wrote:

> At my side the version 3.0 was running fine in production
> for 5 months without restarting.
> There is no sign of any significant memory leek.
> If you wish I can provide the log of the command:
> ps vax | grep /usr/local/bin/milter-greylist | grep -v grep >>
/var/milter-greylist/runningsize.log
> That is scheduled to run from crontab once an hour.
> I stopped the milter-greylist v3.0 just to participate in the 4.O alpha
> testing. Otherwise it would still run fine I am convinced.

I guess someone could incrementally try each developement snapshot to
between 3.0 and 4.0 alpha to see when things went wrong. But that's not
a funny job. :-/

The other option is to use specialized tools for tracking down memory
leaks. Any specialist here? Someone that could perform a Coverity run on
the sources?

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> I guess someone could incrementally try each developement snapshot to
> between 3.0 and 4.0 alpha to see when things went wrong. But 
> that's not
> a funny job. :-/
> 
> The other option is to use specialized tools for tracking down memory
> leaks. Any specialist here? Someone that could perform a 
> Coverity run on
> the sources?
> 

Hello,

The attached patch may give a bit more of information about the session in which
the error may occur.

Bests,
Attila

> > I guess someone could incrementally try each developement 
> snapshot to
> > between 3.0 and 4.0 alpha to see when things went wrong. But 
> > that's not
> > a funny job. :-/
> > 
> > The other option is to use specialized tools for tracking 
> down memory
> > leaks. Any specialist here? Someone that could perform a 
> > Coverity run on
> > the sources?
> > 
> 
> The attached patch may give a bit more of information about 
> the session in which
> the error may occur.
> 

So here we are:

May 30 19:14:34 mail1 sendmail[217629]: l4UHCKir217629: from=<>, size=10000, class=0, nrcpts=1, msgid=<xxx@...>, proto=ESMTP, daemon=MTA, relay=abc.def [1.2.3.4]
May 30 19:14:35 mail1 milter-greylist: l4UHCKir217629: addr abc.def[1.2.3.4] from <> to <user@...> delayed after DATA phase for 00:02:23 (ACL 1124)
May 30 19:14:35 mail1 milter-greylist: l4UHCKir217629: addr abc.def[1.2.3.4] from <> to <user@...> delayed after DATA phase for 00:02:23 (ACL 1124)
May 30 19:14:35 mail1 milter-greylist: l4UHCKir217629: mg_setreply(): invoked twice
May 30 19:14:36 mail1 sendmail[217629]: l4UHCKir217629: milter_sys_read(milter-greylist): cmd read returned 0, expecting 5
May 30 19:14:36 mail1 sendmail[217629]: l4UHCKir217629: Milter (milter-greylist): to error state
May 30 19:14:36 mail1 sendmail[217629]: l4UHCKir217629: Milter: data, reject=451 4.3.2 Please try again later
May 30 19:14:36 mail1 sendmail[217629]: l4UHCKir217629: to=<user@...>, delay=00:00:08, pri=10000, stat=Please try again later

Since I am using delayed reject option, the code part which triggers the error is this one:

        if (priv->priv_delayed_reject) {
                LIST_FOREACH(rcpt, &priv->priv_rcpt, r_list)
                        log_and_report_greylisting(ctx, priv, rcpt->r_addr);

The log_and_report_greylisting() calls mg_setreply, and there is no smtp_reply_free() in the loop.

Bests,
Attila

On Thu, May 31, 2007 at 05:36:37PM +0200, attila.bruncsak@... wrote:
> So here we are:

You rock! :-)

> May 30 19:14:35 mail1 milter-greylist: l4UHCKir217629: mg_setreply(): invoked twice
> Since I am using delayed reject option, the code part which triggers the error is this one:
> 
>         if (priv->priv_delayed_reject) {
>                 LIST_FOREACH(rcpt, &priv->priv_rcpt, r_list)
>                         log_and_report_greylisting(ctx, priv, rcpt->r_addr);
> 
> The log_and_report_greylisting() calls mg_setreply, and there is no smtp_reply_free() in the loop.

What about this fix?

Index: milter-greylist.c
===================================================================
RCS file: /cvsroot/milter-greylist/milter-greylist.c,v
retrieving revision 1.188
diff -U2 -r1.188 milter-greylist.c
--- milter-greylist.c   30 May 2007 23:32:06 -0000      1.188
+++ milter-greylist.c   31 May 2007 23:38:02 -0000
@@ -2904,8 +2904,8 @@
 
 	if (priv->priv_sr.sr_msg_x != NULL) {
-		mg_log(LOG_ERR, "%s: mg_setreply(): invoked twice",
-		     priv->priv_queueid);
-		exit(E _SOFTWARE);
+		free(priv->priv_sr.sr_msg_x);
+		priv->priv_sr.sr_msg_x = NULL;
 	}
+
 	priv->priv_sr.sr_msg_x =
 		fstring_expand(priv, rcpt, priv->priv_sr.sr_msg);


-- 
Emmanuel Dreyfus
manu@...

> What about this fix?
> 
> Index: milter-greylist.c
> ===================================================================
> RCS file: /cvsroot/milter-greylist/milter-greylist.c,v
> retrieving revision 1.188
> diff -U2 -r1.188 milter-greylist.c
> --- milter-greylist.c   30 May 2007 23:32:06 -0000      1.188
> +++ milter-greylist.c   31 May 2007 23:38:02 -0000
> @@ -2904,8 +2904,8 @@
>  
>  	if (priv->priv_sr.sr_msg_x != NULL) {
> -		mg_log(LOG_ERR, "%s: mg_setreply(): invoked twice",
> -		     priv->priv_queueid);
> -		exit(E _SOFTWARE);
> +		free(priv->priv_sr.sr_msg_x);
> +		priv->priv_sr.sr_msg_x = NULL;
>  	}
> +
>  	priv->priv_sr.sr_msg_x =
>  		fstring_expand(priv, rcpt, priv->priv_sr.sr_msg);
> 

I have applied the patch, and there is no problem for the time being.

Bests,
Attila