search

grosjo / fts-xapian

Dovecot FTS plugin based on Xapian
GNU Lesser General Public License v2.1
91 stars 19 forks source link

Search times out when fts_autoindex=yes, lowmemory mode is active and changes requiring indexing have occured #146

Closed an0nz closed 6 months ago

an0nz commented 7 months ago

Hi @grosjo , this is a follow on from issue #145, upgrading to the latest version did not actually resolve the issue, it appeared to but I just needed to wait until we hit lowmemory again, moving to the latest release did fix numerous other errors we were seeing so the package does need updating but the core problem still occurs which I now have debugged further.

When fts_autoindex = yes and lowmemory mode is triggered you are unable to search after the arrival of a new email even after the indexer-worker has finished indexing the mailbox, I am not sure if it actually did or not as lsof on the processes never showed the test mailbox but it would have completed quickly so was easily missed.

With fts_autoindex = no I have been unable to reproduce the error when triggering lowmemory mode, although this could be an issue with my testing.

Server

Test scenario

Ensure fts-xapian is configured with fts_autoindex = yes Fully index the mailbox doveadm index -u 'user@domain.com' '*' Search and make sure it works Send an email to the account

Check lda logs for indexing on arrival

Jan  9 00:35:21 mail dovecot: lda(user@domain.com)<3252032><xwnjDjn3nGVAnzEAsUmEQg>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
Jan  9 00:35:21 mail dovecot: lda(user@domain.com)<3252032><xwnjDjn3nGVAnzEAsUmEQg>: FTS Xapian: Starting with partial=3 full=18 verbose=1 lowmemory=250 MB vs freemem=1730 MB
Jan  9 00:35:21 mail dovecot: lda(user@domain.com)<3252032><xwnjDjn3nGVAnzEAsUmEQg>: save: box=INBOX, uid=13668, msgid=<CAEw2ge1BJJAUuNGpGyQU1U32mqioVm03xV3h7Wr43-iAHETAoQ@mail.gmail.com>, size=3443, from=Sender <sender@otherdomain.com>, subject=test, flags=()
Jan  9 00:35:21 mail dovecot: lda(user@domain.com)<3252032><xwnjDjn3nGVAnzEAsUmEQg>: sieve: from=sender@otherdomain.com, envelope_sender=sender@gmail.com, subject=test, msgid=<CAEw2ge1BJJAUuNGpGyQU1U32mqioVm03xV3h7Wr43-iAHETAoQ@mail.gmail.com>, size=3443, delivery_time=31ms, stored mail into mailbox 'INBOX'
Jan  9 00:35:21 mail dovecot: lda(user@domain.com)<3252032><xwnjDjn3nGVAnzEAsUmEQg>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes)

Attempt search

Check imap logs

Jan  9 00:35:29 mail dovecot: imap-login: Login: user=<user@domain.com>, method=PLAIN, rip=yyy.yyy.yyy.yyy, lip=xxx.xxx.xxx.xxx, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
Jan  9 00:35:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
Jan  9 00:35:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Starting with partial=3 full=18 verbose=1 lowmemory=250 MB vs freemem=512 MB
Jan  9 00:35:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: fts_backend_xapian_get_last_uid
Jan  9 00:35:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Set box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 00:35:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
Jan  9 00:35:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Get last UID of INBOX (79704f04f3940863160a0900b1498442) = 13667
... Wait 5 minutes
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: Disconnected: Connection closed (UID SEARCH running for 300.331 + waiting input for 0.019 secs, 101 B in + 0 B out, state=wait-external) in=259 out=28993 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes)
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Unset box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: fts_backend_xapian_oldbox
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: fts_backend_xapian_oldbox - done
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: fts_backend_xapian_release (unset_box)
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: Committed 'unset_box' in 0 ms
Jan  9 00:40:29 mail dovecot: imap(user@domain.com)<3252047><JqvSW34O0NzOUGCq>: FTS Xapian: fts_backend_xapian_release (unset_box) - done

