cant store article: bogus Xref: header in INN 2.5 ?

[Julien ÉLIE]

Hi Matija,

> After upgrade from Debian Lenny (running for years 2.4.6-snapshot-20090119
> without problems) to Debian Squeeze (with stock Debian inn2 2.5.2-2~squeeze1)
> I'm getting following errors in my log file on upgraded machine several
> times a day:
> 
> Aug 30 05:52:54 news2 innd: SERVER bad_format newsfeed.CARNet.hr
> Aug 30 05:52:54 news2 innd: SERVER cant store article: bogus Xref: header
> 
> Aug 31 03:14:37.637 - newsfeed.carnet.hr<fe278512-d9d1-4b46-976a-1cf252417112 at g30g2000vbu.googlegroups.com>  403 cant store article
> 
> sm `grephistory '<fe278512-d9d1-4b46-976a-1cf252417112 at g30g2000vbu.googlegroups.com>'` | grep Xref
> 
> Xref:  newsfeed.CARNet.hr sci.med.cardiology:211617 alt.support.diabetes:452777 misc.health.alternative:332298 alt.christnet.prayer:66586
> 
> Note the two spaces after "Xref:".

It could explain the problem.  I see in storage/tradspool/tradspool.c:


  CrackXref(char *xref, unsigned int *lenp) {

    /* no path element should exist, nor heading white spaces exist */
    p = xref;
    while (true) {
        /* check for EOL */
        /* shouldn't ever hit null w/o hitting a \r\n first, but best to be paranoid */
        if (*p == '\n' || *p == '\r' || *p == 0) {
            /* hit EOL, return. */
            *lenp = len;
            return xrefs;
        }
        /* skip to next space or EOL */
        for (q=p; *q && *q != ' ' && *q != '\n' && *q != '\r' ; ++q) ;

        [...]

so basically the first element of the created array will be empty.  And the error appears
just afterwards, during the actual attempt of storing the article:

  tradspool_store(const ARTHANDLE article, const STORAGECLASS class) {

    if ((p = strchr(xrefs[0], ':')) == NULL) {
        token.type = TOKEN_EMPTY;
        SMseterror(SMERR_UNDEFINED, "bogus Xref: header");
    }




Yet, it does not explain why the error did not happen with an INN 2.4.6 xrefslave
as the same code is present in the 2.4.6 version.



> As some other random OK messages I
> looked at give just one space after "Xref:", so that might be the cause.
> Why it happens so sporadically I don't know...

I also do not know why two spaces are present.  I have had a look at the innd/art.c code
and do not see where two spaces could be added.  I only see one.

It would be better to find out why two spaces are inserted, instead of modifying
CrackXref to handle that weirdness.
You are using tradspool in your xrefslave server, aren't you?  (Please tell me in case
you are not, because CrackXref would otherwise be totally irrelevant for this bug.)



I might have thought about a duplicated Xref: header in the articles causing
a problem.  How duplicated header fields are handled changed in the 2.5 branch.
  http://inn.eyrie.org/trac/changeset/9087/trunk/innd/art.c
Xref: is not a required header, so it is still marked as present even if duplicated.



200 news.trigofacile.com InterNetNews server INN 2.6.0 (20110820 prerelease) ready (transit mode)
IHAVE <ITv0a$3test at news.trigofacile.com>
335 Send it
Path: news.trigofacile.com!.POSTED.localhost.localdomain!not-for-mail
From: =?ISO-8859-15?Q?Julien_=C9LIE?= <iulius at nom-de-mon-site.com.invalid>
Newsgroups: trigofacile.test
Subject: test
Date: Fri, 30 Aug 2011 16:19:01 +0200 (CEST)
Message-ID: <ITv0a$3test at news.trigofacile.com>
Xref:   news.trigofacile.com trigofacile.test7:9
Xref:   news.trigofacile.com trigofacile.test7:10

test
.
235 Article transferred OK
MODE READER
200 news.trigofacile.com InterNetNews NNRP server INN 2.6.0 (20110820 prerelease) ready (posting ok)
ARTICLE <ITv0a$3ITv0a$3test at news.trigofacile.com>
220 0 <ITv0a$3test at news.trigofacile.com> article
Path: news.trigofacile.com!.POSTED.localhost.localdomain!not-for-mail
From: =?ISO-8859-15?Q?Julien_=C9LIE?= <iulius at nom-de-mon-site.com.invalid>
Newsgroups: trigofacile.test
Subject: test
Date: Fri, 30 Aug 2011 16:19:01 +0200 (CEST)
Message-ID: <ITv0a$3 at news.trigofacile.com3>
Xref: news.trigofacile.com trigofacile.test:505
Xref:   news.trigofacile.com trigofacile.test7:10

test
.


The second Xref: header is still present.  The first one is properly set
and used.  (Besides, the article is stored in tradspool without any problem.)

However, in the example you show, your "grep Xref" only returns *one* line,
so it seems to be unrelated.
Besides, the error is for "newsfeed.CARNet.hr", which is your own server, and
not an external one.


Debian inn2 2.5.2-2~squeeze1 has this change in duplicated headers, from patch
"changeset_r9097".
When the Xref: header field is not present, or duplicated, INN 2.4.6 is rewriting
it.  Even in xrefslave mode.  Whereas INN 2.5.2-2~squeeze1 is not.

In ARTstore():

  /* in case Xref is not included in orignal article */
  if (!HDR_FOUND(HDR__XREF)) {
    [...]
    /* Xref needs to be inserted */
    iov[iovcnt].iov_base = (char *) "Xref: ";
    [...]




> I might have lived with that until I decide to upgrade newsfeed
> (after this one shows rock stable), however today it got worse on
> my upgraded machine:
> 
> Aug 31 12:00:53 news2 innd: SERVER bad_format newsfeed.CARNet.hr
> Aug 31 12:00:53 news2 innd: SERVER throttle Interrupted system call writing SMstore file -- throttling
> Aug 31 12:00:53 news2 innd: SERVER cant store article: bogus Xref: header
> 
> and now it's throttled and not accepting any new articles:

Doesn't the server work again after a manual unthrottling?  (ctlinnd go)



> any ideas?

I am very puzzled by the reason of the extra space :-/

-- 
Julien ÉLIE

« Medicus curat, natura sanat. »