Lurker

On Thu, Jun 05, 2003 at 09:08:25PM -0400, Kevin Brosius wrote:
> Since I seem to have had a database corruption today, (getting:=20
>=20
> Lurker - failed to render page:
> Database mindex seek failure (Walker::advance:Invalid argument):

I would have really liked to be able to see what was causing that...

> I figured it was time to update from this pre-0.8 cvs version to more
> recent cvs.

Interesting supposition: recent cvs (more changes) is more stable. :-)

> This still means that new incoming mail will only be seen after whatever
> the cron interval is, right?

Lurker has never done that. Once the message arrives, it's viewable.
However, your cache may not have expired.

> What's the behavior of lurker-prune with respect to removal of the
> rendered pages?

This is what it does. It removes them.

It deduces whether the content of a file actually changed before deciding to
delete them. It also deletes files which have not been accessed in a certain
amount of time and after creation for a certain amount of time.

> Also, a smaller item.  Wasn't there a link on the earlier lurker
> generated message pages for "reply"?  Any deliberate reason for removing
> it?

Yes there was.
Yes I removed it.

I am searching for a better way to do this.

--=20
Wesley W. Terpstra <wesley@...>

"Wesley W. Terpstra" wrote:
> 
> 
> On Thu, Jun 05, 2003 at 09:08:25PM -0400, Kevin Brosius wrote:
> > Since I seem to have had a database corruption today, (getting:
> >
> > Lurker - failed to render page:
> > Database mindex seek failure (Walker::advance:Invalid argument):
> 
> I would have really liked to be able to see what was causing that...
> 

I still have the mbox's and db's.  What would you like to see?  I'll
save a copy for a few days :)  It's 300M though, so I won't send it... 
Want a CD (partly kidding)?


> > I figured it was time to update from this pre-0.8 cvs version to more
> > recent cvs.
> 
> Interesting supposition: recent cvs (more changes) is more stable. :-)
> 
> > This still means that new incoming mail will only be seen after whatever
> > the cron interval is, right?
> 
> Lurker has never done that. Once the message arrives, it's viewable.
> However, your cache may not have expired.

Yes, exactly...  Unless the index .html/xml file is removed by cron rm,
or lurker-prune, the index page won't show the messages until the next
removal, right?

> 
> > What's the behavior of lurker-prune with respect to removal of the
> > rendered pages?
> 
> This is what it does. It removes them.
> 
> It deduces whether the content of a file actually changed before deciding to
> delete them. It also deletes files which have not been accessed in a certain
> amount of time and after creation for a certain amount of time.
> 
> > Also, a smaller item.  Wasn't there a link on the earlier lurker
> > generated message pages for "reply"?  Any deliberate reason for removing
> > it?
> 
> Yes there was.
> Yes I removed it.
> 
> I am searching for a better way to do this.

Sounds good.  I thought it might have been my imagination.

-- 
Kevin

On Thu, Jun 05, 2003 at 10:50:26PM -0400, Kevin Brosius wrote:
> "Wesley W. Terpstra" wrote:
> > On Thu, Jun 05, 2003 at 09:08:25PM -0400, Kevin Brosius wrote:
> > > Lurker - failed to render page:
> > > Database mindex seek failure (Walker::advance:Invalid argument):
>=20
> I still have the mbox's and db's.  What would you like to see?  I'll
> save a copy for a few days :)  It's 300M though, so I won't send it...=20
> Want a CD (partly kidding)?

If you can hold on to it I will provide you with detailed instructions on
how to track down the problem tomorrow. (I am riding on zero sleep right now
so it would be a waste of your time to follow my directions now)

Please keep the version of CVS you used which lead to the problem.

> > Lurker has never done that. Once the message arrives, it's viewable.
> > However, your cache may not have expired.
>=20
> Yes, exactly...  Unless the index .html/xml file is removed by cron rm,
> or lurker-prune, the index page won't show the messages until the next
> removal, right?

That's right.
By index page a presume you mean the mindex/ page at the end of time?

--=20
Wesley W. Terpstra <wesley@...>

"Wesley W. Terpstra" wrote:
> 
> 
> On Thu, Jun 05, 2003 at 10:50:26PM -0400, Kevin Brosius wrote:
> > "Wesley W. Terpstra" wrote:
> > > On Thu, Jun 05, 2003 at 09:08:25PM -0400, Kevin Brosius wrote:
> > > > Lurker - failed to render page:
> > > > Database mindex seek failure (Walker::advance:Invalid argument):
> >
> > I still have the mbox's and db's.  What would you like to see?  I'll
> > save a copy for a few days :)  It's 300M though, so I won't send it...
> > Want a CD (partly kidding)?
> 
> If you can hold on to it I will provide you with detailed instructions on
> how to track down the problem tomorrow. (I am riding on zero sleep right now
> so it would be a waste of your time to follow my directions now)
> 
> Please keep the version of CVS you used which lead to the problem.


Sounds good.  Looks like there may be an mbox problem here besides the
db one, although I'll look at that a little tomorrow (I need some sleep
too.)  I say this, because the re-imported mbox for a local user group
seems to stop in 8/2002 now.

http://kevb.net:3000/lurker/mindex/plug@...>

The system was heavily loaded, and had to be reset this afternoon to
recover.  I'm not sure what happened to the mbox, unless it was
lurker-index that ran away.  Filesystem is reiser, so I'd only expect
possible damage to open files.

-- 
Kevin

