database is locked #55

aletheia7 · 2020-09-23T22:36:38Z

I am getting occasional errors in dovecot:

...
Sep 23 12:31:52 orange dovecot[17049]: indexer-worker(ray)<156088><ybAEGqiia1+3YQIAfYjuOg:iI6CG6iia1+4YQIAfYjuOg>: Error: FTS Xapian: Error in expunge fct (SELECT DOCID,ID from IDS ORDER BY DOCID LIMIT 5) (database is locked) : unset_box
Sep 23 12:31:52 orange dovecot[17049]: lmtp(156087): Error: FTS Xapian: adding expunge IDs (REPLACE INTO IDS (DOCID,ID) VALUES (3550,144670);) : err(5,database is locked)
...

fts-xapian: 68ea96 (master)
OS: Debian Linux testing/bullseye
Dovecot: v2.3.11.3 (latest)

The text was updated successfully, but these errors were encountered:

grosjo · 2020-09-27T14:26:42Z

Can you set verbose=1 with the latest git , and share messages before and after the error ?

aletheia7 · 2020-09-29T23:22:05Z

Received One

Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630, me): FTS Xapian: Starting with partial=4 full=20 attachments=0 verbose=1
Sep 29 04:20:37 orange dovecot[1429]: lmtp(me)<47630><KMRRMIUYc18OugAAfYjuOg>: sieve: msgid=<0.1.44.FA.1D6965289EA7E42.0@omp.e.lenscrafters.com>: fileinto action: stored mail into mailbox 'Junk/Other'
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTX Xapian: Set box 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Unset box '(null)' ((null))
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Committed 'unset_box' in 0 ms
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Expunge UID=8971
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: adding expunge IDs : REPLACE INTO IDS (DOCID,ID) VALUES (6507,8971);
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Starting with partial=4 full=20 attachments=0 verbose=1
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTX Xapian: Set box 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Unset box '(null)' ((null))
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Committed 'unset_box' in 0 ms
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Get last UID of Junk/Other (ececcd190285a45da97100007d88ee3a) = 9164
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTX Xapian: Set box 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Get last UID of Junk/Other (ececcd190285a45da97100007d88ee3a) = 9164
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTX Xapian: Set box 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Start indexing 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Expunge UID=8972
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: adding expunge IDs : REPLACE INTO IDS (DOCID,ID) VALUES (6508,8972);
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Unset box 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: FTS Xapian: Done indexing 'Junk/Other' (ececcd190285a45da97100007d88ee3a) (1 msgs in 15 ms, rate: 66.7)
Sep 29 04:20:37 orange dovecot[1429]: indexer-worker(me)<47637><KMRRMIUYc18OugAAfYjuOg:WT7GMYUYc18VugAAfYjuOg>: Error: FTS Xapian: Error in expunge fct (SELECT DOCID,ID from IDS ORDER BY DOCID LIMIT 5) (database is locked) : unset_box
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Unset box 'Junk/Other' (ececcd190285a45da97100007d88ee3a)
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Committed 'unset_box' in 0 ms
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Box is empty
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Unset box '(null)' ((null))
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): FTS Xapian: Committed 'unset_box' in 0 ms
Sep 29 04:20:37 orange dovecot[1429]: lmtp(47630): Disconnect from local: Client has quit the connection (state=READY)

aletheia7 · 2020-09-29T23:23:33Z

The indexer had successfully completed an index operation before and after this problem at exactly the same minute/second.

grosjo · 2020-10-03T10:16:46Z

Hello, can you try with additional updates ?

aletheia7 · 2020-10-03T19:27:30Z

Upgraded and watching.

aletheia7 · 2020-10-07T21:00:12Z

Received One Today

https://gist.github.com/aletheia7/f7c9e38592fa34172313594908423f02#file-journal-txt-L54

grosjo · 2020-10-08T09:01:23Z

Do you have a process of expunging the mailbox in parallel to main core binary ?

aletheia7 · 2020-10-08T20:58:04Z

