server disconnect leads to "article not found"

server disconnect leads to "article not found"

[Matthias Andree]

Some strange occurrences with Oort 0.7 from CVS:

I use leafnode with a rather short timeout. When I read a longer mail,
maybe reply, leafnode (NNTP server part, internal development version)
may disconnect. This leafnode version silently disconnects, i. e. the
client just sees EOF (read) or EPIPE (write). With Oort Gnus 0.6,
everything was fine.

With the current version (maybe half a day old), one (random) article is
claimed to be "not found" (bogus message), when it's in fact still there
(I can retrieve the "missing" article by leaving and re-entering the
group and for instance reconstruct the whole thread). I've observed this
for some days now.

The whole thing is maybe related to a POST that takes place, maybe the
disconnect prior to the post messes Gnus' internal state.

What happens:

- timeout, leafnode disconnects (5 min timeout)
- Gnus is supposed to post, connects again, sends MODE READER, POST, the
  article (which is posted properly) and GROUP (to the group it was in).
- At that time, leafnode crashes when reading the updated files (xinetd
  logs SIG 11). Clearly a leafnode bug.
- In the log, I see that Gnus immediately reconnects to leafnode, issues
  MODE READER, GROUP, ARTICLE n

I believe Gnus is confused at this point, not handling the disconnect
after "GROUP" properly, the logs don't yield more information ATM. Is
there any way to track and log Gnus keypresses or actions along with a
timestamp? I've now set up leafnode to run from tcpserver with recordio,
logging into multilog, in the hope that this will reveal more
information should that be necessary.

-- 
Matthias Andree

Re: server disconnect leads to "article not found"

[Matthias Andree]

Matthias Andree <ma@dt.e-technik.uni-dortmund.de> writes:

> What happens:
>
> - timeout, leafnode disconnects (5 min timeout)
> - Gnus is supposed to post, connects again, sends MODE READER, POST, the
>   article (which is posted properly) and GROUP (to the group it was in).
> - At that time, leafnode crashes when reading the updated files (xinetd
>   logs SIG 11). Clearly a leafnode bug.
> - In the log, I see that Gnus immediately reconnects to leafnode, issues
>   MODE READER, GROUP, ARTICLE n

Either the post or the crash are crucial to the "article unavailable"
issue, but I haven't yet seen anything weird in my recordio log. I'll
keep 20 MB of NNTP conversation between Gnus and leafnode and report
what I'll find.

Unless someone else has also seen bogus "article unaccessible", don't
waste your time searching for this. I'll report back if I can reproduce
things.

-- 
Matthias Andree

Re: server disconnect leads to "article not found"

[David S Goldberg]

I've seen this with other nntp servers (verizon and newsguy).  What
happens to me is a little different, I think, but may be related to
the same issue.

1: I start reading news
2: One of the kids or my wife needs attention
3: In the interim the connection to the nntp server times out
4: I come back and try to read the next article ; it is bogusly marked
   deleted
5: I try to go to the next next article, gnus realizes the connection
   is gone, reestablishes it and properly finds that article.
6: I unmark the previously bogusly marked article and successfully
   read it.  I should note that it is necessary to read a different
   article before unmarking and reading it, presumably because there's
   a bogus article buffer associated with it, but I haven't done
   enough troubleshooting to be sure

My workaround is to recognize the likely hood of a server time out and
M-: (gnus-close-server "newsguy") RET M-: (gnus-open-server "newsguy") RET

Before trying to read anything when I get back to gnus.  I've been
seeing this for a long time now, much longer than Oort 0.7, probably
even before Oort but I'm less certain of that.  I've not been using
Gnus at home for nearly as long as at work and don't recall what was
current when I set up at home.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: server disconnect leads to "article not found"

[Matthias Andree]

David S Goldberg <david.goldberg6@verizon.net> writes:

> I've seen this with other nntp servers (verizon and newsguy).  What
> happens to me is a little different, I think, but may be related to
> the same issue.
>
> 1: I start reading news
> 2: One of the kids or my wife needs attention
> 3: In the interim the connection to the nntp server times out
> 4: I come back and try to read the next article ; it is bogusly marked
>    deleted
> 5: I try to go to the next next article, gnus realizes the connection
>    is gone, reestablishes it and properly finds that article.

Ok, I now have a full NNTP trace an can say what has happened. I'm not
attaching it in full, a commented excerpt is below.

1 - enter a group
2 - read an article
3 - write a follow, which takes me longer than the timeout of my NNTP
    server
4 - to post, gnus connects, sends MODE READER, POST, the article,
    receives 240 OK