Kevin Brosius wrote:
> 
> 
> "Wesley W. Terpstra" wrote:
> >
> >
> > On Thu, Jun 05, 2003 at 10:50:26PM -0400, Kevin Brosius wrote:
> > > "Wesley W. Terpstra" wrote:
> > > > On Thu, Jun 05, 2003 at 09:08:25PM -0400, Kevin Brosius wrote:
> > > > > Lurker - failed to render page:
> > > > > Database mindex seek failure (Walker::advance:Invalid argument):
> > >
> > > I still have the mbox's and db's.  What would you like to see?  I'll
> > > save a copy for a few days :)  It's 300M though, so I won't send it...
> > > Want a CD (partly kidding)?
> >
> > If you can hold on to it I will provide you with detailed instructions on
> > how to track down the problem tomorrow. (I am riding on zero sleep right now
> > so it would be a waste of your time to follow my directions now)
> >
> > Please keep the version of CVS you used which lead to the problem.
> 
> Sounds good.  Looks like there may be an mbox problem here besides the
> db one, although I'll look at that a little tomorrow (I need some sleep
> too.)  I say this, because the re-imported mbox for a local user group
> seems to stop in 8/2002 now.
> 
> http://kevb.net:3000/lurker/mindex/plug@...>
> 
> The system was heavily loaded, and had to be reset this afternoon to
> recover.  I'm not sure what happened to the mbox, unless it was
> lurker-index that ran away.  Filesystem is reiser, so I'd only expect
> possible damage to open files.


Looks like this was a duplicate messages problem.  Postfix was seeing
errors on the delivering system, which caused it to defer extra copies
of some messages.  I'm re-importing with '-d' and that list seems fine
now.

-- 
Kevin

On Thu, Jun 05, 2003 at 11:30:53PM -0400, Kevin Brosius wrote:
> Sounds good.  Looks like there may be an mbox problem here besides the
> db one, although I'll look at that a little tomorrow (I need some sleep
> too.)  I say this, because the re-imported mbox for a local user group
> seems to stop in 8/2002 now.
> 
> http://kevb.net:3000/lurker/mindex/plug@...>

It seems all your messages are at 1970-01-01...

Uhm, wtf is with these timestamps on your mailbox (first line)?
-> http://kevb.net:3000/lurker/mbox/19700101.000001.0cd7a8e2.txt
They're formatted wrong. Fawwwk.

I suppose I am going to need to find a better date parser.

> The system was heavily loaded, and had to be reset this afternoon to
> recover.

I suppose that's one way to deal with load. :-)

--
Wes

"Wesley W. Terpstra" wrote:
> 
> 
> On Thu, Jun 05, 2003 at 11:30:53PM -0400, Kevin Brosius wrote:
> > Sounds good.  Looks like there may be an mbox problem here besides the
> > db one, although I'll look at that a little tomorrow (I need some sleep
> > too.)  I say this, because the re-imported mbox for a local user group
> > seems to stop in 8/2002 now.
> >
> > http://kevb.net:3000/lurker/mindex/plug@...>
> 
> It seems all your messages are at 1970-01-01...
> 
> Uhm, wtf is with these timestamps on your mailbox (first line)?
> -> http://kevb.net:3000/lurker/mbox/19700101.000001.0cd7a8e2.txt
> They're formatted wrong. Fawwwk.
> 
> I suppose I am going to need to find a better date parser.
> 

Hmm, good question.  That's probably either a Solaris or Netscape
problem...  Some of the history of that list comes from local mailboxes
I had in Netscape format.  So blame that on my import technique if it's
broken.

> > The system was heavily loaded, and had to be reset this afternoon to
> > recover.
> 
> I suppose that's one way to deal with load. :-)
> 

Well, that's the short version.  Really, something was running away. 
When I switched from X to console and back, X never redrew the screen
and the box was locked.  Plus no remote access anymore.

-- 
Kevin

On Fri, Jun 06, 2003 at 07:43:31AM -0400, Kevin Brosius wrote:
> "Wesley W. Terpstra" wrote:
> > Uhm, wtf is with these timestamps on your mailbox (first line)?
> > -> http://kevb.net:3000/lurker/mbox/19700101.000001.0cd7a8e2.txt
> > They're formatted wrong. Fawwwk.
> > 
> > I suppose I am going to need to find a better date parser.
> > 
> 
> Hmm, good question.  That's probably either a Solaris or Netscape
> problem...  Some of the history of that list comes from local mailboxes
> I had in Netscape format.  So blame that on my import technique if it's
> broken.

CVS now has a date parser stolen from GNU date (which is mind-blowing in
what it accepts). Your broken mailbox should now work. :>

date's like "now", "yesterday", and other insane things work too. =)

---
Wes

"Wesley W. Terpstra" wrote:
> 
> 
> On Fri, Jun 06, 2003 at 07:43:31AM -0400, Kevin Brosius wrote:
> > "Wesley W. Terpstra" wrote:
> > > Uhm, wtf is with these timestamps on your mailbox (first line)?
> > > -> http://kevb.net:3000/lurker/mbox/19700101.000001.0cd7a8e2.txt
> > > They're formatted wrong. Fawwwk.
> > >
> > > I suppose I am going to need to find a better date parser.
> > >
> >
> > Hmm, good question.  That's probably either a Solaris or Netscape
> > problem...  Some of the history of that list comes from local mailboxes
> > I had in Netscape format.  So blame that on my import technique if it's
> > broken.
> 
> CVS now has a date parser stolen from GNU date (which is mind-blowing in
> what it accepts). Your broken mailbox should now work. :>
> 
> date's like "now", "yesterday", and other insane things work too. =)

Better :)  That message is all gone.

I'm fighting a corrupted xfree86 mbox in the lurker db dir now, it
appears.  That's the one that seemed to cause me problems on re-import. 
Did the rules for message dates change, besides the parsing?  I see
http://kevb.net:3000/lurker/mindex/xfree86@...>
and
http://kevb.net:3000/lurker/message/20110518.124633.b6db0087.html

with really far out years now.

-- 
Kevin

On Fri, Jun 06, 2003 at 10:51:06AM -0400, Kevin Brosius wrote:
> I'm fighting a corrupted xfree86 mbox in the lurker db dir now, it
> appears.  That's the one that seemed to cause me problems on re-import. 
> Did the rules for message dates change, besides the parsing? 