Yes.
The following job runs daily at 1:00 am as root via a systemd.timer:

    /usr/bin/doveadm expunge -A mailbox '*' from 'no_reply @ooma.com' since 2017-06-28 before 30d header Subject 'New voicemail

The following expunge rules are defined in the dovecot local.conf file:

namespace inbox {
  ...
  mailbox Junk {
    special_use = \Junk
    auto = subscribe
    autoexpunge = 7d
  }
  mailbox Junk/Other {
    special_use = \Junk
    auto = no
    autoexpunge = 7d
  }
  mailbox "Junk E-mail" {
    special_use = \Junk   
    autoexpunge = 7d
  }
  mailbox Backups/baobab {
    auto = no
    autoexpunge = 180days
  }
  mailbox Backups/peach {
    auto = no
    autoexpunge = 180days
  }
  ...
}

The Junk and Backups/baobab mailbox expunge rules get executed when a new email arrives. They get executed often because backups occur in the evening at ~ 22:00 and, well, we get a lot of Junk/Spam.

aletheia7 · 2020-10-08T21:37:16Z

It's always one email account.

Received 5 Today

aletheia7 · 2020-10-08T21:57:17Z

Maybe the sqlite timeout should be increased. What is the timeout?

https://sqlite.org/c3ref/busy_timeout.html

Is the code using sqlite wal mode?
https://www.sqlite.org/wal.html

Is the sqlite code in dovecot or fts-xapian?

grosjo · 2020-10-10T10:52:13Z

All sqlite calls are in fts-xapian.
I added a "timeout" function.
Please knidly check again

aletheia7 · 2020-10-12T20:59:20Z

I upgraded now. Also, it's happening to another email account too.

aletheia7 · 2020-10-14T20:00:19Z

One yesterday. Two today.

grosjo · 2020-10-16T04:38:44Z

I increased the timeout to see

aletheia7 · 2020-10-19T21:20:04Z

I used the 100 timeout on 2020-10-16. I received one "database is locked" on 2020-10-17.

I changed 100 -> 500.

slavkoja · 2020-10-19T21:38:23Z

Please, @grosjo, for what is SQLite used? Cannot this be stored directly into xapian DB?

AFAIK, the timeout is in msec. Default timeout in Python & Exim is 5000 msec, Dovecot uses 1000 msec. IMO 100 msec is too low.

grosjo · 2020-10-20T01:36:41Z

I used SQlite to handle expunges outside xapuan, as xapian does not explicitely handle concurrency.

https://getting-started-with-xapian.readthedocs.io/en/latest/concepts/concurrency.html

Does 5000 timeout solve the issue ?
Do you have a better idea ?

grosjo · 2020-10-20T04:12:20Z

Actually tried with https://tartarus.org/james/xapian-apidoc/html/namespaceXapian.html#a296fe000d6d9525bb8e80f72838026a6
from recent version of Xapian

Make sense ?

slavkoja · 2020-10-20T09:48:39Z

I cannot comment xapian locking, but if i properly understand provided link, there will be no timeout, but infinite waiting for lock, i am not sure if it is good idea.

I can comment SQLite locking, but i have only basic C/C++ experiences, thus i didn't inspect your code (i will lost in int), thus some of my notes can be applied already (you simple ignore them):

use transactions to write multiple records, for better performance
keep transactions as short as possible, any write transaction will lock the database for write & read
make sure that proper indexes are defined, otherwise SQLite (by default) will (re)create dynamic index on any read, which can be slow
writing to indexes can slow write performace, if missing indexes are OK, disable its auto creation by PRAGMA automatic_index command https://sqlite.org/pragma.html#pragma_automatic_index

Using WAL mode can improve performance, especially it will allow concurrent write/read access. Its setting is persisent and can be enabled/disabled anytime, even by CLI tool. It can little slowdown reads, but concurrent access can improve it at all. Because it is persistent, it can be enabled on DB file creation (only once) and because it is not error to enable it more time, it can be enabled ag. in time plugin initialization, to ensure enabling it for existing DB file .

grosjo · 2020-10-20T12:08:06Z

