`doveadm index` doesn't index anything

[sergiodj]

Hi,

This may very well be a local configuration problem, so I apologize in advance if it's not a bug.

I'm running Debian testing with dovecot-core 1:2.3.18+dfsg1-1+b1 and dovecot-fts-xapian 1.5.5 (built locally; the package in unstable/testing doesn't work with dovecot 2.3.18).

Here's my conf.d/90-fts.conf:

mail_plugins = $mail_plugins fts fts_xapian

plugin {
        fts = xapian
        fts_xapian = partial=3 full=20 verbose=10
        fts_autoindex = yes
        fts_enforced = yes
        fts_decoder = decode2text
}

service indexer-worker {
        vsz_limit = 0
}

service decode2text {
        executable = script /usr/share/doc/dovecot-core/examples/decode2text.sh
        user = dovecot
        unix_listener decode2text {
                mode = 0666
        }
}

I have a non-standard mailbox configuration using namespaces, like this (from conf.d/10-mail.conf):

...
namespace {
  type = private 
  separator = /
  prefix = ns1/
  location = maildir:~/Mail/ns1:INBOX=~/Mail/ns1/INBOX:LAYOUT=fs
  inbox = no
  hidden = no  
  subscriptions = yes
}

namespace { 
  type = private
  separator = /
  prefix = ns2/
  location = maildir:~/Mail/ns2:INBOX=~/Mail/ns2/INBOX:LAYOUT=fs
  inbox = no
  hidden = no
  subscriptions = yes
}

namespace {
  type = private
  separator = /
  prefix = ns3/
  location = maildir:~/Mail/ns3:INBOX=~/Mail/ns3/INBOX:LAYOUT=fs
  inbox = yes
  hidden = no
  subscriptions = yes
}
...

I don't think there's anything else that could impact doveadm index, but if there is just let me know and I will gladly post the configuration here.

Anyway, what happens is that when I run doveadm index it doesn't do anything. It returns immediately (even though I have hundreds of thousands of messages to be indexed), and doesn't populate the xapian-indexes directories inside the respective namespaces' folders. Here's the output I see when I enable debugging:

# doveadm -v index -u myuser \*
Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentio
nal, so just ignore this message)
Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so: undefined symbol: quota_user_module (this is usually in
tentional, so just ignore this message)
Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (t
his is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usual
ly intentional, so just ignore this message)
Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests
 (this is usually intentional, so just ignore this message)