Seems I broke it. *cough*
All better. Sorry about that.
I didn't test the right thing.

> I see
> http://kevb.net:3000/lurker/message/20110518.124633.b6db0087.html
> with really far out years now.

This message now works for me. cvs update.

Anyways, if you have any more date problems let me know! This is important
to have just right.

---
Wes

"Wesley W. Terpstra" wrote:
> 
> 
> On Fri, Jun 06, 2003 at 10:51:06AM -0400, Kevin Brosius wrote:
> > I'm fighting a corrupted xfree86 mbox in the lurker db dir now, it
> > appears.  That's the one that seemed to cause me problems on re-import.
> > Did the rules for message dates change, besides the parsing?
> 
> Seems I broke it. *cough*
> All better. Sorry about that.
> I didn't test the right thing.
> 

No problem, that's what people using cvs help with :)

> > I see
> > http://kevb.net:3000/lurker/message/20110518.124633.b6db0087.html
> > with really far out years now.
> 
> This message now works for me. cvs update.
> 
> Anyways, if you have any more date problems let me know! This is important
> to have just right.

Excellent, thanks!

It seems I'm loosing parts of the database sometimes.  I was all up and
running again, and I was trying to reproduce the problem.  It appears to
be a lurker-index problem (or a lurker-prune interaction.)  I had
delivery working, and pages were being served fine.  I verified delivery
was clean, then enabled lurker prune.  I ran it a couple times manually
also, to prove that it didn't delete any parts of the database. 
Everything looked clean, and I had already received some of the deferred
messages from my external postfix queue.  I then tried to flush the
queue and pick up all the deferred mail.  After some number of messages
(6 actually), postfix started reporting:  

Command died with status 1: "/usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l plug -m". Command output: opening database: No
such file or directory 

The db directory looks like:

total 290118
drwxr-xr-x    2 wwwrun   root          368 2003-06-06 11:47 .
drwxr-xr-x   10 root     root          304 2003-06-06 11:19 ..
-rw-r--r--    1 wwwrun   users          33 2003-06-06 11:47 db
-rw-------    1 wwwrun   nogroup      8192 2003-06-06 11:47 db.iee
-rw-r--r--    1 wwwrun   users     1114112 2003-06-06 10:36 db.ioq
-rw-r--r--    1 wwwrun   users    76259328 2003-06-06 10:35 db.ipk
-rw-r--r--    1 wwwrun   users     4120576 2003-06-06 10:36 db.iss
-rw-r--r--    1 wwwrun   users           0 2003-06-06 09:50 db.writer
-rw-r--r--    1 wwwrun   users     7645836 2003-06-06 11:47
linux-usb-devel
-rw-r--r--    1 wwwrun   users    45211535 2003-06-06 11:47 lkml
-rw-r--r--    1 wwwrun   users      551199 2003-06-06 11:38 lurker-users
-rw-r--r--    1 wwwrun   users    76637082 2003-06-06 11:47 plug
-rw-r--r--    1 wwwrun   users    73504916 2003-06-06 11:47 xfree86
-rw-r--r--    1 wwwrun   users    11724762 2003-06-06 09:54
xfree86-devel

A backup of the directory was: (I did a cp -r, so no user info is
saved.)

total 289966
-rw-r--r--    1 root     root           29 2003-06-06 11:19 db
-rw-r--r--    1 root     root       180224 2003-06-06 11:19 db.ieg
-rw-r--r--    1 root     root      1114112 2003-06-06 11:19 db.ioq
-rw-r--r--    1 root     root     76259328 2003-06-06 11:19 db.ipk
-rw-r--r--    1 root     root      4120576 2003-06-06 11:19 db.iss
-rw-r--r--    1 root     root            0 2003-06-06 11:19 db.writer
-rw-r--r--    1 root     root      7562894 2003-06-06 11:19
linux-usb-devel
-rw-r--r--    1 root     root     45135014 2003-06-06 11:19 lkml
-rw-r--r--    1 root     root       542427 2003-06-06 11:19 lurker-users
-rw-r--r--    1 root     root     76534237 2003-06-06 11:19 plug
-rw-r--r--    1 root     root     73444116 2003-06-06 11:20 xfree86
-rw-r--r--    1 root     root     11724762 2003-06-06 11:19
xfree86-devel

Where did db.ieg go? :)

-- 
Kevin

On Fri, Jun 06, 2003 at 12:06:03PM -0400, Kevin Brosius wrote:
> It seems I'm loosing parts of the database sometimes.  I was all up and
> running again, and I was trying to reproduce the problem.  It appears to
> be a lurker-index problem (or a lurker-prune interaction.)  I had
> delivery working, and pages were being served fine.  I verified delivery
> was clean, then enabled lurker prune.  I ran it a couple times manually
> also, to prove that it didn't delete any parts of the database. 

Since lurker-prune only opens read-only it shouldn't delete anything.
It might be a locking interaction though.

> Everything looked clean, and I had already received some of the deferred
> messages from my external postfix queue.  I then tried to flush the
> queue and pick up all the deferred mail.  After some number of messages
> (6 actually), postfix started reporting:  
> 
> Command died with status 1: "/usr/local/bin/lurker-index -c
> /srv/www/lurker.conf -l plug -m". Command output: opening database: No
> such file or directory 

Great!!! This is the problem Federico ran into. I would love to fix it.

