headers
River Tarnell | 12 Jan 2012 00:13

Streaming NNTP bug (redux)

Hi,

Some time ago I posted about a strange behaviour from INN on my own 
server:
 <https://lists.isc.org/pipermail/inn-workers/2011-March/017392.html>

Julien wasn't able to reproduce the bug and I never saw that behaviour 
from any other server, so I never got around to investigating it 
further (or proving that it wasn't something about my system 
specifically).

However, I've now run across it again, from several of my peers.  For 
example:

Jan 11 22:58:39 INFO:     feeder: enfer-du-nord[87.98.157.95]:119: invalid response from command [.438 <jektk2$7ja$1 <at> dont-email.me>]
Jan 11 23:04:17 INFO:     feeder: tomockey[220.157.151.83]:119: invalid response from command [y438 <DkM4jRgkX7fAHPAXlidGc.0.gpbBcspOKKMq7MNTw.AHtQ <at> spot.net>]

For the second example I captured a packet trace, which can be seen 
here:
  <http://www.rt.uk.eu.org/~river/files/inn_bug.txt>

The relevant part is:

23:04:17.699596 IP s151083.ppp.asahi-net.or.jp.nntp > news-transit.rt.uk.eu.org.59499: .
36663:38065(1402) ack 49772 win 1281 <nop,nop, timestamp 4256181521 8>
[...]
        0x01a0:  6c2e 6d65 3e0d 0a34 3338 203c 6a67 6372  l.me>..438.<jgcr
        0x01b0:  6737 6433 6976 7531 376a 7469 6d65 6735  g7d3ivu17jtimeg5
        0x01c0:  6564 3130 6674 3267 3466 3962 3261 4034  ed10ft2g4f9b2a <at> 4
        0x01d0:  6178 2e63 6f6d 3e0d 0a79 3433 3820 3c44  ax.com>..y438.<D
(Continue reading)

Permalink | Reply |
headers
Julien ÉLIE | 12 Jan 2012 21:32
Favicon

Re: Streaming NNTP bug (redux)

Hi River,

> Jan 11 22:58:39 INFO:     feeder: enfer-du-nord[87.98.157.95]:119: invalid response from command [.438<jektk2$7ja$1 <at> dont-email.me>]
> Jan 11 23:04:17 INFO:     feeder: tomockey[220.157.151.83]:119: invalid response from command [y438<DkM4jRgkX7fAHPAXlidGc.0.gpbBcspOKKMq7MNTw.AHtQ <at> spot.net>]
> 
> I don't have any more details, but if I can reproduce it on my own
> INN server again I'll investigate.

Thanks for the head up.

I wonder whether this bug could not be triggered by the following code
in innd/nc.c:

#define WCHANappend(cp, p, l)   buffer_append(&(cp)->Out, (p), (l))

cp->Out->data is a buffer containing the data to write
cp->Out->used is the position of the next byte in cp->Out->data to write
cp->Out->left is the number of bytes waiting to be sent

If the write() function fails, "i" is negative and we substract "i"
to cp->Out->left anyway.
So if for instance i=-1, we end up in having cp->Out->left increased
by one.  Which would, I believe, generate the bug you see:  an extra
character is added after a complete response.  (So it appears in fact
before a new response, just before 438 in this case.)

