bug: [s]ave function adds bogus pathnames into the notmuch DB

[Selene Scriven]

After updating to the latest mutt-kz in git, I noticed some 
strange behavior.  I was getting weird results for folder-based 
queries.  After some investigation, I narrowed it down to the 
[s]ave and purge functions in mutt-kz.

I'm running git rev be196028c755d3ffff184e9781ac933fbacbd562 (Thu 
Jan 2 15:15:55 2014 +0100).

Steps to reproduce the issue:

  - Open a virtual folder in mutt-kz.
  - [s]ave a message to a different Maildir.  (original gets 
    marked as [D]eleted)
  - Purge deleted messages.

Mutt-kz then prints an error.  It's a bit hard to catch before 
the screen redraws, but it looks like...  "Writing 
notmuch://?query=(folder:INBOX or (...  (...older:in...ror: A 
Xapian exception occurred flushing database: Can't commit during 
a transaction"

At this point, I can query notmuch directly to see the broken 
pathname.  'notmuch search folder:$HOME' works, but I prefer this 
for more detail:

>  nm-files id:[e-mail]
  === id:[e-mail] ===
  thread:000000000003ff58  Today 10:31 [1/1] H&R Block; Appointments available now –
give us a call (unread)
  /home/selene/mail//home/selene/mail/receipts//new/1392149990.21796_1.mutt

  Messages: 1

After running 'notmuch new', the database updates by adding the correct pathname:

>  nm-files id:[e-mail]
  === id:[e-mail] ===
  thread:000000000003ff58  Today 10:31 [1/1] H&R Block; Appointments available now –
give us a call (unread)
  /home/selene/mail//home/selene/mail/receipts//new/1392149990.21796_1.mutt
  /home/selene/mail/receipts/new/1392149990.21796_1.mutt

  Messages: 1

This gets weird if the message is ever moved again, because the 
broken pathname shows up forever unless the DB gets dumped, 
rebuilt from scratch, and restored (which takes ~3 hours for me).  
Notmuch never detects the error or removes the bogus path.

For reference, here is the script I used above:

>  cat bin/local/nm-files 
  #!/bin/sh
  # show the files associated with each message for a given search

  for ID in $( notmuch search --output=messages $* ); do
    echo "=== $ID ==="
    notmuch search --output=summary $ID
    notmuch search --output=files $ID
    echo
  done
  echo -n "Messages: " ; notmuch search $* | wc -l


-- Selene

[Selene Scriven]

Some extra info from #notmuch:

<ToyKeeper> amdragon, j4ni: Here's the bug report I sent to mutt-kz.  Perhaps it
might be helpful for notmuch too?  http://pastebin.ca/2638732
<ToyKeeper> (it seems like notmuch should probably have a way to detect and remove
bogus paths)
<j4ni> ToyKeeper: rather, detect and not add them in the first place!
<ToyKeeper> ... perhaps when a move or copy is detected, it should stat all the
other known paths and remove anything weird?
<ToyKeeper> Or not adding them in the first place.  :)
<cworth> ToyKeeper: Yes, it's not clear where the bogus path is actually coming
from. Presumably some inconsistent database state due to the unhandlend Xapian exception.
<cworth> (And then, the question is why is there a repeatable Xapian exception being
hit.)
<cworth> ToyKeeper: More information here will definitely be helpful.
<j4ni> apparently a missing notmuch_database_end_atomic
<amdragon> j4ni: How does that translate into a bogus path in the database?
<ToyKeeper> cworth: I can at least say the issue was introduced sometime in the past
3 months or so.  Should be relatively easy to bisect, if nothing else...  though I'll
wait for KZ to respond before I dive in much further.
<j4ni> amdragon: that I don't know, but notmuch_database_close with transaction
in progress is the only way, afaict, to trigger the xapian exception in the referenced
log
<j4ni> ToyKeeper: you can pass on the info that one of the bugs is in
remove_filename() in mutt_notmuch.c. it does not call notmuch_database_end_atomic() on the
failure path of notmuch_database_find_message_by_filename().
<j4ni> however, at that point my guess is that the bad path is already in the
database
<j4ni> which could be the reason for notmuch_database_find_message_by_filename()
failing


-- Selene

[Karel Zak]

On Tue, Feb 11, 2014 at 01:50:16PM -0700, Selene Scriven wrote:

 Sorry for the delay, I was busy with something else.

>  Steps to reproduce the issue:
>  
>    - Open a virtual folder in mutt-kz.
>    - [s]ave a message to a different Maildir.  (original gets 
>      marked as [D]eleted)
>    - Purge deleted messages. 
 I'm no able to reproduce the problem, maybe you can try to compile
 mutt with --enable-debug and run ./mutt -d 2 and check the file
 ~/.muttdebug0. You will see something like:

[2014-03-06 10:28:52] nm: db open '/home/kzak/Mail/Maildir/' [WRITE] (timeout 5)
[2014-03-06 10:28:52] nm: rename filename,
/home/kzak/Mail/Maildir/bee/cur/1394097976.25403_1.x2:2,S ->
/home/kzak/Mail/Maildir/misc/cur/1394098132.25667_1.x2:2,S
[2014-03-06 10:28:52] nm: db trans start
[2014-03-06 10:28:52] nm: rename: add
'/home/kzak/Mail/Maildir/misc/cur/1394098132.25667_1.x2:2,S'
[2014-03-06 10:28:52] nm: rename: rem
'/home/kzak/Mail/Maildir/bee/cur/1394097976.25403_1.x2:2,S'
[2014-03-06 10:28:52] nm: rename: syncing duplicate filename
[2014-03-06 10:28:52] nm: add tag: 'rh'
[2014-03-06 10:28:52] nm: db trans end
[2014-03-06 10:28:52] nm: db close

 that's produced by code that rename files.

/home/selene/mail/receipts//new/1392149990.21796_1.mutt

>  Mutt-kz then prints an error.  It's a bit hard to catch before 
>  the screen redraws, but it looks like...  "Writing 
>  notmuch://?query=(folder:INBOX or (...  (...older:in...ror: A 
>  Xapian exception occurred flushing database: Can't commit during 
>  a transaction" 
 this problem (exception) with unbalanced transaction should be fixed now 

 git pull; make
 
>  At this point, I can query notmuch directly to see the broken 
>  pathname.  'notmuch search folder:$HOME' works, but I prefer this 
>  for more detail:
>  
>    > nm-files id:[e-mail]
>    === id:[e-mail] ===
>    thread:000000000003ff58  Today 10:31 [1/1] H&R Block; Appointments available now –
> give us a call (unread)
>    /home/selene/mail//home/selene/mail/receipts//new/1392149990.21796_1.mutt 
 hmm... I don't understand how is it possible to add to DB such path
 when we use notmuch_database_add_message() that parses the message.

 IMHO it's mistake that there is no "notmuch fsck" command to clean up the
DB.

    Karel


-- 
 Karel Zak  <kzak(a)redhat.com&gt;
 http://karelzak.blogspot.com