> The db directory looks like:
> 
> total 290118
> drwxr-xr-x    2 wwwrun   root          368 2003-06-06 11:47 .
> drwxr-xr-x   10 root     root          304 2003-06-06 11:19 ..
> -rw-r--r--    1 wwwrun   users          33 2003-06-06 11:47 db
> -rw-------    1 wwwrun   nogroup      8192 2003-06-06 11:47 db.iee
> -rw-r--r--    1 wwwrun   users     1114112 2003-06-06 10:36 db.ioq
> -rw-r--r--    1 wwwrun   users    76259328 2003-06-06 10:35 db.ipk
> -rw-r--r--    1 wwwrun   users     4120576 2003-06-06 10:36 db.iss
> -rw-r--r--    1 wwwrun   users           0 2003-06-06 09:50 db.writer
> -rw-r--r--    1 wwwrun   users     7645836 2003-06-06 11:47
> linux-usb-devel
> -rw-r--r--    1 wwwrun   users    45211535 2003-06-06 11:47 lkml
> -rw-r--r--    1 wwwrun   users      551199 2003-06-06 11:38 lurker-users
> -rw-r--r--    1 wwwrun   users    76637082 2003-06-06 11:47 plug
> -rw-r--r--    1 wwwrun   users    73504916 2003-06-06 11:47 xfree86
> -rw-r--r--    1 wwwrun   users    11724762 2003-06-06 09:54
> xfree86-devel
> 
> A backup of the directory was: (I did a cp -r, so no user info is
> saved.)
> 
> total 289966
> -rw-r--r--    1 root     root           29 2003-06-06 11:19 db
> -rw-r--r--    1 root     root       180224 2003-06-06 11:19 db.ieg
> -rw-r--r--    1 root     root      1114112 2003-06-06 11:19 db.ioq
> -rw-r--r--    1 root     root     76259328 2003-06-06 11:19 db.ipk
> -rw-r--r--    1 root     root      4120576 2003-06-06 11:19 db.iss
> -rw-r--r--    1 root     root            0 2003-06-06 11:19 db.writer
> -rw-r--r--    1 root     root      7562894 2003-06-06 11:19
> linux-usb-devel
> -rw-r--r--    1 root     root     45135014 2003-06-06 11:19 lkml
> -rw-r--r--    1 root     root       542427 2003-06-06 11:19 lurker-users
> -rw-r--r--    1 root     root     76534237 2003-06-06 11:19 plug
> -rw-r--r--    1 root     root     73444116 2003-06-06 11:20 xfree86
> -rw-r--r--    1 root     root     11724762 2003-06-06 11:19
> xfree86-devel
> 
> Where did db.ieg go? :)

Ok.. So, ipk is the same size, so it's fine. iss is also the same size.
ioq is the same. ieg is gone and .iee is new.

Since you only imported six messages there is no way you got 180k worth of
keyword data (the only way ieg would be affected)... (they were normal sized
messages right?) ... hence only new smaller files should have been generated.

Can you verify that 'cat db' of the new database lists iee, ieg, ioq, iss,
ipk in that order? Is the backup database consistent? (ie: no lurker-index
was run during backup?) 

If you are brave, uncomment 
# Main dump : dump.cpp ;
# LinkLibraries dump : libesort ;
in libesort/Jamfile, and build it by running 'jam' in that dir.

Then copy db.iee and db to a new dir, and strip all the other db.* files from
db. Run dump on this database and confirm that all the keyword data there
comes only from the new 6 messages (and that all six messages are in it).
(PS: pipe dump though less or the high ascii will bite you)
(lines beginning with 's' are summary data and include subject lines
 which would help determine what's in there)

Heh, I just noticed a bug using dump; I don't decode quoted-printable before
indexing it for keywords. Sheeet.

I really wonder what could cause this since it doesn't happen during
straight import. It most be some form of locking issue... There was no error
on the last non "does not exist" index run? Maybe log the results of
lurker-prune -v ?

Man I really hope you can make this reproducible as it is a bug that has
been troubling me. Is this the same symptom as you experienced with the
older version of cvs?

/me rubs hands together in anticipation of bug squashing.

---
Wes

"Wesley W. Terpstra" wrote:
> 
> 
> On Fri, Jun 06, 2003 at 12:06:03PM -0400, Kevin Brosius wrote:
> > It seems I'm loosing parts of the database sometimes.  I was all up and
> > running again, and I was trying to reproduce the problem.  It appears to
> > be a lurker-index problem (or a lurker-prune interaction.)  I had
> > delivery working, and pages were being served fine.  I verified delivery
> > was clean, then enabled lurker prune.  I ran it a couple times manually
> > also, to prove that it didn't delete any parts of the database.
> 
> Since lurker-prune only opens read-only it shouldn't delete anything.
> It might be a locking interaction though.
> 
> > Everything looked clean, and I had already received some of the deferred
> > messages from my external postfix queue.  I then tried to flush the
> > queue and pick up all the deferred mail.  After some number of messages
> > (6 actually), postfix started reporting:
> >
> > Command died with status 1: "/usr/local/bin/lurker-index -c
> > /srv/www/lurker.conf -l plug -m". Command output: opening database: No
> > such file or directory
> 
> Great!!! This is the problem Federico ran into. I would love to fix it.
> 
> > The db directory looks like:
> >
> > total 290118
> > drwxr-xr-x    2 wwwrun   root          368 2003-06-06 11:47 .
> > drwxr-xr-x   10 root     root          304 2003-06-06 11:19 ..
> > -rw-r--r--    1 wwwrun   users          33 2003-06-06 11:47 db
> > -rw-------    1 wwwrun   nogroup      8192 2003-06-06 11:47 db.iee
> > -rw-r--r--    1 wwwrun   users     1114112 2003-06-06 10:36 db.ioq
> > -rw-r--r--    1 wwwrun   users    76259328 2003-06-06 10:35 db.ipk
> > -rw-r--r--    1 wwwrun   users     4120576 2003-06-06 10:36 db.iss
> > -rw-r--r--    1 wwwrun   users           0 2003-06-06 09:50 db.writer
> > -rw-r--r--    1 wwwrun   users     7645836 2003-06-06 11:47
> > linux-usb-devel
> > -rw-r--r--    1 wwwrun   users    45211535 2003-06-06 11:47 lkml
> > -rw-r--r--    1 wwwrun   users      551199 2003-06-06 11:38 lurker-users
> > -rw-r--r--    1 wwwrun   users    76637082 2003-06-06 11:47 plug
> > -rw-r--r--    1 wwwrun   users    73504916 2003-06-06 11:47 xfree86
> > -rw-r--r--    1 wwwrun   users    11724762 2003-06-06 09:54
> > xfree86-devel
> >
> > A backup of the directory was: (I did a cp -r, so no user info is
> > saved.)
> >
> > total 289966
> > -rw-r--r--    1 root     root           29 2003-06-06 11:19 db
> > -rw-r--r--    1 root     root       180224 2003-06-06 11:19 db.ieg
> > -rw-r--r--    1 root     root      1114112 2003-06-06 11:19 db.ioq
> > -rw-r--r--    1 root     root     76259328 2003-06-06 11:19 db.ipk
> > -rw-r--r--    1 root     root      4120576 2003-06-06 11:19 db.iss
> > -rw-r--r--    1 root     root            0 2003-06-06 11:19 db.writer
> > -rw-r--r--    1 root     root      7562894 2003-06-06 11:19
> > linux-usb-devel
> > -rw-r--r--    1 root     root     45135014 2003-06-06 11:19 lkml
> > -rw-r--r--    1 root     root       542427 2003-06-06 11:19 lurker-users
> > -rw-r--r--    1 root     root     76534237 2003-06-06 11:19 plug
> > -rw-r--r--    1 root     root     73444116 2003-06-06 11:20 xfree86
> > -rw-r--r--    1 root     root     11724762 2003-06-06 11:19
> > xfree86-devel
> >
> > Where did db.ieg go? :)
> 
> Ok.. So, ipk is the same size, so it's fine. iss is also the same size.
> ioq is the same. ieg is gone and .iee is new.
> 
> Since you only imported six messages there is no way you got 180k worth of
> keyword data (the only way ieg would be affected)... (they were normal sized
> messages right?) ... hence only new smaller files should have been generated.
> 