void
NCwritereply(CHANNEL *cp, const char *text)
{
    struct buffer *bp;
(Continue reading)

Permalink | Reply |
headers
Russ Allbery | 12 Jan 2012 21:38
Picon
Favicon
Gravatar

Re: Streaming NNTP bug (redux)

Julien ÉLIE <julien <at> trigofacile.com> writes:

> I wonder whether this bug could not be triggered by the following code
> in innd/nc.c:

> #define WCHANappend(cp, p, l)   buffer_append(&(cp)->Out, (p), (l))

> cp->Out->data is a buffer containing the data to write
> cp->Out->used is the position of the next byte in cp->Out->data to write
> cp->Out->left is the number of bytes waiting to be sent

> If the write() function fails, "i" is negative and we substract "i"
> to cp->Out->left anyway.
> So if for instance i=-1, we end up in having cp->Out->left increased
> by one.  Which would, I believe, generate the bug you see:  an extra
> character is added after a complete response.  (So it appears in fact
> before a new response, just before 438 in this case.)

Good catch!  That code indeed looks very suspect.

> void
> NCwritereply(CHANNEL *cp, const char *text)
> {
>     struct buffer *bp;
>     int i;

>     bp = &cp->Out;
>     i = bp->left;
>     WCHANappend(cp, text, strlen(text));        /* Text in buffer. */
>     WCHANappend(cp, NCterm, strlen(NCterm));    /* Add CR LF to text. */
(Continue reading)

Permalink | Reply |
headers
River Tarnell | 12 Jan 2012 21:50

Re: Streaming NNTP bug (redux)

Julien ÉLIE:
> If the write() function fails, "i" is negative and we substract "i"
> to cp->Out->left anyway.
> So if for instance i=-1, we end up in having cp->Out->left increased
> by one.  Which would, I believe, generate the bug you see:  an extra
> character is added after a complete response.  (So it appears in fact
> before a new response, just before 438 in this case.)

Hi,

When I restricted the number of outstanding CHECK/TAKETHIS commands to a 
fairly low number, I didn't see this problem.  It appeared after I 
removed the limit, so in some cases there could be >1000 commands in 
flight.  I imagine that in this case, write()ing the reply could easily 
return EAGAIN when it didn't with the lower limit.

So based on that reasoning, and code inspection of NCwritereply, I think 
your diagnosis and fix is correct.  I'm still trying to reproduce the 
problem on my own server; I'll try the fix there if I can.

PS: As it happens, I had exactly the opposite bug in my own 
implementation: my writev() implementation would drop the first 
character in the buffer when it didn't write the entire buffer.

Regards,
--

-- 
        -- river.                      | Free Usenet: http://news.rt.uk.eu.org/
Non-Reciprocal Laws of Expectations:   | PGP: 2B9CE6F2
    Negative expectations yield negative results.
    Positive expectations yield negative results.
(Continue reading)

Permalink | Reply |
headers
River Tarnell | 12 Jan 2012 22:03

Re: Streaming NNTP bug (redux)

River Tarnell:
> I'm still trying to reproduce the problem on my own server; I'll try 
> the fix there if I can.

Finally I reproduced this using a list of 50,000 CHECK commands.  10,000 
was not sufficient ;-)

Here is the bug (2.5.2nb4 from pkgsrc):

% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
e438 <ecedb319-ae53-46a7-91c7-49c21a1d31df <at> p3g2000pbb.googlegroups.com>
$438 <cf2e6318-c7e4-4e4b-b581-7dba723ebc80 <at> iu7g2000pbc.googlegroups.com>
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
g438 <jelrgt$hga$5 <at> dont-email.me>
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
g438 <jelrgt$hga$5 <at> dont-email.me>
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
e438 <1651463140348034694.072087djmartin_nospam-tamu.edu <at> news.eternal-september.org>
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
>438 <9n79r6F81mU1 <at> mid.individual.net>
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
e438 <ecedb319-ae53-46a7-91c7-49c21a1d31df <at> p3g2000pbb.googlegroups.com>

It happens every time with this list.

Then I applied your patch and tested again:

% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
% ./inntest isis 433 list > out; egrep -v '^(.38|200)' out
(Continue reading)

Permalink | Reply |
headers
Julien ÉLIE | 12 Jan 2012 23:00
Favicon

Re: Streaming NNTP bug (redux)

Hi River,

> Finally I reproduced this using a list of 50,000 CHECK commands.  10,000
> was not sufficient ;-)
> It happens every time with this list.
>
> Then I applied your patch and tested again:
> So, this seems to have fixed it.

Thanks for having confirmed the issue is fixed.

The patch (probably in the form Russ suggested with only one conditional 
on i > 0) will be in INN 2.5.3.

Speaking about INN 2.5.3, I see that
   http://ftp.isc.org/isc/inn/snapshots/
is being updated again.
(Though exact mirroring with deletion on the local mirror is still missing.)

That's a great news because it means that ftp.isc.org is no longer a 
possible blocker for the release.  We're now just a few (pending) 
commits away from the release.

P.-S.:  Do you still see lots of
Dec 7 18:38:55 isis nnrpd[17593]: Invalid or inaccessible entry
for article 1682 in /aux0/overview/u/t/b/uk.telecom.broadband.IDX:
offset 622623 length 306 datalength 622133
in your logs?

--

--
(Continue reading)

Permalink | Reply |
headers
Russ Allbery | 12 Jan 2012 23:42
Picon
Favicon
Gravatar

Re: Streaming NNTP bug (redux)

Julien ÉLIE <julien <at> trigofacile.com> writes:

> Speaking about INN 2.5.3, I see that
>   http://ftp.isc.org/isc/inn/snapshots/
> is being updated again.
> (Though exact mirroring with deletion on the local mirror is still missing.)

Whoops.  I filed a ticket about that.

And yes, ftp.isc.org should be synchronizing properly.

> That's a great news because it means that ftp.isc.org is no longer a
> possible blocker for the release.  We're now just a few (pending)
> commits away from the release.

I don't have a system in place for publishing the actual release myself,
but I can file a ticket for that and maybe eventually we'll get something
set up.

--

-- 
Russ Allbery (rra <at> stanford.edu)             <http://www.eyrie.org/~eagle/>

    Please send questions to the list rather than mailing me directly.
     <http://www.eyrie.org/~eagle/faqs/questions.html> explains why.
_______________________________________________
inn-workers mailing list
inn-workers <at> lists.isc.org
https://lists.isc.org/mailman/listinfo/inn-workers
Permalink | Reply |

Gmane