Search fails Manually index the mailbox doveadm index -u 'user@domain.com' '*' Attempt search, everything works correctly

Now set fts_autoindex = no and restart dovecot (I set lowmemory=2048 for this test so it would trigger as free was showing 600MB) Send a test email

Check lda logs to ensure no indexing on arrival

Jan  9 02:18:38 mail dovecot: lda(user@domain.com)<3270669><vNltIW4PnWUN6DEAsUmEQg>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
Jan  9 02:18:38 mail dovecot: lda(user@domain.com)<3270669><vNltIW4PnWUN6DEAsUmEQg>: FTS Xapian: Starting with partial=3 full=18 verbose=1 lowmemory=2048 MB vs freemem=571 MB
Jan  9 02:18:38 mail dovecot: lda(user@domain.com)<3270669><vNltIW4PnWUN6DEAsUmEQg>: save: box=INBOX, uid=13679, msgid=<CAEw2ge18R6i3WOCOs31=RaegRDcvLkLOoSBfwbVCZG8yGdyU_w@mail.gmail.com>, size=3443, from=Sender <sender@gmail.com>, subject=off1, flags=()
Jan  9 02:18:38 mail dovecot: lda(user@domain.com)<3270669><vNltIW4PnWUN6DEAsUmEQg>: sieve: from=sender@gmail.com, envelope_sender=sender@gmail.com, subject=off1, msgid=<CAEw2ge18R6i3WOCOs31=RaegRDcvLkLOoSBfwbVCZG8yGdyU_w@mail.gmail.com>, size=3443, delivery_time=20ms, stored mail into mailbox 'INBOX'
Jan  9 02:18:38 mail dovecot: lda(user@domain.com)<3270669><vNltIW4PnWUN6DEAsUmEQg>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes)

Note that the lda log is identical to when fts_autoindex = yes which seems strange

Attempt search .. will work as normal

Jan  9 02:18:57 mail dovecot: imap-login: Login: user=<user@domain.com>, method=PLAIN, rip=yyy.yyy.yyy.yyy, lip=xxx.xxx.xxx.xxx, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Starting with partial=3 full=18 verbose=1 lowmemory=2048 MB vs freemem=512 MB
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_get_last_uid
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Set box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Get last UID of INBOX (79704f04f3940863160a0900b1498442) = 13678
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_refresh
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_release (refresh)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Committed 'refresh' in 0 ms
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_release (refresh) - done
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_get_last_uid
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Set box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Get last UID of INBOX (79704f04f3940863160a0900b1498442) = 13679
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_lookup
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Set box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: QUery '' -> 0 results
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: 0 results in 0 ms
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_lookup
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Set box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: QUery 'from:"issues" OR to:"issues" OR cc:"issues" OR subject:"issues"' -> 245 results
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: 245 results in 21 ms
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: Disconnected: Logged out in=923 out=101788 deleted=0 expunged=0 trashed=0 hdr_count=32 hdr_bytes=56961 body_count=0 body_bytes=0
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Unset box 'INBOX' (79704f04f3940863160a0900b1498442)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_oldbox
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_oldbox - done
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_release (unset_box)
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Committed 'unset_box' in 0 ms
Jan  9 02:18:57 mail dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: fts_backend_xapian_release (unset_box) - done

Other issues

FTS Xapian takes its freemem value from free in Linux, it should be using available else eventually it will change to lowmemory on a busy server since inode cache data is stored in memory and slowly fills buff/cache even though that memory can be used.

# free -m
               total        used        free      shared  buff/cache   available
Mem:           24210        4855         434          10       18920       18952
Swap:            951         594         357

dovecot: imap(user@domain.com)<3270892><UyLczX8OJMvOUGCq>: FTS Xapian: Starting with partial=3 full=18 verbose=1 lowmemory=250 MB vs freemem=434

Due to this issue, lowmemory mode is activated when there is plenty of available memory, this in turn triggers the other bug reported above where search times out if fts_autoindex = yes and the mailbox folder has new messages

