Send inn-workers mailing list submissions to
[email protected]
To subscribe or unsubscribe via the World Wide Web, visit
https://lists.isc.org/mailman/listinfo/inn-workers
or, via email, send a message with subject or body 'help' to
[email protected]
You can reach the person managing the list at
[email protected]
When replying, please edit your Subject line so it is more specific
than "Re: Contents of inn-workers digest..."
Today's Topics:
1. nnrpd given the same PID as innfeed (Julien ?LIE)
2. Re: nnrpd given the same PID as innfeed (Richard Kettlewell)
3. Re: nnrpd given the same PID as innfeed (christian mock)
----------------------------------------------------------------------
Message: 1
Date: Mon, 15 Jun 2015 21:26:37 +0200
From: Julien ?LIE <[email protected]>
To: "[email protected]" <[email protected]>
Subject: nnrpd given the same PID as innfeed
Message-ID: <[email protected]>
Content-Type: text/plain; charset=utf-8
Hi all,
Has someone ever seen "exit 1" lines for innfeed in your news.notice files?
Jun 15 17:37:14 news innd: innfeed! exit 1 elapsed 48133 pid 4474
I have recently seen it a few times. The problem is that during a fork,
nnrpd is given the PID of innfeed if I trust the logs:
Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com
(67.242.187.207) connect - port 119
Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com
rejected by rule (Closed service.)
Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com times
user 0.032 system 0.016 idle 0.000 elapsed 0.036
Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com time
36 nntpwrite 0(1)
Jun 15 17:37:14 news innd: innfeed! exit 1 elapsed 48133 pid 4474
I don't know why it happens. But the fact is it happens...
That issue always appears (at least on my system) when a user tries to connect
very very often.
I blacklist such users in my readers.conf file, whence the "rejected by rule
(Closed service.)".
% grep cpe-67-242-187-207.rochester.res.rr.com news.notice | grep connect | wc
-l
14768
Now blacklisted directly in my iptables!
Maybe it is a bug in my old Debian Etch (2007) distrib...
If someone sees similar "exit 1" lines, please tell!
--
Julien ?LIE
? N'as-tu jamais fait ces r?ves, Neo, qui ont l'air plus vrais que la
r?alit? ? Si tu ?tais incapable de sortir de l'un de ces r?ves,
comment ferais-tu la diff?rence entre le monde du r?ve et le monde
r?el ? ? (Morpheus, _Matrix_)
------------------------------
Message: 2
Date: Mon, 15 Jun 2015 23:04:32 +0100
From: Richard Kettlewell <[email protected]>
To: [email protected]
Subject: Re: nnrpd given the same PID as innfeed
Message-ID: <[email protected]>
Content-Type: text/plain; charset=utf-8
Julien ?LIE <[email protected]> writes:
> Has someone ever seen "exit 1" lines for innfeed in your news.notice files?
>
> Jun 15 17:37:14 news innd: innfeed! exit 1 elapsed 48133 pid 4474
>
>
>
> I have recently seen it a few times. The problem is that during a fork,
> nnrpd is given the PID of innfeed if I trust the logs:
>
> Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com
> (67.242.187.207) connect - port 119
> Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com
> rejected by rule (Closed service.)
> Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com
> times user 0.032 system 0.016 idle 0.000 elapsed 0.036
> Jun 15 17:37:14 news nnrpd[4474]: cpe-67-242-187-207.rochester.res.rr.com
> time 36 nntpwrite 0(1)
> Jun 15 17:37:14 news innd: innfeed! exit 1 elapsed 48133 pid 4474
>
>
> I don't know why it happens. But the fact is it happens...
>
> That issue always appears (at least on my system) when a user tries to
> connect very very often.
> I blacklist such users in my readers.conf file, whence the "rejected
> by rule (Closed service.)".
I have two guesses.
1. It seems PROCscan() runs only intermittently, so there's a window of
opportunity between innfeed actually terminating and the log entry for
an nnrpd to start up. It may by chance happen to get the PID that
innfeed used to have. Perhaps that explains the weird PID behavior.
In this case, any log message from innfeed explaining its termination
might be above the nnrpd lines.
2. When a child (say, nnrpd) terminates, innd gets SIGCHLD and
immediately invokes PROCreap(). This looks for the process in
PROCtable. However, if another child process has just been started then
PROCwatch() will be part way through executing realloc() to expand
PROCtable at the point the signal arrives. So PROCreap() may see an old
and possibly corrupted version of the table. This too might explain the
weird PID behavior.
The issue described in 2 needs to be fixed. My usual approach in this
situation is to block signals except when waiting in select(). (The
signal mask must also be restored inside forks if this approach is
used.) I'll submit a patch at some point, subject of course to any
discussion here.
ttfn/rjk
------------------------------
Message: 3
Date: Tue, 16 Jun 2015 08:46:08 +0200
From: christian mock <[email protected]>
To: [email protected]
Subject: Re: nnrpd given the same PID as innfeed
Message-ID: <[email protected]>
Content-Type: text/plain; charset=us-ascii
On Mon, Jun 15, 2015 at 11:04:32PM +0100, Richard Kettlewell wrote:
I don't have much time ATM, but I have graylog, so I looked. There's 2
"exit 1" entries in the last 2+ months on my small server, and the one
I'm looking at seems to fit theory #2:
2015-06-01 09:11:22.193 news nnrpd-ldap-auth 17949
chello062178153031.8.14.vie.surfer.at exit articles 5 groups 3
2015-06-01 09:11:22.193 news nnrpd-ldap-auth 17949
DIGEST-MD5 common mech free
2015-06-01 09:11:22.193 news nnrpd-ldap-auth 17949
chello062178153031.8.14.vie.surfer.at timeout
2015-06-01 09:11:22.193 news nnrpd-ldap-auth 17949
chello062178153031.8.14.vie.surfer.at artstats get 5 time 0 size 8750
2015-06-01 09:11:22.193 news nnrpd-ldap-auth 17949
chello062178153031.8.14.vie.surfer.at times user 0.080 system 0.020 idle 0.000
elapsed 748.886
2015-06-01 09:11:22.193 news
innfeed-delayed! exit 1 elapsed 97871 pid 17949
That "elapsed 748.886" would indicate that the nnrpd process has been
running for quite some time, so #1 is probably out.
(Also, why does it log "nnrpd-ldap-auth" as the process name? -- that
is a perl_auth/perl_access thingy).
ciao,
cm.
--
** christian mock in vienna, austria -- http://www.tahina.priv.at/
** http://www.vibe.at/ ** http://quintessenz.org/ ** [email protected]
Ich kenne auch ein Klo, wo "Austria Email" draufsteht. Das ist
wahrscheinlich eine Art Rohrpost. -- Robert Bihlmeyer in at.sonstiges
------------------------------
_______________________________________________
inn-workers mailing list
[email protected]
https://lists.isc.org/mailman/listinfo/inn-workers
End of inn-workers Digest, Vol 73, Issue 4
******************************************
