Re: Writing an custom imap command
> On 04/05/2021 16:42 Ryan Beethe wrote: > > > On Mon, May 03, 2021 at 09:14:13AM +0300, Aki Tuomi wrote: > > > > > On 01/05/2021 18:32 Ryan Beethe wrote: > > > > > > 1. Why does cmd-idle.c sometimes call client_command_free()? But > > > sometimes it doesn't? > > > > > > For example, cmd_idle_continue() frees it in some branches but not > > > others. That makes no sense to me; it seems like it should be based > > > on your entrypoint (mailbox notify callback vs input callback vs > > > timeout callback), not based on which branch of logic within that > > > entrypoint. > > > > > > 2. Why does cmd-idle.c ever call client_destroy()? That seems like > > > something that should be invoked only by the imap process, not by any > > > command. > > > > > > It calls it in cmd-idle.c:idle_callback (which is a mailbox notify > > > callback). It invokes it after idle_sync_now() when it detects that > > > client->disconnected is set. Maybe that happens in imap_sync_init() > > > or something? > > > > > > 3. Why does cmd-idle.c ever call client_disconnect()? That also seems > > > like the responsibility of the imap process, and not any command. > > > > > > idle_client_input_more() detects when i_stream_read returns -1, > > > meaning that the client has *already disconnected*. Then it calls > > > client_disconnect(). > > > > > > I think this is the crazy part... the istream is effectively unique > > > to the imap process, so it seems unreasonable that any command is > > > responsible for cleaning it up; it should just always happen at the > > > imap process level before exiting, right? > > > > > > > IDLE cmd can be sometimes delegated to a separate worker called > > imap-hibernate, in which case the connection is moved to another process. > > This explains about all your questions. > > Wait, but then why does APPEND also make each of these calls? APPEND > can't be hibernated, as far as I can tell? > Because APPEND might need to read quite a lot of data from the client. > > > 4. What does client_continue_pending_input() actually do, and under > > > what conditions does it need to be called? > > > > It means that you did not consume all the input there was. > > Ok, reading over the code now with this understanding makes a lot of > sense, thank you. > > > You probably shold look some much more simple commands as insipiration. Try > > looking e.g. how cmd_id is implemented instead. > > I implemented a simpler command as well, but because it was simple I > didn't have any questions :) > > Unfortunately I do need a long-running command more like IDLE as well. > > Ryan What kind of "long running command" did you have in mind? Aki
huge mdbox broken / Log synchronization error
Hi, its the second time in 6 Month i have issues with a huge mdbox. It broken in November and i restored from backup because force-resync twice didnt fix it. (And restore from borg-backup was MUCH faster than force-resync) This time i have heavy delivery into that mailbox (postfix concurrency 1) and i tried merging folders with doveadm move. The move froze and now i seem to have a broken mdbox: Errors are: May 05 10:21:09 lda(in...@wasteland.rfc822.org): Error: Log synchronization error at seq=2736,offset=135540 for /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index: Extension record inc drops number below zero (uid=7757856, diff=-1, orig=0) trying root@pax:~# doveadm -D -v force-resync -u in...@wasteland.rfc822.org \* now. Although this will mostly likely take 8-10 hours. Mailbox is 44GByte (Compressed mdbox) and 220K folders. This is dovecot on Debian/Stretch dovecot-core1:2.2.27-3+deb9u7 dovecot-imapd 1:2.2.27-3+deb9u7 dovecot-ldap1:2.2.27-3+deb9u7 dovecot-managesieved1:2.2.27-3+deb9u7 dovecot-pop3d 1:2.2.27-3+deb9u7 dovecot-sieve 1:2.2.27-3+deb9u7 dovecot-solr1:2.2.27-3+deb9u7 Flo -- Florian Lohoff f...@zz.de Any sufficiently advanced technology is indistinguishable from magic. signature.asc Description: PGP signature
Re: huge mdbox broken / Log synchronization error
> On 05/05/2021 12:42 Florian Lohoff wrote: > > > Hi, > its the second time in 6 Month i have issues with a huge mdbox. It > broken in November and i restored from backup because force-resync > twice didnt fix it. (And restore from borg-backup was MUCH faster > than force-resync) > > This time i have heavy delivery into that mailbox (postfix concurrency 1) > and i tried merging folders with doveadm move. The move froze and now > i seem to have a broken mdbox: > > Errors are: > > May 05 10:21:09 lda(in...@wasteland.rfc822.org): Error: Log > synchronization error at seq=2736,offset=135540 for > /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index: > Extension record inc drops number below zero (uid=7757856, diff=-1, > orig=0) > > trying > > root@pax:~# doveadm -D -v force-resync -u in...@wasteland.rfc822.org \* > > now. Although this will mostly likely take 8-10 hours. > > Mailbox is 44GByte (Compressed mdbox) and 220K folders. > > This is dovecot on Debian/Stretch > > dovecot-core1:2.2.27-3+deb9u7 > dovecot-imapd 1:2.2.27-3+deb9u7 > dovecot-ldap1:2.2.27-3+deb9u7 > dovecot-managesieved1:2.2.27-3+deb9u7 > dovecot-pop3d 1:2.2.27-3+deb9u7 > dovecot-sieve 1:2.2.27-3+deb9u7 > dovecot-solr1:2.2.27-3+deb9u7 > > Flo > -- > Florian Lohoff f...@zz.de >Any sufficiently advanced technology is indistinguishable from magic. Hi! That version is pretty old already, there has been fixes to mdbox format after that. Can you at least try to upgrade to 2.2.36? Aki
Dovecot v2.3.13 reporting (very) incorrect vsize for some maildir folders
Hello!
Dovecot v2.3.13. Full, but anonymized, `doveconf -n` attached.
We are in the process of migrating maildir-backed users from filesystem quotes,
to using dovecot's "count" quota backend.
This is not reflected in the doveconf output because we're overriding `quota`,
`quota_rule` and `quota_vsizes` in userdb:
{"quota":"count:User quota","quota_rule":"*:storage=15G","quota_vsizes":"yes"}
Afterwards, for a couple users, we received reports that mail delivery had
failed because they were over quota. When looking into it for a specific user,
we noticed that the vsize reported for a particular folder (with 47k messages)
was reported as being nearly 50 times larger than it's on-disk size:
root@mail02:~# doveadm mailbox status -u anonymized_user 'messages recent
unseen vsize' 'anonymized/folder/name'
[...]
anonymized/folder/name messages=47338 recent=0 unseen=0 vsize=14335366070
However, the filesystem itself reports a much smaller size (but correct message
count):
root@mail02:~# du -hd1 /home/anonymized_user/Maildir/.anonymized.folder.name/
313M/home/anonymized_user/Maildir/.anonymized.folder.name/cur
36K /home/anonymized_user/Maildir/.anonymized.folder.name/tmp
4.0K/home/anonymized_user/Maildir/.anonymized.folder.name/new
320M/home/anonymized_user/Maildir/.anonymized.folder.name/
root@mail02:~# ls /home/anonymized_user/Maildir/.anonymized.folder.name/cur |
wc -l
47338
I have tried:
- `doveadm force-resync -u anonymized_user`
- deleting the index files in the specific folder, and running `doveadm index
-u anonymized_user '*'` as well as `doveadm mailbox status -u anonymized_user
vsize '*'`
- deleting all `*index*` files in maildir, and running `doveadm index -u
anonymized_user '*'` as well as `doveadm mailbox status -u anonymized_user
vsize '*'`
- comparing all maildir-sizes (S=) with their actual sizes to see if there
are discrepancies. There are none.
- regardless of the above, set `maildir_broken_filename_sizes = yes`, deleted
indexes and reindexed.
Even after deleting the list index (dovecot.list.index) as well as the mailbox
indexes, recalculating the vsize seems very quick so I feel like the incorrect
vsize is being fetched from a cache somewhere instead of being recalculated..?
Any idea what is causing dovecot to report this wildly incorrect mailbox size?
Are there any other files (not matching `*index*`) that are responsible? I'd
rather not touch the user's control files, for obvious reasons.
On a side note: We're also experiencing some issues with
`mail_vsize_bg_after_count`. It seems to work correctly by returning a
temporary error and deferring to a background job, but the indexer-worker job
often times never appears to start (or do anything) at all:
dovecot 29622 0.0 0.0 4120 1124 ?S15:22 0:00
dovecot/indexer [0 clients, 0 requests]
266248 29623 0.0 0.0 6008 4604 ?S15:22 0:00
dovecot/indexer-worker [idling]
Waiting a while, and attempting to refetch the quota returns the same temperror
with no indexer-worker being started. However, this is a separate issue from
the above and can be ignored for now.
Best regards,
Eirik Rye
# 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.13 (cdd19fe3)
# OS: Linux 4.19.0-14-amd64 x86_64 Debian 10.8
debug_log_path = /var/log/dovecot.log
default_vsz_limit = 768 M
disable_plaintext_auth = no
imap_id_log = *
info_log_path = /var/log/dovecot.log
lmtp_add_received_header = no
lmtp_hdr_delivery_address = none
log_path = /var/log/dovecot.err
log_timestamp = "%FT%T%z "
login_greeting = %{hostname} ready.
login_log_format_elements = user=<%u> orig=<%{orig_user}> method=%m proto=%s
rip=%r lip=%l session=<%{session}> %c %k
mail_fsync = always
mail_location = maildir:~/Maildir
mail_nfs_index = yes
mail_nfs_storage = yes
mail_plugins = quota
mail_vsize_bg_after_count = 500
maildir_broken_filename_sizes = yes
managesieve_sieve_capability = fileinto envelope encoded-character subaddress
comparator-i;ascii-numeric relational regex imap4flags copy include variables
body environment mailbox date index ihave duplicate mime foreverypart
extracttext
mmap_disable = yes
namespace inbox {
inbox = yes
location =
mailbox Drafts {
auto = subscribe
special_use = \Drafts
}
mailbox Sent {
auto = subscribe
special_use = \Sent
}
mailbox "Sent Messages" {
auto = no
special_use = \Sent
}
mailbox Spam {
auto = create
special_use = \Junk
}
mailbox Trash {
auto = subscribe
special_use = \Trash
}
prefix =
separator = /
}
passdb {
args = /etc/dovecot/dovecot-redis-alias.conf.ext
driver = dict
name = redis-alias
override_fields = noauthenticate
username_filter = *@*
}
passdb {
args = /etc/dovecot/dovecot-redis-deny.conf.ext
deny = yes
driver = dict
name = redis-deny
}
passdb {
args = /etc/dovecot/dovecot-redis.conf.ext
auth_verbose = yes
driver = dict
name = redis-auth
}
plug
Re: Writing an custom imap command
On Wed, May 05, 2021 at 10:53:30AM +0300, Aki Tuomi wrote: > > > On 04/05/2021 16:42 Ryan Beethe wrote: > > > > > > On Mon, May 03, 2021 at 09:14:13AM +0300, Aki Tuomi wrote: > > > > > > > On 01/05/2021 18:32 Ryan Beethe wrote: > > > > > > > > 1. Why does cmd-idle.c sometimes call client_command_free()? But > > > > sometimes it doesn't? > > > > > > > > For example, cmd_idle_continue() frees it in some branches but not > > > > others. That makes no sense to me; it seems like it should be based > > > > on your entrypoint (mailbox notify callback vs input callback vs > > > > timeout callback), not based on which branch of logic within that > > > > entrypoint. > > > > > > > > 2. Why does cmd-idle.c ever call client_destroy()? That seems like > > > > something that should be invoked only by the imap process, not by any > > > > command. > > > > > > > > It calls it in cmd-idle.c:idle_callback (which is a mailbox notify > > > > callback). It invokes it after idle_sync_now() when it detects that > > > > client->disconnected is set. Maybe that happens in imap_sync_init() > > > > or something? > > > > > > > > 3. Why does cmd-idle.c ever call client_disconnect()? That also seems > > > > like the responsibility of the imap process, and not any command. > > > > > > > > idle_client_input_more() detects when i_stream_read returns -1, > > > > meaning that the client has *already disconnected*. Then it calls > > > > client_disconnect(). > > > > > > > > I think this is the crazy part... the istream is effectively unique > > > > to the imap process, so it seems unreasonable that any command is > > > > responsible for cleaning it up; it should just always happen at the > > > > imap process level before exiting, right? > > > > > > > > > > IDLE cmd can be sometimes delegated to a separate worker called > > > imap-hibernate, in which case the connection is moved to another process. > > > This explains about all your questions. > > > > Wait, but then why does APPEND also make each of these calls? APPEND > > can't be hibernated, as far as I can tell? > > > > Because APPEND might need to read quite a lot of data from the client. So then I am back at my original questions. Maybe I can guess at some answers and you can tell me if I'm understanding correctly: 1. Why does cmd-idle.c sometimes call client_command_free()? But sometimes it doesn't? Earlier I said I though cmd_idle_continue() freed it in some branches but not others, but I think I was mistaken. It looks like the only path where client_command_free is called is inside an io_add_istream callback. That makes sense, and I can do the same thing with my command. 2. Why does cmd-idle.c ever call client_destroy()? That seems like something that should be invoked only by the imap process, not by any command. This is only ever triggered by idle_callback, which is a mailbox_notify_changes callback, which I don't have to interact with, so maybe I can ignore this. 3. Why does cmd-idle.c ever call client_disconnect()? That also seems like the responsibility of the imap process, and not any command. While I'm still not sure why the imap process is not responsible for calling this, it does seem like it only gets called when i_stream_read() returns -1, and I can probably immitate that without much risk. But wait, why does cmd-idle.c call client_disconnect() when i_stream_read() returns -1, but cmd-append.c calls client_command_free() and client_destroy() but not client_disconnect()? > > > You probably shold look some much more simple commands as > > > insipiration. Try looking e.g. how cmd_id is implemented instead. > > > > I implemented a simpler command as well, but because it was simple I > > didn't have any questions :) > > > > Unfortunately I do need a long-running command more like IDLE as well. > > What kind of "long running command" did you have in mind? My email service offers a layer of encryption which is not transparent to IMAP, and where the keys are created and kept on each client device. Since IMAP synchronization is bidirectional, each client needs to encrypt uploaded messages to all known client devices. Thus, clients need a way update their list of all known keys. So the command is roughly: tag XKEYSYNC [known_fingerprint ...] ... DONE And the responses are rougly: * XKEYSYNC DELETED fingerprint * XKEYSYNC CREATED public_key The full source can be found at: github.com/splintermail/splintermail-client/blob/dev/server/xkeysync.c Ryan
Re: Writing an custom imap command
> On 05/05/2021 18:28 Ryan Beethe wrote: > > > On Wed, May 05, 2021 at 10:53:30AM +0300, Aki Tuomi wrote: > > > > > On 04/05/2021 16:42 Ryan Beethe wrote: > > > > > > > > > On Mon, May 03, 2021 at 09:14:13AM +0300, Aki Tuomi wrote: > > > > > > > > > On 01/05/2021 18:32 Ryan Beethe wrote: > > > > > > > > > > 1. Why does cmd-idle.c sometimes call client_command_free()? But > > > > > sometimes it doesn't? > > > > > > > > > > For example, cmd_idle_continue() frees it in some branches but not > > > > > others. That makes no sense to me; it seems like it should be > > > > > based > > > > > on your entrypoint (mailbox notify callback vs input callback vs > > > > > timeout callback), not based on which branch of logic within that > > > > > entrypoint. > > > > > > > > > > 2. Why does cmd-idle.c ever call client_destroy()? That seems like > > > > > something that should be invoked only by the imap process, not by any > > > > > command. > > > > > > > > > > It calls it in cmd-idle.c:idle_callback (which is a mailbox notify > > > > > callback). It invokes it after idle_sync_now() when it detects > > > > > that > > > > > client->disconnected is set. Maybe that happens in > > > > > imap_sync_init() > > > > > or something? > > > > > > > > > > 3. Why does cmd-idle.c ever call client_disconnect()? That also seems > > > > > like the responsibility of the imap process, and not any command. > > > > > > > > > > idle_client_input_more() detects when i_stream_read returns -1, > > > > > meaning that the client has *already disconnected*. Then it calls > > > > > client_disconnect(). > > > > > > > > > > I think this is the crazy part... the istream is effectively > > > > > unique > > > > > to the imap process, so it seems unreasonable that any command is > > > > > responsible for cleaning it up; it should just always happen at > > > > > the > > > > > imap process level before exiting, right? > > > > > > > > > > > > > IDLE cmd can be sometimes delegated to a separate worker called > > > > imap-hibernate, in which case the connection is moved to another > > > > process. This explains about all your questions. > > > > > > Wait, but then why does APPEND also make each of these calls? APPEND > > > can't be hibernated, as far as I can tell? > > > > > > > Because APPEND might need to read quite a lot of data from the client. > > So then I am back at my original questions. Maybe I can guess at some > answers and you can tell me if I'm understanding correctly: > > 1. Why does cmd-idle.c sometimes call client_command_free()? But > sometimes it doesn't? > > Earlier I said I though cmd_idle_continue() freed it in some > branches but not others, but I think I was mistaken. It looks > like the only path where client_command_free is called is inside > an io_add_istream callback. That makes sense, and I can do the > same thing with my command. > > 2. Why does cmd-idle.c ever call client_destroy()? That seems like > something that should be invoked only by the imap process, not by > any command. > > This is only ever triggered by idle_callback, which is a > mailbox_notify_changes callback, which I don't have to interact > with, so maybe I can ignore this. > > 3. Why does cmd-idle.c ever call client_disconnect()? That also > seems like the responsibility of the imap process, and not any > command. > > While I'm still not sure why the imap process is not responsible > for calling this, it does seem like it only gets called when > i_stream_read() returns -1, and I can probably immitate that > without much risk. > > But wait, why does cmd-idle.c call client_disconnect() when > i_stream_read() returns -1, but cmd-append.c calls > client_command_free() and client_destroy() but not > client_disconnect()? > > > > > You probably shold look some much more simple commands as > > > > insipiration. Try looking e.g. how cmd_id is implemented instead. > > > > > > I implemented a simpler command as well, but because it was simple I > > > didn't have any questions :) > > > > > > Unfortunately I do need a long-running command more like IDLE as well. > > > > What kind of "long running command" did you have in mind? > > My email service offers a layer of encryption which is not transparent > to IMAP, and where the keys are created and kept on each client device. > Since IMAP synchronization is bidirectional, each client needs to > encrypt uploaded messages to all known client devices. Thus, clients > need a way update their list of all known keys. > > So the command is roughly: > > tag XKEYSYNC [known_fingerprint ...] > ... > DONE > > And the responses are rougly: > > * XKEYSYNC DELETED fingerprint > > * XKEYSYNC CREATED public_key > > The full source can be found at: > > github.com/s
Re: huge mdbox broken / Log synchronization error
On Wed, May 05, 2021 at 03:30:39PM +0300, Aki Tuomi wrote: > Hi! > > That version is pretty old already, there has been fixes to mdbox format > after that. Can you at least try to upgrade to 2.2.36? Aborted force-resync after 16 hours - Every fsck took 2-3 hours. It always restarted from the beginning it seems. Numbers for the inconsistency changed from run to run. [ ... ] doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 10337 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,811812) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,811828) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 9959 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,863376) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,970728) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes I upgraded to 2.3.4 from stretch-backports now and rerunning force-fsck now. Flo -- Florian Lohoff f...@zz.de Any sufficiently advanced technology is indistinguishable from magic. signature.asc Description: PGP signature
Re: huge mdbox broken / Log synchronization error
> On 06/05/2021 09:54 Florian Lohoff wrote: > > > On Wed, May 05, 2021 at 03:30:39PM +0300, Aki Tuomi wrote: > > Hi! > > > > That version is pretty old already, there has been fixes to mdbox format > > after that. Can you at least try to upgrade to 2.2.36? > > Aborted force-resync after 16 hours - Every fsck took 2-3 hours. It > always restarted from the beginning it seems. Numbers for the > inconsistency changed from run to run. > > [ ... ] > doveadm(inbox@wasteland): Warning: Transaction log file > /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for > 10337 seconds (mdbox storage rebuild) > doveadm(inbox@wasteland): Warning: mdbox > /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index > (2736,135512 != 2736,811812) > doveadm(inbox@wasteland): Warning: fscking index file > /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index > doveadm(inbox@wasteland): Warning: mdbox > /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index > (2736,135512 != 2736,811828) > doveadm(inbox@wasteland): Warning: fscking index file > /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index > doveadm(inbox@wasteland): Warning: mdbox > /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes > doveadm(inbox@wasteland): Warning: Transaction log file > /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for > 9959 seconds (mdbox storage rebuild) > doveadm(inbox@wasteland): Warning: mdbox > /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index > (2736,135512 != 2736,863376) > doveadm(inbox@wasteland): Warning: fscking index file > /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index > doveadm(inbox@wasteland): Warning: mdbox > /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index > (2736,135512 != 2736,970728) > doveadm(inbox@wasteland): Warning: fscking index file > /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index > doveadm(inbox@wasteland): Warning: mdbox > /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes > > I upgraded to 2.3.4 from stretch-backports now and rerunning force-fsck now. > > Flo > -- > Florian Lohoff f...@zz.de > Any sufficiently advanced technology is indistinguishable from magic. This seems to indicate that there is some larger corruption in your mdbox files. I'm afraid it might mean that you need to rm the dovecot.map.index* files and force-resync then. AKi