Current Solution

Less than ideal as it reduces the search speed a fair bit, set fts_autoindex = no

grosjo commented 7 months ago

Can you try with latest git ?

an0nz commented 7 months ago

Thanks @grosjo,

This has fixed the issue with fts_autoindex = yes based on the testing I have done so far, we will continue to monitor tthis though.

Remaining Issue

The decision to enter low memory mode on Linux seems to still be based on MemFree rather than MemAvailable causing it to enter into low memory mode when indexing.

Ideally this should be using MemAvailable or MemFree + Cached, my C++ knowledge is very low but it seems like you are using MemFree + Cached Line 543-546 so maybe the if(p==buffer) is not returning correctly?

fts_xapian = partial=3 full=18 verbose=1 lowmemory=13000

# doveadm index -u 'user@domain.com' '*'
doveadm(user@domain.com)<60774><G0BmDgNlomVm7QAAsUmEQg>: Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com)<60774><G0BmDgNlomVm7QAAsUmEQg>: Info: FTS Xapian: Starting with partial=3 full=18 verbose=1 lowmemory=13000 MB vs freemem=1857 MB
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Trash' (3b06201d7cc6526469d73300b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of Trash (3b06201d7cc6526469d73300b1498442) = 57
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Notes' (32b7e63175c6526454d73300b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Unset box 'Trash' (3b06201d7cc6526469d73300b1498442)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox - done
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box)
doveadm(user@domain.com): Info: FTS Xapian: Committed 'unset_box' in 0 ms
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box) - done
doveadm(user@domain.com): Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of Notes (32b7e63175c6526454d73300b1498442) = 0
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Drafts' (ad8d0321d3e8f4631a231600b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Unset box 'Notes' (32b7e63175c6526454d73300b1498442)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox - done
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box)
doveadm(user@domain.com): Info: FTS Xapian: Committed 'unset_box' in 0 ms
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box) - done
doveadm(user@domain.com): Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of Drafts (ad8d0321d3e8f4631a231600b1498442) = 4148
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'My Sent Items' (853e0d2651cdf463ebea1500b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Unset box 'Drafts' (ad8d0321d3e8f4631a231600b1498442)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox - done
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box)
doveadm(user@domain.com): Info: FTS Xapian: Committed 'unset_box' in 0 ms
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box) - done
doveadm(user@domain.com): Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of My Sent Items (853e0d2651cdf463ebea1500b1498442) = 7094
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Deleted Items' (10392b22ae05c06372580a00b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Unset box 'My Sent Items' (853e0d2651cdf463ebea1500b1498442)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox - done
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box)
doveadm(user@domain.com): Info: FTS Xapian: Committed 'unset_box' in 0 ms
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box) - done
doveadm(user@domain.com): Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of Deleted Items (10392b22ae05c06372580a00b1498442) = 34
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Sent' (300c131fae05c06372580a00b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Unset box 'Deleted Items' (10392b22ae05c06372580a00b1498442)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox - done
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box)
doveadm(user@domain.com): Info: FTS Xapian: Committed 'unset_box' in 0 ms
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (unset_box) - done
doveadm(user@domain.com): Info: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of Sent (300c131fae05c06372580a00b1498442) = 1315
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_get_last_uid
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Sent' (300c131fae05c06372580a00b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Get last UID of Sent (300c131fae05c06372580a00b1498442) = 1315
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_update_context
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_update_set_mailbox
doveadm(user@domain.com): Info: FTS Xapian: Set box 'Sent' (300c131fae05c06372580a00b1498442)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_oldbox - done
doveadm(user@domain.com): Info: FTS Xapian: Start indexing 'Sent' (300c131fae05c06372580a00b1498442)
doveadm(user@domain.com): Info: FTS Xapian: Opening DB (RW) /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes/db_300c131fae05c06372580a00b1498442
doveadm(user@domain.com): Info: FTS Xapian: Opening DB (RW) /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes/db_300c131fae05c06372580a00b1498442 (1299 docs stored): Done
doveadm(user@domain.com): Warning: FTS Xapian: Warning Low memory (1857 MB)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (Low memory indexing)
doveadm(user@domain.com): Info: FTS Xapian: Commit & Close : 1299 (old) vs 1299 (new)
doveadm(user@domain.com): Info: FTS Xapian: Commit & Close - Done
doveadm(user@domain.com): Info: FTS Xapian: Committed 'Low memory indexing' in 0 ms (1299 docs in index)
doveadm(user@domain.com): Info: FTS Xapian: fts_backend_xapian_release (Low memory indexing) - done
doveadm(user@domain.com): Info: FTS Xapian: Opening DB (RW) /var/vmail/vmail1/domain.com/user//Maildir/xapian-indexes/db_300c131fae05c06372580a00b1498442
....
# free -m
               total        used        free      shared  buff/cache   available
