sqlite_busy ... write txn held by unknown

MichaelH

Hi,
i get this error or info message in the log gromox-http. During this a login into the Web IF is not possible.

[2024-09-01 16:04:28.834381]: system: HTTP daemon is now running
[2024-09-02 06:32:08.754808]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:32:08.755669]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:33:13.764661]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:33:13.765324]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:33:49.779337]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:33:49.780080]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:43:28.675330]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:43:28.676125]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:46:18.896622]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:46:18.897508]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:46:46.891764]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:46:46.892286]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:49:22.904480]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:49:22.905101]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:51:59.915932]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:51:59.916493]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 06:58:31.160969]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
[2024-09-02 06:58:31.161857]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown
[2024-09-02 07:02:14.335329]: gromox-http 2.31.21.gf1d7ee1 (pid 27407 uid 0)

WalterH

Is a backup job running at this time?

WalterH

What tells a lsof /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 ?

MichaelH

Hi @WalterH

here the output from lsof /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3

mail01:~ # lsof /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
COMMAND   PID   USER   FD   TYPE DEVICE   SIZE/OFF    NODE NAME
http    32560 gromox   36ur  REG  254,0 3971227648 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   44ur  REG  254,0 3971227648 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   63ur  REG  254,0 3971227648 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   77ur  REG  254,0 3971227648 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   81ur  REG  254,0 3971227648 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
mail01:~ #

A backup should not be running, at least I haven't set one up.

crpb

That output is ok.

You will need to use the lsof when that error happens. Because then we might see something else besides the http process.

WalterH

Restarting gromox-http, will this solve the issue?
systemctl restart gromox-http

MichaelH

@crpb
here is a Output where the error still exist

mail01:~ # lsof /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
COMMAND   PID   USER   FD   TYPE DEVICE   SIZE/OFF    NODE NAME
http    32560 gromox   36ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   44ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   63ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   77ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   81ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   93ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
http    32560 gromox   97ur  REG  254,0 3973001216 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3
mail01:~ #

@WalterH

Yes restart the gromox-http process will resolve the error.

WalterH

Seams a process in gromox-http hangs and the restart solved this issue.

crpb

Well, those kinda outputs are basically always there during workhours 😛

lsof /var/lib/gromox/user/*/*/exmdb/exchange.sqlite*

MichaelH

Is there anything else I can check? Or at least notice it more quickly. It just occurs irregularly, mostly when I'm not at the PC.

crpb

It shouldn't happen. And those open files are totaly normal.

(well, whatever one can still see there... they are open because that is how it works ^_^)
I found one server where i could see a few of those in the last two weeks.. My own.. But it doesn't look like your case..