Ok, that may have been a little misleading.  There were more than size
messages since the backup copy, but only six from the time I did a
postfix flush to finish off the update.  I think there were about 39
messages in the postfix queue.  I can go back and look at the delivery
logs to tell how many successful deliveries prior to my start of the
flush.

> Can you verify that 'cat db' of the new database lists iee, ieg, ioq, iss,
> ipk in that order? Is the backup database consistent? (ie: no lurker-index
> was run during backup?)
> 

Hmm, bad dir:

 cat db
255 8192 255
iee
iiz
ioq
ipk
iss

backup dir:

 cat db_ok_withxfree86/db
255 8192 255
ieg
ioq
ipk
iss


> If you are brave, uncomment
> # Main dump : dump.cpp ;
> # LinkLibraries dump : libesort ;
> in libesort/Jamfile, and build it by running 'jam' in that dir.
> 
> Then copy db.iee and db to a new dir, and strip all the other db.* files from
> db. Run dump on this database and confirm that all the keyword data there
> comes only from the new 6 messages (and that all six messages are in it).
> (PS: pipe dump though less or the high ascii will bite you)
> (lines beginning with 's' are summary data and include subject lines
>  which would help determine what's in there)

I'll take a look, and run through the mail log to get an idea of how
many messages were added prior to the last 6 good ones.

> 
> Heh, I just noticed a bug using dump; I don't decode quoted-printable before
> indexing it for keywords. Sheeet.
> 
> I really wonder what could cause this since it doesn't happen during
> straight import. It most be some form of locking issue... There was no error
> on the last non "does not exist" index run? Maybe log the results of
> lurker-prune -v ?

Doesn't appear to be any other error.  postfix has several:

 postfix/local[1634]: B5E42115622: to=<xfree86@...]>,
relay=local, delay=0, status=sent ("|/usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l xfree86 -m")
 postfix/local[1640]: B323C1155D9: to=<lkml@...]>, relay=local,
delay=0, status=sent ("|/usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m")
 postfix/local[1644]: C66D3115235: to=<plug@...]>, relay=local,
delay=0, status=sent ("|/usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l plug -m")

(several connects from the postfix system I'm flushing occur here, with
the next batch of messages.)

 postfix/local[1634]: E2E91112CBA: to=<plug@...]>, relay=local,
delay=0, status=deferred (SOFT BOUNCE - Command died with status 1:
"/usr/local/bin/lurker-index -c /srv/www/lurker.conf -l plug -m".
Command output: opening database: No such file or directory )


That's a very abbreviated snippet.  Three successful lurker-indexes,
postfix queues 4 or some more messages, then starts to attempt local
delivery.  That one to 'plug' fails, followed by ones to:
linux-usb-devel
lurker-users
lkml
lkml

Then we queue some more from the remote system.  IIRC, the postfix
connection limit is set at 4, so this fits.  Queue 4, deliver 4.

> 
> Man I really hope you can make this reproducible as it is a bug that has
> been troubling me. Is this the same symptom as you experienced with the
> older version of cvs?
> 

Possibly.  I think it was aggravated by using a 2.5.69 kernel which
appears to also have some kind of a lockup bug related to heavy load.  I
think that's what took the system down.  That kernel problem prevented
me from being able to see the database problem right away.

> /me rubs hands together in anticipation of bug squashing.

Okay, I've got a couple ideas :)  I'm wondering if I can reproduce it by
running a half dozen instances of lurker-index with single message input
(ignoring postfix) all concurrently.  I need a way that doesn't depend
on queued mail, as there's only so much of that. :)

-- 
Kevin