Mem:           24210        5586        1502          10       17121       18220
Swap:            951         515         436

# cat /proc/meminfo
MemTotal:       24791528 kB
MemFree:         1537712 kB
MemAvailable:   18656980 kB
Buffers:               0 kB
Cached:         17188032 kB
SwapCached:       163120 kB
Active:         12492652 kB
Inactive:        9276028 kB
grosjo commented 7 months ago

Please check again latest git

an0nz commented 7 months ago

@grosjo All tests are now passing, indexing does not enter into low memory mode when Cached memory can be used, fts_autoindex = yes works as expected and does not break the existing index.

Thankyou for the quick turnaround and excellent module.

an0nz commented 7 months ago

@grosjo I celebrated too soon, I ran into the issue again however the issue related specifically to autoindex and memory limits seems to be resolved. This may be best as another issue or simply updating documentation.

I have tested a variety of actions to try trigger the bug, search, receive mail, move the email to a folder, delete another email with trash set to be excluded from autoindex, then done all that again and used doveadm fts optimize to see if that causes it but it wont occur.

The issue would then randomly occur again after a period of time where search was completely broken.

The latest config change I made which after an hour has not had the issue reoccur was to change

service indexer-worker {
    vsz_limit = 2G
    client_limit = 1
    process_limit = 4
}

to

service indexer-worker {
    vsz_limit = 2G
    client_limit = 1
    process_limit = 10
}

When experiencing the issue though multiple workers were idle so I cannot be certain if this was the problem or not as there are no process_limit errors in the logs.

If I manually reindex everything with doveadm index -A \* the Old & New message count for Commit & Close is nearly always different, sometimes by a few hundred. This feels like autoindex isnt really running and something is getting stuck.

The other oddity I have noticed is I have 1 mailbox on the server shared with another user of the same domain, for some reason the logs for fts-xapian indicate that every user action is taking a look at the shared index even without permission

doveadm acl get -u user1@domain.com inbox
ID                              Global Rights
user=user2@domain.com        admin create delete expunge insert lookup post read write write-deleted write-seen