gromi:~ # journalctl --since -2weeks --grep "BEGIN IMMEDIATE"
-- Boot 8af53553afca451eb6ebac0dec88ddd5 --
-- Boot 46b1d2ba1b604a3aaaa23f0d0dfec471 --
Aug 27 09:20:49 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
Aug 28 12:36:48 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Aug 28 14:47:33 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Aug 29 11:40:26 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
Aug 29 13:04:26 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
Aug 30 04:33:48 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
Aug 30 17:18:48 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 02 15:33:17 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 02 20:35:50 gromi gromox-http[1938]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
-- Boot 0f8e025cf0f3409095303d6a156f3aad --
Sep 03 08:48:25 gromi gromox-http[1929]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 03 12:09:33 gromi gromox-http[1929]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 03 15:30:57 gromi gromox-http[1929]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 03 17:44:18 gromi gromox-http[1929]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 04 03:56:42 gromi gromox-http[1929]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
-- Boot 8361a95004e546029215bd558fc079d4 --
Sep 04 14:35:04 gromi gromox-http[1924]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 04 15:03:22 gromi gromox-http[1924]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 04 16:29:39 gromi gromox-http[1924]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
Sep 04 20:32:23 gromi gromox-http[1924]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 06 16:47:13 gromi gromox-http[1924]: sqlite3_exec(/maildir/user/2/3/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": cannot start a transaction within a transaction (1)
Sep 07 11:54:32 gromi gromox-http[1924]: sqlite3_exec(/maildir/user/0/1/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5)
-- Boot fbc5fbee807445d2ba448708b11de217 --

crpb

I don't know if it is helpful at all.. but it didn't hurt here to run the following

for mbx in /var/lib/gromox/user/*/*/exmdb/exchange.sqlite3 ; do gromox-mbck $mbx ; done

This will only show problems if it can find any and you have to change the command to apply the fixes. So it's safe.

MichaelH

hi,

it found 165 problems. In a second run i add "-p" to fix the problem. Now there are no Problems.

mail01:~ # for mbx in /var/lib/gromox/user/*/*/exmdb/exchange.sqlite3 ; do gromox-mbck $mbx ; done NOTE: This utility may be integrated into gromox-mbop before the end of the development phase. Expect the command "gromox-mbck" to go away. == /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3 == ck_allocated_eids: f261 f262 f263 f264 f265 f266 f267 f268 f269 f270 f271 f272 f273 f274 f275 f276 f277 f278 f279 [19 issues] [fixed] ck_indices_present: /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3: 19 problems total NOTE: This utility may be integrated into gromox-mbop before the end of the development phase. Expect the command "gromox-mbck" to go away. == /var/lib/gromox/user/1/0/exmdb/exchange.sqlite3 == ck_allocated_eids: f261 f262 [2 issues] [fixed] ck_indices_present: /var/lib/gromox/user/1/0/exmdb/exchange.sqlite3: 2 problems total NOTE: This utility may be integrated into gromox-mbop before the end of the development phase. Expect the command "gromox-mbck" to go away. == /var/lib/gromox/user/1/1/exmdb/exchange.sqlite3 == ck_allocated_eids: f261 f262 [2 issues] [fixed] ck_indices_present: /var/lib/gromox/user/1/1/exmdb/exchange.sqlite3: 2 problems total NOTE: This utility may be integrated into gromox-mbop before the end of the development phase. Expect the command "gromox-mbck" to go away. == /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 == ck_allocated_eids: f257 f258 f291 f292 f293 f294 f297 f298 f299 f300 f301 f302 f316 f317 f318 f319 f320 f321 f322 f325 f326 f327 f330 f331 f332 f333 f334 f335 f336 f337 f338 f339 f340 f341 f350 f351 f353 f355 f356 f357 f358 f359 f360 f361 f362 f363 f364 f365 f366 f367 f368 f369 f370 f372 f373 f374 f375 f376 f377 f378 f379 f380 f381 f382 f383 f384 f385 f386 f387 f389 f393 f394 f395 f396 f397 f398 f399 f400 f401 f402 f403 f405 f410 f422 f423 f424 f425 f426 f427 f428 f429 f430 f431 f432 f433 f434 f435 f436 f437 f438 f439 f440 f441 f442 f456 f457 f461 f463 f464 f465 f466 f467 f469 f472 f534 f537 f548 f549 f566 f567 f568 f569 f570 f571 f572 f573 f574 f575 f576 f577 f578 f579 f580 f581 f582 f583 f584 f585 f586 f587 f588 f589 f590 f591 f592 f593 f594 f597 f598 f599 f600 f601 f602 f607 f608 f609 f610 f611 f612 m2196081 m2719298 m2915906 m3122514 m3319122 m3480194 [165 issues] [fixed] ck_indices_present: /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: 165 problems total mail01:~ #

MichaelH

Hi,

the error has just returned, here are the issues.

ep 09 16:42:23 mail01 gromox-http[21054]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5) Sep 09 16:42:23 mail01 gromox-http[21054]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown Sep 09 16:42:40 mail01 gromox-http[21054]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5) Sep 09 16:42:40 mail01 gromox-http[21054]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown Sep 09 16:43:05 mail01 gromox-http[21054]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5) Sep 09 16:43:05 mail01 gromox-http[21054]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown Sep 09 16:44:15 mail01 gromox-http[21054]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5) Sep 09 16:44:15 mail01 gromox-http[21054]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown Sep 09 16:44:23 mail01 gromox-http[21054]: sqlite3_exec(/var/lib/gromox/user/3/0/exmdb/exchange.sqlite3) "BEGIN IMMEDIATE": database is locked (5) Sep 09 16:44:23 mail01 gromox-http[21054]: sqlite_busy on /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3: write txn held by unknown mail01:~ # lsof /var/lib/gromox/user/*/*/exmdb/exchange.sqlite* COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME http 21054 gromox mem-w REG 254,0 32768 9303428 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-shm http 21054 gromox mem-r REG 254,0 32768 367112258 /var/lib/gromox/user/1/1/exmdb/exchange.sqlite3-shm http 21054 gromox mem-r REG 254,0 32768 1065361727 /var/lib/gromox/user/1/0/exmdb/exchange.sqlite3-shm http 21054 gromox mem-r REG 254,0 32768 507511546 /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3-shm http 21054 gromox 19ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 29ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 31uw REG 254,0 32768 9303428 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-shm http 21054 gromox 38ur REG 254,0 16711680 1066426726 /var/lib/gromox/user/1/0/exmdb/exchange.sqlite3 http 21054 gromox 44u REG 254,0 0 1065361726 /var/lib/gromox/user/1/0/exmdb/exchange.sqlite3-wal http 21054 gromox 45u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal http 21054 gromox 46ur REG 254,0 32768 1065361727 /var/lib/gromox/user/1/0/exmdb/exchange.sqlite3-shm http 21054 gromox 48ur REG 254,0 6762496 507511536 /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3 http 21054 gromox 49u REG 254,0 4309552 507511507 /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3-wal http 21054 gromox 50ur REG 254,0 32768 507511546 /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3-shm http 21054 gromox 53ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 59u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal http 21054 gromox 60u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal http 21054 gromox 61ur REG 254,0 36610048 367632735 /var/lib/gromox/user/1/1/exmdb/exchange.sqlite3 http 21054 gromox 62u REG 254,0 0 367112257 /var/lib/gromox/user/1/1/exmdb/exchange.sqlite3-wal http 21054 gromox 66ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 67ur REG 254,0 32768 367112258 /var/lib/gromox/user/1/1/exmdb/exchange.sqlite3-shm http 21054 gromox 74ur REG 254,0 6762496 507511536 /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3 http 21054 gromox 76u REG 254,0 4309552 507511507 /var/lib/gromox/user/0/2/exmdb/exchange.sqlite3-wal http 21054 gromox 79ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 82u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal http 21054 gromox 91u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal http 21054 gromox 93ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 94u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal http 21054 gromox 98ur REG 254,0 4015550464 9716483 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3 http 21054 gromox 99u REG 254,0 6324232 9711684 /var/lib/gromox/user/3/0/exmdb/exchange.sqlite3-wal mail01:~ #

