Re: [leafnode-list] SIGPIPE Issues

["Michael O'Quinn" <michael@xxxxxxxxxxx>]

On Wed, 20 Mar 2002, Matthias Andree wrote:

> "Michael O'Quinn" <michael@xxxxxxxxxxx> writes:
> 
> Well, fix NewsPlex. It should not offer articles it cannot fetch, and
> leafnode is logging the 500 replies when it tries to fetch things.

Oh, I agree completely.  I included the NewsPlex stuff mostly for 
completeness, not to show that something was wrong with Leafnode.

FWIW, the missing articles are not necessarily the fault of NewsPlex,
either.  NewsPlex does not cache the actual articles, only the overview
information from its upstream servers.  Many servers expire articles and
then wait a while before they update their overview database.

NewsPlex actually goes out about every 10 or 15 minutes and updates its 
overview information for any active groups.  Any more often than that and 
I'd have news admins jumping down my throat.

> > Mar 19 03:58:08 shire fetchnews[26161]: >GROUP {GROUP 8}^M
> > Mar 19 03:58:09 shire fetchnews[26161]: >GROUP {GROUP 9}^M
> 
> No new articles offered.

Yes.

> 
> > Mar 19 03:58:12 shire fetchnews[27012]: reading XOVER info from /var/spool/news/{GROUP 1}/91930
> > Mar 19 03:58:13 shire fetchnews[27012]: reading XOVER info from /var/spool/news/{GROUP 1}/91931
> 
> Looks correct.

Yep.

> 
> > First, fetchnews should have fetched a lot more articles in {GROUP 1}.

More on this below...

> >
> > Third is just a minor logging issue.  I am connecting to {SERVERNAME} port 
> > 2000, but the log reported it as port 200.
> 
> That's not the port number, but the response of the server. 200: you may
> post. 201: you cannot post.
> 
> ChangeLog extract:
> 
> 2002-03-20  Matthias Andree  <matthias.andree@xxxxxx>
> 
> 	* nntputil.c: Log port number in "connected to" syslog message,
> 	and mark the "200" with "reply:" so users know it's not the port
> 	number. Suggested by Michael O'Quinn.
> 
> Log messages now look like this:
> 
> Mar 20 12:59:39 merlin fetchnews[25834]: connected to 127.0.0.1:119, reply: 200


Ah!  Only my unfortunate choice of port 200x could make this look like a 
bug.  (Well, "200xx" could as well, I suppose.)

Thanks for the change.

> 
> > Finally, is there something I should be doing which will give you more
> > information about this?
> 
> Nope, that's sufficient to know the bug is outside leafnode, and
> leafnode has functioned seemingly correctly.

I disagree.

Looking at my post yesterday about this, When I ran fetchnews, it said to 
the console:

> > {GROUP 1}: considering articles 23631-30565

But when it ran, the log shows it quit that group at:

> > Mar 19 03:47:56 shire fetchnews[26161]: >HEAD 27556^M
> > Mar 19 03:47:56 shire fetchnews[26161]: >BODY 27556^M
> > Mar 19 03:48:02 shire fetchnews[26161]: >HEAD 27557^M
> > Mar 19 03:48:03 shire fetchnews[26161]: >BODY 27557^M
> > Mar 19 03:58:08 shire fetchnews[26161]: >GROUP {GROUP 2}^M
> > Mar 19 03:58:08 shire fetchnews[26161]: >GROUP {GROUP 3}^M

Taking 30565 and subtracting 27557, that leaves about 3008 articles that 
fetchnews didn't even ATTEMPT to download.

THESE are the missing articles I was referring to.  I think I may not have
been clear yesterday and gave the impression I was attributing the "reply
500 No server having article is reachable" errors to leafnode.  That was
not the case.

I did not do this on this particular run, but in the past when this has
happened I've telnetted in to the NewsPlex server immediately after
fetchnews crashed, and tried retrieving the articles that SHOULD have been
retrieved.  They've always been there, all the way to the end of what
fetchnews said it would try to get (article number 30565 in this case.)

I have seen this behavior MANY many times.  Before it was with a "Broken
pipe" message, now it just either quits cold (with a "Disconnecting
from..." to the console") or just skips the last block of articles and
moves on like it did this time.

> 
> Nonetheless, 1.9.20.rc8 will log many more replies to NNTP commands than
> rc7, so check back after 1.9.20.rc8 is released (really soon now).

I'm short on time until later today, but I'll let you know if anything new
pops up with rc8.  And thanks for adding the extra logging to help track
this down.

One more logging suggestion, if you haven't already done done it.  With
debuglevel = 1 could the logs show the "considering articles" line like
the console?  I am speaking of this console output:

> > {GROUP 1}: considering articles 23631-30565

This is not currently output to the logs.  If it's not already in the
change you just made (rc8) I think it would be useful.

Oh, BTW, I no longer seem to have a problem with leafnode's XOVER becoming
stale.  It now updates as it should, regardless of how fetchnews
terminates (including CTRL-C from the console).

Again, thanks for your responsiveness and help!

Michael O'Quinn





-- 
leafnode-list@xxxxxxxxxxxxxxxxxxxxxxxxxxxx -- mailing list for leafnode
To unsubscribe, send mail with "unsubscribe" in the subject to the list