grep user1@domain.com /var/log/dovecot/imap.log
Jan 17 02:39:14 mail dovecot: imap(bob@anotherdomain.com)<1184116><JxnhtSAPHttLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:14 mail dovecot: imap(contact@hello.com)<1184115><phThtSAPINtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:14 mail dovecot: imap(contact@hello.com)<1184115><phThtSAPINtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:14 mail dovecot: imap(sarah@mywebsite.com)<1184111><0crftSAPG9tLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:14 mail dovecot: imap(sarah@mywebsite.com)<1184111><0crftSAPG9tLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:14 mail dovecot: imap(sarah@mywebsite.com)<1184111><0crftSAPG9tLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:14 mail dovecot: imap(sarah@mywebsite.com)<1184111><0crftSAPG9tLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(jdoe@anotherdomain.com)<1184108><w5vftSAPGNtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(jdoe@anotherdomain.com)<1184108><w5vftSAPGNtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(jdoe@anotherdomain.com)<1184108><w5vftSAPGNtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(jdoe@anotherdomain.com)<1184108><w5vftSAPGNtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(marketing@company.com)<1184113><OxHhtSAPH9tLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(marketing@company.com)<1184113><OxHhtSAPH9tLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(marketing@company.com)<1184113><OxHhtSAPH9tLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(marketing@company.com)<1184113><OxHhtSAPH9tLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(james@example.net)<1184110><H7vftSAPGdtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(james@example.net)<1184110><H7vftSAPGdtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(james@example.net)<1184110><H7vftSAPGdtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(james@example.net)<1184110><H7vftSAPGdtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(jane@anotherdomain.com)<1184109><PrDftSAPGttLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(jane@anotherdomain.com)<1184109><PrDftSAPGttLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(jane@anotherdomain.com)<1184109><PrDftSAPGttLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(jane@anotherdomain.com)<1184109><PrDftSAPGttLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(sales@anotherdomain.com)<1184112><t9jftSAPHNtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(sales@anotherdomain.com)<1184112><t9jftSAPHNtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(sales@anotherdomain.com)<1184112><t9jftSAPHNtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(sales@anotherdomain.com)<1184112><t9jftSAPHNtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1184107><tpnftSAPF9tLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1184107><tpnftSAPF9tLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1184107><tpnftSAPF9tLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1184107><tpnftSAPF9tLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1186946><UEnZtSAPDdtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1186946><UEnZtSAPDdtLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1186946><UEnZtSAPDdtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:15 mail dovecot: imap(support@testing.com)<1186946><UEnZtSAPDdtLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:23 mail dovecot: imap(info@test123.org)<1187016><Yd+YBSEP0uvMDaRU>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:23 mail dovecot: imap(info@test123.org)<1187016><Yd+YBSEP0uvMDaRU>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:23 mail dovecot: imap(info@test123.org)<1187016><Yd+YBSEP0uvMDaRU>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:23 mail dovecot: imap(info@test123.org)<1187016><Yd+YBSEP0uvMDaRU>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:25 mail dovecot: imap(secretary@support.org)<1187039><9+mLbyAPzdSSRqhO>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:25 mail dovecot: imap(secretary@support.org)<1187039><9+mLbyAPzdSSRqhO>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:25 mail dovecot: imap(secretary@support.org)<1187039><9+mLbyAPzdSSRqhO>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:25 mail dovecot: imap(secretary@support.org)<1187039><9+mLbyAPzdSSRqhO>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:25 mail dovecot: imap(chair@support.org)<1187042><pfGLbyAP0dSSRqhO>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:25 mail dovecot: imap(chair@support.org)<1187042><pfGLbyAP0dSSRqhO>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:25 mail dovecot: imap(chair@support.org)<1187042><pfGLbyAP0dSSRqhO>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:25 mail dovecot: imap(chair@support.org)<1187042><pfGLbyAP0dSSRqhO>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:33 mail dovecot: imap(kelly@bugs.com)<1187102><Kme36SAP6rA0YCrV>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:33 mail dovecot: imap(kelly@bugs.com)<1187102><Kme36SAP6rA0YCrV>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:33 mail dovecot: imap(kelly@bugs.com)<1187102><Kme36SAP6rA0YCrV>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:33 mail dovecot: imap(kelly@bugs.com)<1187102><Kme36SAP6rA0YCrV>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:58 mail dovecot: imap(contact@problems.com)<1187310><Tvm1ByEPgNsvnpqI>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:58 mail dovecot: imap(contact@problems.com)<1187310><Tvm1ByEPgNsvnpqI>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:39:58 mail dovecot: imap(contact@problems.com)<1187310><Tvm1ByEPgNsvnpqI>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:39:58 mail dovecot: imap(contact@problems.com)<1187310><Tvm1ByEPgNsvnpqI>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:41:24 mail dovecot: imap(help@anotherdomain.com)<1188013><6h3cDCEPdOlLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:41:24 mail dovecot: imap(help@anotherdomain.com)<1188013><6h3cDCEPdOlLMfu6>: FTS Xapian: Index path = /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes
Jan 17 02:41:24 mail dovecot: imap(help@anotherdomain.com)<1188013><6h3cDCEPdOlLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
Jan 17 02:41:24 mail dovecot: imap(help@anotherdomain.com)<1188013><6h3cDCEPdOlLMfu6>: FTS Xapian: Deinit /var/vmail/vmail1/domain.com/user1//Maildir/Shared/domain.com/user1/xapian-indexes)
an0nz commented 7 months ago