WalterH

For: /var/lib/gromox/user/3/0/ is there anything special for this mailbox?

To find the mail address, use:
grommunio-admin user query username maildir | grep "/3/0"

MichaelH

Hi,

this mailbox has a big size 35Gb and 14 Alias Names.
This is the only special for this mailbox.
All other Mailboxes are round 1Gb big, and they have no Aliases.

greets
Michael

WalterH

35GB is not so big, I have seen mailboxes with 70GB without problems. Aliases are processed by Postfix not grommunio.

Is the volume where the mailboxes are located a SSD volume? SSD is essential for speed.

MichaelH

It is located on a SSD volume.

The System self is a VPS Server with 6x vCPU and 16GB RAM.

MichaelH

Hello,
I have now checked the mailbox more closely. It is actually only 1.8Gb in size.
The rest were deleted e-mails that were no longer in the recycle bin, but had not yet been completely deleted.

I have now deleted the mails in several small steps with

for i in /var/lib/gromox/user/*/*; do /usr/sbin/gromox-mbop -d "$i" purge-softdelete -r / -p 1200d ; done
for i in /var/lib/gromox/user/*/*; do /usr/sbin/gromox-mbop -d "$i" purge-datafiles; done
cleaned

I then made the “-p” option shorter and shorter, finally to 30 days.