Please kindly test again, and let me know.

aletheia7 · 2020-10-20T14:48:29Z

Please kindly test again, and let me know.

I will. I am currently testing 3f7fe69 with sqlite3_busy_timeout(500).

After 24 h I will test b8cad27 (latest).

aletheia7 · 2020-10-21T20:22:00Z

An sqlite3_busy_timeout of 500 works for me.

Now upgrade with the latest.

aletheia7 · 2020-10-22T20:25:16Z

Problem fixed in fee8502.

grosjo added a commit that referenced this issue Sep 27, 2020

Issue #55

63d402d

grosjo added a commit that referenced this issue Oct 3, 2020

Issue #55

be1d863

grosjo added a commit that referenced this issue Oct 3, 2020

Issue #55

5594d3d

grosjo added a commit that referenced this issue Oct 4, 2020

Issue #55

cb0769a

grosjo added a commit that referenced this issue Oct 4, 2020

Issue #55

ac52833

grosjo added a commit that referenced this issue Oct 10, 2020

Issue #55

5724c38

grosjo added a commit that referenced this issue Oct 16, 2020

Issue #55

7b8b470

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

2712dfb

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

ca4567e

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

e433201

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

369b86f

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

a8e4cb1

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

b8cad27

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

d5c979a

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

42e38a4

grosjo added a commit that referenced this issue Oct 20, 2020

Issue #55

fee8502

aletheia7 closed this as completed Oct 22, 2020

Philippe23 mentioned this issue Feb 28, 2024

1.5.9: Can't re-create Xapian DB; DatabaseCreateError - Permission denied #147

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

database is locked #55

database is locked #55

aletheia7 commented Sep 23, 2020

grosjo commented Sep 27, 2020

aletheia7 commented Sep 29, 2020

aletheia7 commented Sep 29, 2020

grosjo commented Oct 3, 2020

aletheia7 commented Oct 3, 2020

aletheia7 commented Oct 7, 2020 •

edited

grosjo commented Oct 8, 2020

aletheia7 commented Oct 8, 2020

aletheia7 commented Oct 8, 2020 •

edited

aletheia7 commented Oct 8, 2020

grosjo commented Oct 10, 2020 •

edited

aletheia7 commented Oct 12, 2020

aletheia7 commented Oct 14, 2020

grosjo commented Oct 16, 2020

aletheia7 commented Oct 19, 2020

slavkoja commented Oct 19, 2020

grosjo commented Oct 20, 2020

grosjo commented Oct 20, 2020

slavkoja commented Oct 20, 2020

grosjo commented Oct 20, 2020

aletheia7 commented Oct 20, 2020

aletheia7 commented Oct 21, 2020

aletheia7 commented Oct 22, 2020

database is locked #55

database is locked #55

Comments

aletheia7 commented Sep 23, 2020

grosjo commented Sep 27, 2020

aletheia7 commented Sep 29, 2020

Received One

aletheia7 commented Sep 29, 2020

grosjo commented Oct 3, 2020

aletheia7 commented Oct 3, 2020

aletheia7 commented Oct 7, 2020 • edited

Received One Today

grosjo commented Oct 8, 2020

aletheia7 commented Oct 8, 2020

aletheia7 commented Oct 8, 2020 • edited

Received 5 Today

aletheia7 commented Oct 8, 2020

grosjo commented Oct 10, 2020 • edited

aletheia7 commented Oct 12, 2020

aletheia7 commented Oct 14, 2020

grosjo commented Oct 16, 2020

aletheia7 commented Oct 19, 2020

slavkoja commented Oct 19, 2020

grosjo commented Oct 20, 2020

grosjo commented Oct 20, 2020

slavkoja commented Oct 20, 2020

grosjo commented Oct 20, 2020

aletheia7 commented Oct 20, 2020

aletheia7 commented Oct 21, 2020

aletheia7 commented Oct 22, 2020

aletheia7 commented Oct 7, 2020 •

edited

aletheia7 commented Oct 8, 2020 •

edited

grosjo commented Oct 10, 2020 •

edited