I have been unable to find a way to reliably reproduce this issue, it seems to just happen at random. Changing process_limit did not fix the issue, it just took a while for the issues to return after restarting dovecot.

Looking through the logs there are no errors to indicate a problem other than xapian hanging and not responding, I see it on mailboxes as small as 300mb and as large as 70GB, the users it happens on are seemingly random and constantly change. The logs provided are all the detail it gives which doesn't indicate why or where it may be getting stuck.

For now I have had to disable fts-xapian as customers are getting frustrated with search working for a few hours or a day then failing until we run a manual index to fix everyone overnight. Unfortunately this module does not seem to really be useable on a mail server with a few hundred users and solr may still be the only option even if it is overly complex at a small scale.

grosjo commented 7 months ago

Cna you try just removing " client_limit = 1 process_limit = 10"

grosjo commented 7 months ago

Wait, there is something very wrong:

doveadm(user@domain.com): Warning: FTS Xapian: Warning Low memory (1857 MB)

1857 is above 250...

I tried to fix the calculatin in latest git

grosjo commented 7 months ago

ah, and you set "lowmemory=13000" you shall really remove that (low memory mode at 13G ?, no...)

an0nz commented 7 months ago

Currently lowmemory is set to 512, the 13000 was to force low memory mode to trigger the original bug.

These are the dovecot default values so are always set unless I override it with different values. client_limit = 1 process_limit = 10

grosjo commented 7 months ago

Ok, but in production, you shal use it with default values

lowMem is by default set to 250M, which is surely never reached on a production server, or you shall increase the RAM

grosjo commented 7 months ago

the principle is that below 250M (or lowmemory setting), the plugin flushes memory often to disk to avoid crashing the server. but this shall technically never happens on a production server

an0nz commented 7 months ago

I have it set to 512 just to provide a bit of extra buffer since the server has 24GB, I can remove the setting so it uses the default but I can’t see that making a difference to the issue we are seeing.

Can you add additional logging to help work out where it is hanging?

grosjo commented 7 months ago

Hi

The Lowmem mode is underperforming indeed as it is exact the purpose to avoid memory exhaustion minimizing memory usage by increasing disk I/O, in the extreme case of very low memory available

So, this route is not the correct one to find any route cause.

The actual performance issue is when xapian files are written on the disk.

I am thinking of a way to keep the handle in memory so disk writing happens less offen

grosjo commented 7 months ago

Please try with latest git

basil-conto commented 7 months ago

Please try with latest git

FWIW, since 4f4d7373985eb8a63a24f432349149800fb566e7, doveadm index -A \* fails for me. Sometimes it ends with the message Aborted, sometimes with Segmentation fault, and sometimes with

doveadm(outlook): Panic: Leaked t_pop() call
doveadm(outlook): Panic: Leaked t_pop() call
Aborted

On 992613498f1b6ad4828e047a36ace4083d7c883e doveadm index -A \* succeeds.

My settings include:

  fts_xapian = partial=3 full=20 attachments=0 verbose=1
  fts_autoindex = yes
  fts_enforced = yes
grosjo commented 7 months ago

please try again latest git

basil-conto commented 7 months ago

The abort no longer happens, thanks!

grosjo commented 7 months ago

Kindly let me know if further update is necessary

grosjo commented 6 months ago

@an0nz do not hesitate to re-open if any further issue