Apr 17 21:31:31 Debug: Loading modules from directory: /usr/lib/dovecot/modules
Apr 17 21:31:31 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_fts_plugin.so
Apr 17 21:31:31 Debug: Module loaded: /usr/lib/dovecot/modules/lib21_fts_xapian_plugin.so
Apr 17 21:31:31 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
Apr 17 21:31:31 Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is
usually intentional, so just ignore this message)
Apr 17 21:31:31 Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so: undefined symbol: quota_user_module (this is usually intentional, so just ignore this message)
Apr 17 21:31:31 Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
Apr 17 21:31:31 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so
Apr 17 21:31:31 Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
Apr 17 21:31:31 doveadm(myuser)<868012><>: Debug: auth-master: userdb lookup(myuser): Started userdb lookup
Apr 17 21:31:31 doveadm(myuser)<868012><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb: Connecting
Apr 17 21:31:31 doveadm(myuser)<868012><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=865141,uid=0): Client connected (fd=9)
Apr 17 21:31:31 doveadm(myuser)<868012><>: Debug: auth-master: userdb lookup(myuser): auth USER input: myuser system_groups_user=myuser uid=1000 gid=1000 home=/home/myuser
Apr 17 21:31:31 doveadm(myuser)<868012><>: Debug: auth-master: userdb lookup(myuser): Finished userdb lookup (username=myuser system_groups_user=myuser uid=1000 gid=1000 home=/home/myuser)
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: Effective uid=1000, gid=1000, home=/home/myuser
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: Namespace : type=private, prefix=ns1/, sep=/, inbox=no, hidden=no, list=yes, subscriptions=yes location=maildir:~/Mail/ns1:INBOX=~/Mail/ns1/INBOX:LAYOUT=fs
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: fs: root=/home/myuser/Mail/ns1, index=, indexpvt=, control=, inbox=/home/myuser/Mail/ns1/INBOX, alt=
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: Namespace : type=private, prefix=ns2/, sep=/, inbox=no, hidden=no, list=yes, subscriptions=yes location=maildir:~/Mail/ns2:INBOX=~/Mail/ns2/INBOX:LAYOUT=fs
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: fs: root=/home/myuser/Mail/ns2, index=, indexpvt=, control=, inbox=/home/myuser/Mail/ns2/INBOX, alt=
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: Namespace : type=private, prefix=ns3/, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Mail/ns3:INBOX=~/Mail/ns3/INBOX:LAYOUT=fs
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: fs: root=/home/myuser/Mail/ns3, index=, indexpvt=, control=, inbox=/home/myuser/Mail/ns3/INBOX, alt=
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: Namespace : type=private, prefix=, sep=, inbox=no, hidden=yes, list=no, subscriptions=no location=fail::LAYOUT=none
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: none: root=, index=, indexpvt=, control=, inbox=, alt=
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: fts: Indexes disabled for namespace ''
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Info: FTS Xapian: Index path = /home/myuser/Mail/ns2/xapian-indexes
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: RLIM AS =18014398509481984
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: RLIM DATA =18014398509481984
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: Free memory 86001 MB
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Info: FTS Xapian: Starting with partial=3 full=20 verbose=10 lowmemory=250 MB vs freemem=86001 MB
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Info: FTS Xapian: Index path = /home/myuser/Mail/ns3/xapian-indexes
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: RLIM AS =18014398509481984
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: RLIM DATA =18014398509481984
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: Free memory 86001 MB
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Info: FTS Xapian: Starting with partial=3 full=20 verbose=10 lowmemory=250 MB vs freemem=86001 MB
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Info: FTS Xapian: Index path = /home/myuser/Mail/ns1/xapian-indexes
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: RLIM AS =18014398509481984
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: RLIM DATA =18014398509481984
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Warning: FTS Xapian: Free memory 86001 MB
Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Info: FTS Xapian: Starting with partial=3 full=20 verbose=10 lowmemory=250 MB vs freemem=86001 MB
Apr 17 21:31:31 doveadm(myuser): Info: FTS Xapian: Deinit /home/myuser/Mail/ns2/xapian-indexes)
Apr 17 21:31:31 doveadm(myuser): Info: FTS Xapian: Deinit /home/myuser/Mail/ns3/xapian-indexes)
Apr 17 21:31:31 doveadm(myuser): Info: FTS Xapian: Deinit /home/myuser/Mail/ns1/xapian-indexes)
Apr 17 21:31:31 doveadm(868012): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=865141,uid=0): Disconnected: Connection closed (fd=9)

Initially the line Apr 17 21:31:31 doveadm(myuser)<868012><RLbQM3O/XGKsPg0AquyQZQ>: Debug: fts: Indexes disabled for namespace '' caught my attention, but after some research I found that it's harmless. I also tried running doveadm fts rescan, to no avail.

[sergiodj]

Huh, I tried searching something from inside my MUA and now I see the indexer-worker running. That's really strange; I was expecting it to run as soon as I issued the doveadm index command. Now my MUA is blocked waiting for dovecot to reply to the search, which is what I was trying to avoid.

[sergiodj]

For what it's worth, the indexer worker is still running after almost 18 hours. Is this also expected? Not entirely sure whether this is a problem with fts-xapian or dovecot itself.

[grosjo]

if you issue a rescan, dovecot bascially delete indexes and re-index the whole mailbox

How big is your mailbox ? Can you share more about the log file ?

[sergiodj]

if you issue a rescan, dovecot bascially delete indexes and re-index the whole mailbox

Right. I've issued a rescan in the beginning when I noticed that the initial index command wasn't doing anything, but when it started running I didn't issue a rescan anymore.

How big is your mailbox ? Can you share more about the log file ?

The mailbox contains around 300k emails. It's big, but I'm sure there are much bigger mailboxes out there.

Yeah, I can share more abou the log file. What specific info would you like to see?

[grosjo]

For the log file, insterested in what the indexer process is doing during 18 hours ;)

[sergiodj]

I was also interested to know that. Unfortunately I had disabled the verbose/debug options, so there's nothing useful in the log. Also, the process has finished now.

I will try issuing a rescan later today to see if I can reproduce it; will let you know.

[sergiodj]

FWIW, I tried another FTS plugin here and had the same problem with doveadm index not indexing anything when invoked, so I'm closing this bug because it's unlikely this is a problem with fts-xapian itself. Thanks for the help, though.