#22 dk-milter v0.2.6 (+PATCH) to errorstate then SMTP is RESETed
The function of dk-filters is discarded due to failure
of the filter then sending peer resets the SMTP-session.
Here is the output from a fairly recent logfile...
Feb 24 08:43:25 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Milter (sid-filter): init
success to negotiate
Feb 24 08:43:42 aries sendmail[8078]: [ID 801593
mail.error] j1O7hPfW008078: Milter (dk-filter): read
returned -1: Connection reset by [218.108.155.49]
Feb 24 08:43:42 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Milter (dk-filter): to error
state
Feb 24 08:43:42 aries sendmail[8078]: [ID 801593
mail.error] j1O7hPfW008078: Milter (dk-filter): init
failed to open
Feb 24 08:43:42 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Milter (dk-filter): to error
state
Feb 24 08:43:42 aries sendmail[8078]: [ID 801593
mail.info] Feb 24 08:43:42 aries sendmail[8078]: [ID
801593 mail.info] j1O7hPfW008078: Milter: connect to
filters
Feb 24 08:43:48 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Authentication-Warning:
aries.vattenfall.se: Host [218.108.155.49] claimed to
be snr-realty.com
Feb 24 08:44:04 aries milter-greylist: [ID 902575
mail.info] j1O7hPfW008078: skipping greylist because
this is the default action,
(from=<Breanna3veo@e-kolay.net>,
rcpt=<mko@forsmark.vattenfall.se>, addr=218.108.155.49)
Feb 24 08:44:09 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078:
from=<Breanna3veo@e-kolay.net>, size=2410, class=0,
nrcpts=1,
msgid=<100101c51a44$e3a93f93$429e65ca@e-kolay.net>,
proto=ESMTP, daemon=MTA-v4, relay=[218.108.155.49]
Feb 24 08:44:09 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Milter insert (1): header:
X-SenderID: Sendmail Sender-ID Filter v0.2.5
mx1.vattenfall.se j1O7hPfW008078
Feb 24 08:44:09 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Milter insert (1): header:
Authentication-Results: mx1.vattenfall.se
from=Breanna3veo@e-kolay.net; sender-id=neutral;
spf=neutral
(mx1.vattenfall.se [192.36.28.1]); Thu, 24 Feb 2005
08:44:09 +0100 (MET)
Feb 24 08:44:09 aries sendmail[8078]: [ID 801593
mail.info] j1O7hPfW008078: Milter accept: message
Feb 24 08:44:21 aries sendmail[8213]: [ID 801593
mail.info] j1O7hPfW008078:
to=<mko@forsmark.vattenfall.se>, delay=00:00:17,
xdelay=00:00:12, mailer=relay, pri=122410,
relay=orion.vattenfall.se. [151.156.10.12], dsn=2.0.0,
stat=Sent (j1O7i94P016603 Message accepted for delivery)
Logged In: YES
user_id=1048957
I'm not sure I understand what you're reporting here. It
looks to me like you're reporting a filter crash (that's
what the log shows) but the SMTP session continues normally.
If I connect to my home domain's SMTP server, which is
running dk-filter 0.2.6, and inject part of a message but
then disconnect, there's no error like this in my log file.
What are the steps I need to follow to reproduce this?
Logged In: YES
user_id=370342
Sorry for the delay, but your presumption is correct.
The dk-filter craches but the SMTP-session contiues.
I'm not sure how to reproduce this error. Apparently
dk-filter craches hard and never wake up. But no core is
produced...
I will do a little thinking about it. Maybe i should but i
F=T in the sendmail.cf for the milterplugin so i will see
which stranges mails that are rejected due to filtercrashes.
Re,
/P
Logged In: YES
user_id=370342
Another example in the log of just a common mail, that makes
dk-filter fail...I will see if i can get the mail from the user.
Re,
/P
Feb 24 21:23:32 libra sendmail[3194]: [ID 801593 mail.error]
j1OKMQte003194: Milter (dk-filter): read returned -1:
Connection reset by mail98.messagelabs.com
Feb 24 21:23:32 libra sendmail[3194]: [ID 801593 mail.info]
j1OKMQte003194: Milter (dk-filter): to error state
Feb 24 21:23:32 libra sendmail[3194]: [ID 801593 mail.error]
j1OKMQte003194: Milter (dk-filter): init failed to open
Feb 24 21:23:32 libra sendmail[3194]: [ID 801593 mail.info]
j1OKMQte003194: Milter (dk-filter): to error state
Feb 24 21:23:32 libra sendmail[3194]: [ID 801593 mail.info]
j1OKMQte003194: Milter: connect to filters
Feb 24 21:23:35 libra sendmail[3194]: [ID 801593 mail.info]
j1OKMQte003194: from=<Brostrom.Carl@bcg.com>, size=8431,
class=0, nrcpts=1,
msgid=<10DE81BD6D18144AA877EDA639BB15462793AE@stkemail01.bcg.com>,
proto=SMTP, daemon=MTA-v4, relay=mail98.messagelabs.com
[216.82.244.147]
Feb 24 21:23:35 libra sendmail[3194]: [ID 801593 mail.info]
j1OKMQte003194: Milter accept: message
Feb 24 21:23:35 libra sendmail[3223]: [ID 801593 mail.info]
j1OKMQte003194: to=<lennart.asander@vattenfall.com>,
delay=00:00:01, xdelay=00:00:00, mailer=relay, pri=128431,
relay=pegasus.vattenfall.se. [151.156.192.2], dsn=2.0.0,
stat=Sent (j1OKNZ9V010792 Message accepted for delivery)
Logged In: YES
user_id=370342
Hmmm... maybe this a side effect of using select() instead
of poll().
I will recompile sendmail and start the tests again...
Re,
/P
Logged In: YES
user_id=1048957
The error appears to be something to do with the socket
libmilter is using to listen for connections. I see this in
the log every so often:
Feb 27 03:03:21 medusa sm-mta[4633]: j1RB3Bvg004633: Milter
(dk-filter): timeout before data read
Feb 27 03:03:21 medusa sm-mta[4633]: j1RB3Bvg004633: Milter
(dk-filter): to error state
Feb 27 03:03:21 medusa sm-mta[4633]: j1RB3Bvg004633: Milter
(dk-filter): init failed to open
Feb 27 03:03:21 medusa sm-mta[4633]: j1RB3Bvg004633: Milter
(dk-filter): to error state
Feb 27 03:03:21 medusa dk-filter[8515]: Sendmail DomainKeys
Filter: accept() returned invalid socket (Bad file
descriptor), try again
So the accept() in libmilter/listener.c is failing, claiming
the listening socket is suddenly no good anymore. After
this happens a fixed number of times in a row (MAX_FAILS_A,
or 16), the filter will give up trying and terminate.
If you enable the auto-restart feature ("-A"), the filter
will restart itself when this happens, but that doesn't
really fix the problem.
Logged In: YES
user_id=370342
I had to use -A for both dk-filter and sid-filter.
Now that sid-filter don't seems to have any with stability
anymore, so i removed -A . I thought the same for dk-filter
but after some days it went down anyway. But no core-files
this time.
>So the accept() in libmilter/listener.c is failing, claiming
>the listening socket is suddenly no good anymore. After
>this happens a fixed number of times in a row (MAX_FAILS_A,
>or 16), the filter will give up trying and terminate.
Isn't this strange? Why aren't other milter-plugin (like
sid-filter) experiencing the same thing?
Are you using a socketfile or do you use a local port?
I use a local port since i had problems with socketfiles
which don't get deleted then the filter exits (perhaps due
to abnormal exits). Then when the filter restarts, it
complains about the socketfile and exits again... So -A
wasn't that good to use in that configuration.
Logged In: YES
user_id=1048957
I use a UNIX domain socket (file). This is on OpenBSD and
you're on Solaris, so it's definitely not an operating
system problem.
Are you using USE_ARLIB for both filters?
Logged In: YES
user_id=370342
Yepp, i suppose so since i haven't change any configuration
then compiling the filters. (I have a weak memory that you
needed to changes a Makefile or m4-file to get native
resolver support).
libar.a gets compiled and installed.
Logged In: YES
user_id=1048957
libdk doesn't build with USE_ARLIB by default. Please check
because if you're not using USE_ARLIB in your builds, then
we know the problem isn't in the libar code.
Logged In: YES
user_id=370342
dk-filter compiled with USE_ARLIB. Lets see if the error
symptoms disappear...
Logged In: YES
user_id=370342
Apparently, this also seems to be a bug related to native
resolver on Solaris 9. With libar, this doesn't appear...
Thanks for the help!
Re,
/P