"Wesley W. Terpstra" wrote:
> 
> 
> On Fri, Jun 06, 2003 at 12:06:03PM -0400, Kevin Brosius wrote:
> > It seems I'm loosing parts of the database sometimes.  I was all up and
> > running again, and I was trying to reproduce the problem.  It appears to
> > be a lurker-index problem (or a lurker-prune interaction.)  I had
> > delivery working, and pages were being served fine.  I verified delivery
> > was clean, then enabled lurker prune.  I ran it a couple times manually
> > also, to prove that it didn't delete any parts of the database.
> 
> Since lurker-prune only opens read-only it shouldn't delete anything.
> It might be a locking interaction though.
> 
> > Everything looked clean, and I had already received some of the deferred
> > messages from my external postfix queue.  I then tried to flush the
> > queue and pick up all the deferred mail.  After some number of messages
> > (6 actually), postfix started reporting:
> >
> > Command died with status 1: "/usr/local/bin/lurker-index -c
> > /srv/www/lurker.conf -l plug -m". Command output: opening database: No
> > such file or directory
> 
> Great!!! This is the problem Federico ran into. I would love to fix it.
> 
> > The db directory looks like:
> >
> > total 290118
> > drwxr-xr-x    2 wwwrun   root          368 2003-06-06 11:47 .
> > drwxr-xr-x   10 root     root          304 2003-06-06 11:19 ..
> > -rw-r--r--    1 wwwrun   users          33 2003-06-06 11:47 db
> > -rw-------    1 wwwrun   nogroup      8192 2003-06-06 11:47 db.iee
> > -rw-r--r--    1 wwwrun   users     1114112 2003-06-06 10:36 db.ioq
> > -rw-r--r--    1 wwwrun   users    76259328 2003-06-06 10:35 db.ipk
> > -rw-r--r--    1 wwwrun   users     4120576 2003-06-06 10:36 db.iss
> > -rw-r--r--    1 wwwrun   users           0 2003-06-06 09:50 db.writer
> > -rw-r--r--    1 wwwrun   users     7645836 2003-06-06 11:47
> > linux-usb-devel
> > -rw-r--r--    1 wwwrun   users    45211535 2003-06-06 11:47 lkml
> > -rw-r--r--    1 wwwrun   users      551199 2003-06-06 11:38 lurker-users
> > -rw-r--r--    1 wwwrun   users    76637082 2003-06-06 11:47 plug
> > -rw-r--r--    1 wwwrun   users    73504916 2003-06-06 11:47 xfree86
> > -rw-r--r--    1 wwwrun   users    11724762 2003-06-06 09:54
> > xfree86-devel
> >
> > A backup of the directory was: (I did a cp -r, so no user info is
> > saved.)
> >
> > total 289966
> > -rw-r--r--    1 root     root           29 2003-06-06 11:19 db
> > -rw-r--r--    1 root     root       180224 2003-06-06 11:19 db.ieg
> > -rw-r--r--    1 root     root      1114112 2003-06-06 11:19 db.ioq
> > -rw-r--r--    1 root     root     76259328 2003-06-06 11:19 db.ipk
> > -rw-r--r--    1 root     root      4120576 2003-06-06 11:19 db.iss
> > -rw-r--r--    1 root     root            0 2003-06-06 11:19 db.writer
> > -rw-r--r--    1 root     root      7562894 2003-06-06 11:19
> > linux-usb-devel
> > -rw-r--r--    1 root     root     45135014 2003-06-06 11:19 lkml
> > -rw-r--r--    1 root     root       542427 2003-06-06 11:19 lurker-users
> > -rw-r--r--    1 root     root     76534237 2003-06-06 11:19 plug
> > -rw-r--r--    1 root     root     73444116 2003-06-06 11:20 xfree86
> > -rw-r--r--    1 root     root     11724762 2003-06-06 11:19
> > xfree86-devel
> >
> > Where did db.ieg go? :)
> 
> Ok.. So, ipk is the same size, so it's fine. iss is also the same size.
> ioq is the same. ieg is gone and .iee is new.
> 
> Since you only imported six messages there is no way you got 180k worth of
> keyword data (the only way ieg would be affected)... (they were normal sized
> messages right?) ... hence only new smaller files should have been generated.
> 
> Can you verify that 'cat db' of the new database lists iee, ieg, ioq, iss,
> ipk in that order? Is the backup database consistent? (ie: no lurker-index
> was run during backup?)
> 
> If you are brave, uncomment
> # Main dump : dump.cpp ;
> # LinkLibraries dump : libesort ;
> in libesort/Jamfile, and build it by running 'jam' in that dir.
> 
> Then copy db.iee and db to a new dir, and strip all the other db.* files from
> db. Run dump on this database and confirm that all the keyword data there
> comes only from the new 6 messages (and that all six messages are in it).
> (PS: pipe dump though less or the high ascii will bite you)
> (lines beginning with 's' are summary data and include subject lines
>  which would help determine what's in there)
> 
> Heh, I just noticed a bug using dump; I don't decode quoted-printable before
> indexing it for keywords. Sheeet.
> 
> I really wonder what could cause this since it doesn't happen during
> straight import. It most be some form of locking issue... There was no error
> on the last non "does not exist" index run? Maybe log the results of
> lurker-prune -v ?
> 
> Man I really hope you can make this reproducible as it is a bug that has
> been troubling me. Is this the same symptom as you experienced with the
> older version of cvs?
> 
> /me rubs hands together in anticipation of bug squashing.
> 

Ask, and you shall receive...

I grabbed 5 random messages out of linux-kernel and put them in text
files (msg1-5), then I made a script that does:

cat msg1 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
-m&
cat msg2 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
-m&
cat msg3 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
-m&
cat msg4 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
-m&
cat msg5 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
-m&

Running this about a half dozen times, starting with an empty db
directory, caused bad things to happen.  The first thing that happened
was orphaned db's.  For example:

total 524
-rw-r--r--    1 wwwrun   users          17 2003-06-06 19:48 db
-rw-r--r--    1 wwwrun   users       32768 2003-06-06 19:48 db.ied
-rw-r--r--    1 wwwrun   users       32768 2003-06-06 19:48 db.iel
-rw-r--r--    1 wwwrun   users           0 2003-06-06 19:44 db.writer
-rw-r--r--    1 wwwrun   users      464988 2003-06-06 19:48 lkml
:/srv/lurker/db> cat db
255 8192 255
iel
:/srv/lurker/db>

We seem to have lost db.ied at this point.  I suppose that could be a
leak of disk space, and it doesn't break anything yet.

However, a few more runs and I see actual errors.

~/lurk_temp> source ind
[1]   Done                    cat msg1 | /usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m
[2]   Done                    cat msg2 | /usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m
[3]   Done                    cat msg3 | /usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m
[4]-  Done                    cat msg4 | /usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m
[5]+  Done                    cat msg5 | /usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m
opening database: No such file or directory
opening database: No such file or directory
[2]-  Exit 1                  cat msg2 | /usr/local/bin/lurker-index -c
/srv/www/lurker.conf -l lkml -m
~/lurk_temp> opening database: No such file or directory
opening database: No such file or directory
opening database: No such file or directory


Now, the db directory looks like:

/srv/lurker/db # cat db
255 8192 255
iku
ipn
/srv/lurker/db # ls -l
total 841
drwxr-xr-x    2 wwwrun   root          224 2003-06-06 19:54 .
drwxr-xr-x   12 root     root          376 2003-06-06 18:57 ..
-rw-r--r--    1 wwwrun   users          21 2003-06-06 19:54 db
-rw-r--r--    1 wwwrun   users       32768 2003-06-06 19:54 db.icj
-rw-r--r--    1 wwwrun   users       32768 2003-06-06 19:48 db.ied
-rw-r--r--    1 wwwrun   users        8192 2003-06-06 19:54 db.ipn
-rw-r--r--    1 wwwrun   users       32768 2003-06-06 19:54 db.iry
-rw-r--r--    1 wwwrun   users           0 2003-06-06 19:44 db.writer
-rw-r--r--    1 wwwrun   users      746358 2003-06-06 19:54 lkml


We seem to have lost db.iku on disk, while leaking several others.  I
don't think there's anything special about the messages I used, I tried
to get a couple larger ones to increase the time.  Here're the sizes:

-rw-r--r--    1 cobra    users        3287 2003-06-06 19:32 msg1
-rw-r--r--    1 cobra    users        3040 2003-06-06 19:32 msg2
-rw-r--r--    1 cobra    users        5348 2003-06-06 19:33 msg3
-rw-r--r--    1 cobra    users       16917 2003-06-06 19:38 msg4
-rw-r--r--    1 cobra    users       18303 2003-06-06 19:42 msg5

I've tar'd the directory up and placed it at
http://kevb.net/files/lurker_debug.tgz in case you need it.  What else
would you like to see?  Did I do anything wrong in this test case?

-- 
Kevin

On Fri, Jun 06, 2003 at 08:11:40PM -0400, Kevin Brosius wrote:
> I grabbed 5 random messages out of linux-kernel and put them in text
> files (msg1-5), then I made a script that does:
>=20
> cat msg1 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
> -m&
> cat msg2 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
> -m&
> cat msg3 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
> -m&
> cat msg4 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
> -m&
> cat msg5 | /usr/local/bin/lurker-index -c /srv/www/lurker.conf -l lkml
> -m&

Good plan. I will try this myself tomorrow morning.
Reproducible =3D really great!!! =3D)