5 - I then want to read another article of that group, Gnus sends GROUP,
    which lets the server crash (it's buggy), so Gnus gets EOF in
    response to the GROUP command -- at this time, Gnus claims
    the article was expired or deleted.
6 - Reading a second article of the same group after the crash, Gnus
    reconnects and retrieves the article properly.

So it looks as though Gnus would not recover properly from getting an
EOF in reply to a GROUP command, at least not when it had to reconnect
for a POST previously. (No, I haven't yet tracked the bug in my NNTP
server... need to get some core file first.)

-------------------------------
Here's the commented log excerpt of my NNTP session, with all CR
stripped for RFC-977/1036/2822 compliance. The trailing + are an
artifact of DJB's recordio (meaning "no LF here"), as are trailing
blanks (meaning "LF was here") and are not part of the actual chatter:

[Gnus is reading the reply to XOVER]

2002-06-13 02:11:06.681461500 11144 > 7191	Re: html editor	Martin Klaffenboeck <martin.klaffenboeck@gmx.at>	Thu, 13 Jun 2002 00:41:46 +0200	<86it4o5dcl.fsf@ns.kleinerdrache.org>	<7a31ab73.0206101326.601597ab@posting.google.com> <iloverobin.87it4qvlsg.fsf@news.socha.net> <ae+
2002-06-13 02:11:06.681483500 11144 > 5kik$47uvb$2@ID-21915.news.dfncis.de>	1574	22	Xref: merlin.emma.line.org de.comp.os.unix.bsd:7191 
2002-06-13 02:11:06.681487500 11144 > . 

[Writing a followup, 5 mins after the last command, leafnode
disconnects]

2002-06-13 02:16:06.723526500 11144 > [EOF]
2002-06-13 02:16:06.723532500 tcpserver: end 11144 status 0
2002-06-13 02:16:06.723535500 tcpserver: status: 0/40

[still writing, then, to post, Gnus reconnects:]

2002-06-13 02:19:20.434905500 tcpserver: status: 1/40
2002-06-13 02:19:20.435386500 tcpserver: pid 13802 from 192.168.0.1
2002-06-13 02:19:20.441795500 tcpserver: ok 13802 merlin.emma.line.org:192.168.0.1:119 merlin.emma.line.org:192.168.0.1:emma:35542
2002-06-13 02:19:20.499434500 13802 > 200 Leafnode NNTP daemon, version 2.0b8_ma10pre3.2 at merlin.emma.line.org  
2002-06-13 02:19:20.500543500 13802 < MODE READER 
2002-06-13 02:19:20.715260500 13802 > 200 Leafnode 2.0b8_ma10pre3.2, pleased to meet you! 
2002-06-13 02:19:20.718026500 13802 < POST 
2002-06-13 02:19:20.743655500 13802 > 340 Ok, recommended ID <8eo8ea.afd.ln@merlin.emma.line.org> 
2002-06-13 02:19:20.745469500 13802 < Newsgroups: de.comp.os.unix.bsd 
2002-06-13 02:19:20.745476500 13802 < Subject: Re: FreeBSD 4.6: Welche IDE Platten koennen TCQ 
2002-06-13 02:19:20.745479500 13802 < References: <3D04AF13.360354C5@sbox.tu-graz.ac.at> <m3zny3lziy.fsf@merlin.emma.line.org> 
2002-06-13 02:19:20.745484500 13802 <  <fjm4ea.gv.ln@Magelan.Leidinger.net> <m3n0u1bfe4.fsf@merlin.emma.line.org>+
2002-06-13 02:19:20.745488500 13802 <  
2002-06-13 02:19:20.745489500 13802 <  <8im7ea.qj.ln@mscu.best-eng.de> 
2002-06-13 02:19:20.745492500 13802 < From: Matthias Andree <matthias.andree@gmx.de> 
2002-06-13 02:19:20.745552500 13802 < Date: Thu, 13 Jun 2002 02:19:20 +0200 
2002-06-13 02:19:20.745555500 13802 < Message-ID: <m38z5k3u9j.fsf@merlin.emma.line.org> 
2002-06-13 02:19:20.745557500 13802 < Lines: 42 
2002-06-13 02:19:20.745559500 13802 < User-Agent: Gnus/5.090007 (Oort Gnus v0.07) Emacs/21.1 (i686-pc-linux-g+
2002-06-13 02:19:20.745661500 13802 < nu) 
2002-06-13 02:19:20.745663500 13802 < Cancel-Lock: sha1:Qr3IcUu/Aj6nMDy6XmrRljqLoTU= 
2002-06-13 02:19:20.745666500 13802 < MIME-Version: 1.0 
2002-06-13 02:19:20.745668500 13802 < Content-Type: text/plain; charset=iso-8859-15 
2002-06-13 02:19:20.745671500 13802 < Content-Transfer-Encoding: 8bit 
2002-06-13 02:19:20.745674500 13802 <  

[article body omitted]

2002-06-13 02:19:20.747906500 13802 < . 
2002-06-13 02:19:20.918247500 13802 > 240 Article posted, now be patient 

[article posted, another article is to be displayed]

2002-06-13 02:19:27.040830500 13802 < GROUP de.comp.os.unix.bsd 
2002-06-13 02:19:27.043279500 13802 > [EOF]
2002-06-13 02:19:27.043286500 tcpserver: end 13802 status 11
2002-06-13 02:19:27.043289500 tcpserver: status: 0/40

[the server has just crashed, Gnus has announced the article was gone]
[save this log for later analysis]
[Clicking on another article lets Gnus reconnect again]

2002-06-13 02:21:10.901983500 tcpserver: status: 1/40
2002-06-13 02:21:10.902438500 tcpserver: pid 14358 from 192.168.0.1
2002-06-13 02:21:10.908179500 tcpserver: ok 14358 merlin.emma.line.org:192.168.0.1:119 merlin.emma.line.org:192.168.0.1:emma:35544
2002-06-13 02:21:10.970009500 14358 > 200 Leafnode NNTP daemon, version 2.0b8_ma10pre3.2 at merlin.emma.line.org  
2002-06-13 02:21:10.971141500 14358 < MODE READER 
2002-06-13 02:21:11.164818500 14358 > 200 Leafnode 2.0b8_ma10pre3.2, pleased to meet you! 
2002-06-13 02:21:11.166994500 14358 < GROUP de.comp.os.unix.bsd 
2002-06-13 02:21:11.171458500 14358 > 211 2369 4611 7192 de.comp.os.unix.bsd group selected 
2002-06-13 02:21:11.172486500 14358 < ARTICLE 7188 
2002-06-13 02:21:11.189445500 14358 > 220 7188 <86elfc6uh0.fsf@ns.kleinerdrache.org> article retrieved - text follows 
2002-06-13 02:21:11.190671500 14358 > Path: news.t-online.com!newsmm01.sul.t-online.com!newsfeed01.sul.t-online.de!t-online.de!fu-berlin.de!uni-berlin.de!static62-99-146-055.adsl.inode.AT!not-for-mail 
2002-06-13 02:21:11.190681500 14358 > From: Martin Klaffenboeck <martin.klaffenboeck@gmx.at> 
2002-06-13 02:21:11.190685500 14358 > Newsgroups: de.comp.os.unix.bsd 
2002-06-13 02:21:11.190687500 14358 > Sub+
2002-06-13 02:21:11.190689500 14358 > ject: Re: FreeBSD 4.6 Release 
2002-06-13 02:21:11.190692500 14358 > Date: Wed, 12 Jun 2002 23:46:35 +0200 
2002-06-13 02:21:11.190753500 14358 > Lines: 20 
2002-06-13 02:21:11.190755500 14358 > Message-ID: <86elfc6uh0.fsf@ns.kleinerdrache.org> 
2002-06-13 02:21:11.190758500 14358 > References: <GxM2wB.H5@news.online.de> 
2002-06-13 02:21:11.190761500 14358 > NNTP-Posting-Host: static62-99-146-055.adsl.inode.at (62.99.146.55) 
2002-06-13 02:21:11.190764500 14358 > Mime-Version: 1+
2002-06-13 02:21:11.190766500 14358 > .0 
2002-06-13 02:21:11.190767500 14358 > Content-Type: text/plain; charset=iso-8859-1 
2002-06-13 02:21:11.190786500 14358 > Content-Transfer-Encoding: 8bit 
2002-06-13 02:21:11.190789500 14358 > X-Trace: fu-berlin.de 1023919061 5015991 62.99.146.55 (16 [35066]) 
2002-06-13 02:21:11.190792500 14358 > X-Orig-Path: ns.kleinerdrache.org!nobody 
2002-06-13 02:21:11.190795500 14358 > X-Url: http://create.kleinerdrache.org 
2002-06-13 02:21:11.190797500 14358 > User-Agent: Gnus/5.0900+
2002-06-13 02:21:11.190799500 14358 > 07 (Oort Gnus v0.07) XEmacs/21.5 (bok choi, 
2002-06-13 02:21:11.190818500 14358 >  i386-unknown-freebsd4.5) 
2002-06-13 02:21:11.190821500 14358 > Cancel-Lock: sha1:H3iVvfgaKvw59WP9icnRCbmF/LE= 
2002-06-13 02:21:11.190848500 14358 > Xref: merlin.emma.line.org de.comp.os.unix.bsd:7188 
2002-06-13 02:21:11.190851500 14358 >  

[body snipped]

2002-06-13 02:21:11.191030500 14358 > . 
2002-06-13 02:22:00.337190500 14358 > 6776	Re: apache PHP Permissions ?	alex@lapp.tv (Alex Lapp)	Mon, 27 May 2002 19:32:18 GMT	<3cf28938.19545+

[rest stripped, everything is fine again]

-- 
Matthias Andree

Re: server disconnect leads to "article not found"

[Matthias Andree]

Please disregard the many typos in my previous mail, it was too late, I
should have proofread it after sleep. Apologize!

-- 
Matthias Andree