> I've tar'd the directory up and placed it at
> http://kevb.net/files/lurker_debug.tgz in case you need it.  What else
> would you like to see?  Did I do anything wrong in this test case?

Copied that file.=20
(although I agree the particular messsage is probably irrelevant)
The test case seems perfectly fine to me; it *should* have worked.

I would be interested to know if this is filesystem dependent.

It is almost certainly a locking issue since it only appears to occure with
concurrent delivery. You are using reiserfs? I have xfs and ext3 to try.

Forgive me for being a skeptic, but I have had bad experiences with reiserfs
in the past. :-) I would greatly appriciate if you could try this on an ext2
partition. Only the database needs to be ext2.

--=20
Wesley W. Terpstra <wesley@...>

On Fri, Jun 06, 2003 at 08:11:40PM -0400, Kevin Brosius wrote:
> Ask, and you shall receive...

Sweeeeet!!!!

terpstra@...$ v
total 1105920
-rw-r-----    1 terpstra users          21 Jun  7 03:16 db
-rw-r-----    1 terpstra users        8192 Jun  7 03:16 db.iel
-rw-r-----    1 terpstra users        8192 Jun  7 03:16 db.ivq
-rw-r-----    1 terpstra users           0 Jun  7 03:16 db.writer
-rw-r-----    1 terpstra users     1084912 Jun  7 03:16 lkml
terpstra@...$ cat db
255 8192 255
idx
ivq
terpstra@...$

I had to run 'while true; do ./ind; done' to reproduce it, but I did.
It occures on xfs too. Anyways, thanks a ton!

I will fix this tomorrow. I don't need anything further from you.
That was a ton of help! Thanks a lot!

--=20
Wesley W. Terpstra <wesley@...>

On Sat, Jun 07, 2003 at 03:19:42AM +0200, Wesley W. Terpstra wrote:
> I will fix this tomorrow. I don't need anything further from you.
> That was a ton of help! Thanks a lot!

I just can't help myself. I can't go to sleep with this bug...

Check out this highly suspicious sequence of events:   ;-)

+   7073 I OWN THE LOCK!
 ??? 7075 SCANNING FILE
 ??? 7077 SCANNING FILE
 !!! 7073 COMMITING FILE
-   7073 I RELEASE THE LOCK!
+   7075 I OWN THE LOCK!
 !!! 7075 COMMITING FILE
-   7075 I RELEASE THE LOCK!
+   7077 I OWN THE LOCK!
 ??? 7079 SCANNING FILE
 !!! 7077 COMMITING FILE
-   7077 I RELEASE THE LOCK!
+   7079 I OWN THE LOCK!
 ??? 7081 SCANNING FILE
 ??? 7084 SCANNING FILE
 !!! 7079 COMMITING FILE
-   7079 I RELEASE THE LOCK!
+   7081 I OWN THE LOCK!
 ??? 7088 SCANNING FILE
 !!! 7081 COMMITING FILE
-   7081 I RELEASE THE LOCK!
+   7084 I OWN THE LOCK!
 !!! 7084 COMMITING FILE
-   7084 I RELEASE THE LOCK!
+   7088 I OWN THE LOCK!
 !!! 7088 COMMITING FILE
-   7088 I RELEASE THE LOCK!
 ??? 7086 SCANNING FILE
+   7086 I OWN THE LOCK!
 ??? 7090 SCANNING FILE
 !!! 7086 COMMITING FILE
-   7086 I RELEASE THE LOCK!
+   7090 I OWN THE LOCK!
 ??? 7092 SCANNING FILE
 ??? 7095 SCANNING FILE
 ??? 7097 SCANNING FILE
 !!! 7090 COMMITING FILE
-   7090 I RELEASE THE LOCK!


it should look like

+   7073 I OWN THE LOCK!
 ??? 7073 SCANNING FILE
 !!! 7073 COMMITING FILE
-   7073 I RELEASE THE LOCK!
+   7074 I OWN THE LOCK!
 ??? 7074 SCANNING FILE
 !!! 7074 COMMITING FILE
-   7074 I RELEASE THE LOCK!
+   7075 I OWN THE LOCK!
 ??? 7075 SCANNING FILE
 !!! 7075 COMMITING FILE
-   7075 I RELEASE THE LOCK!

=2E.. but it sure don't!
This bug will die very soon.

--=20
Wesley W. Terpstra <wesley@...>

"Wesley W. Terpstra" wrote:
> 
> 
> On Sat, Jun 07, 2003 at 03:19:42AM +0200, Wesley W. Terpstra wrote:
> > I will fix this tomorrow. I don't need anything further from you.
> > That was a ton of help! Thanks a lot!
> 
> I just can't help myself. I can't go to sleep with this bug...
> 
> Check out this highly suspicious sequence of events:   ;-)
> 
> +   7073 I OWN THE LOCK!
>  ??? 7075 SCANNING FILE
>  ??? 7077 SCANNING FILE
>  !!! 7073 COMMITING FILE
> -   7073 I RELEASE THE LOCK!
> +   7075 I OWN THE LOCK!
>  !!! 7075 COMMITING FILE
> -   7075 I RELEASE THE LOCK!
> +   7077 I OWN THE LOCK!
>  ??? 7079 SCANNING FILE
>  !!! 7077 COMMITING FILE
> -   7077 I RELEASE THE LOCK!
> +   7079 I OWN THE LOCK!
>  ??? 7081 SCANNING FILE
>  ??? 7084 SCANNING FILE
>  !!! 7079 COMMITING FILE
> -   7079 I RELEASE THE LOCK!
> +   7081 I OWN THE LOCK!
>  ??? 7088 SCANNING FILE
>  !!! 7081 COMMITING FILE
> -   7081 I RELEASE THE LOCK!
> +   7084 I OWN THE LOCK!
>  !!! 7084 COMMITING FILE
> -   7084 I RELEASE THE LOCK!
> +   7088 I OWN THE LOCK!
>  !!! 7088 COMMITING FILE
> -   7088 I RELEASE THE LOCK!
>  ??? 7086 SCANNING FILE
> +   7086 I OWN THE LOCK!
>  ??? 7090 SCANNING FILE
>  !!! 7086 COMMITING FILE
> -   7086 I RELEASE THE LOCK!
> +   7090 I OWN THE LOCK!
>  ??? 7092 SCANNING FILE
>  ??? 7095 SCANNING FILE
>  ??? 7097 SCANNING FILE
>  !!! 7090 COMMITING FILE
> -   7090 I RELEASE THE LOCK!
> 
> it should look like
> 
> +   7073 I OWN THE LOCK!
>  ??? 7073 SCANNING FILE
>  !!! 7073 COMMITING FILE
> -   7073 I RELEASE THE LOCK!
> +   7074 I OWN THE LOCK!
>  ??? 7074 SCANNING FILE
>  !!! 7074 COMMITING FILE
> -   7074 I RELEASE THE LOCK!
> +   7075 I OWN THE LOCK!
>  ??? 7075 SCANNING FILE
>  !!! 7075 COMMITING FILE
> -   7075 I RELEASE THE LOCK!
> 
> ... but it sure don't!
> This bug will die very soon.


Excellent!  Glad I could help :)  That bad sequence starts to really go
south at the end there.  Scanning going on outside the locks?  I look
forward to a healthy bug squashing!

-- 
Kevin

On Fri, Jun 06, 2003 at 09:43:57PM -0400, Kevin Brosius wrote:
> Excellent!  Glad I could help :)  That bad sequence starts to really go
> south at the end there.  Scanning going on outside the locks?  I look
> forward to a healthy bug squashing!

Squash.

--=20
Wesley W. Terpstra <wesley@...>

"Wesley W. Terpstra" wrote:
> 
> 
> On Fri, Jun 06, 2003 at 09:43:57PM -0400, Kevin Brosius wrote:
> > Excellent!  Glad I could help :)  That bad sequence starts to really go
> > south at the end there.  Scanning going on outside the locks?  I look
> > forward to a healthy bug squashing!
> 
> Squash.

Works great.  I just hit it with a ~60 message postfix queue flush, and
a couple seconds later everything is done, no errors.  Nice Job!  Thank
you.

-- 
Kevin