August 2024 - dovecot

Userdb empty
by Cam Ellison 08 Aug '24

08 Aug '24

I have shifted from a system-based email system to virtual for a website I manage. The MTA is exim4, and user data are in a MySQL database. It will receive email, but with one exception the userdb is empty and emails go out with no username in the email address. Sample error message from exim: 2024-08-05 05:21:43 1sawid-00065N-0R Error while reading message with no usable sender address (R=1sawiX-00065C-1a): at least one malformed recipient address: @scasl.ca - no local part Here is the output of doveconf -n: # 2.3.19.1 (9b53102964): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.19 (4eae2f79) # OS: Linux 6.1.0-20-rt-686-pae i686 Debian 12.6 ext4 # Hostname: football.scasl.ca auth_debug = yes auth_default_realm = scasl.ca auth_mechanisms = plain login auth_username_format = %Ln auth_verbose = yes base_dir = /var/run/dovecot/ hostname = scasl.ca login_trusted_networks = 209.121.143.10/32 mail_debug = yes mail_gid = vmail mail_home = /var/vmail/%n mail_location = maildir:/var/vmail/%n/Maildir:INBOX=/var/vmail/%n/Maildir/INBOX mail_privileged_group = vmail mail_uid = vmail namespace inbox { inbox = yes location = mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = separator = / } passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } postmaster_address = postmaster(a)scasl.ca protocols = " imap" service auth { unix_listener auth-client { mode = 0666 } unix_listener auth-userdb { mode = 0666 } } service imap-login { service_count = 1 } service stats { unix_listener stats-reader { group = vmail mode = 0666 } unix_listener stats-writer { group = vmail mode = 0666 } } ssl_cert = </etc/dovecot/private/dovecot.pem ssl_client_ca_dir = /etc/ssl/certs ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it userdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } userdb { driver = passwd } There are two userdb entries, since one of the users is a system user. It is also the only one that appears in userdb. The relevant commands from dovecot-sql.conf.ext are here: password_query = SELECT email_username AS username, domain, email_password AS password FROM league WHERE email_username = '%n' user_query = SELECT CONCAT('/var/vmail/',email_username) AS home, 5000 AS uid, 5000 AS gid FROM league WHERE email_username = '%n' AND domain = '%d' iterate_query = SELECT email_username AS username, domain FROM league The vmail uid:gid is 5000:5000 As a side issue, it cannot open (/proc/self/io) - I'm not sure whether that means anything. Here is debugging output: 2024-08-05T06:33:18.777211-07:00 football dovecot: auth-worker(24847): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth 2024-08-05T06:33:18.777456-07:00 football dovecot: auth-worker(24847): Debug: Module loaded: /usr/lib/dovecot/modules/auth/lib20_auth_var_expand_crypt.so 2024-08-05T06:33:18.782112-07:00 football dovecot: auth-worker(24847): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so 2024-08-05T06:33:18.782392-07:00 football dovecot: auth-worker(24847): Debug: sqlpool(mysql): Creating new connection 2024-08-05T06:33:18.784671-07:00 football dovecot: auth-worker(24847): Debug: mysql(localhost): Connecting 2024-08-05T06:33:18.785532-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): Server accepted connection (fd=14) 2024-08-05T06:33:18.785703-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): Sending version handshake 2024-08-05T06:33:18.785850-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<1>: Handling PASSV request 2024-08-05T06:33:18.785986-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<1>: sql(scasl,209.121.143.14,<Z41TuO8eENjReY8O>): Performing passdb lookup 2024-08-05T06:33:18.786124-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<1>: sql(scasl,209.121.143.14,<Z41TuO8eENjReY8O>): query: SELECT email_username AS username, domain, emai l_password AS password FROM league WHERE email_username = 'scasl' 2024-08-05T06:33:18.786347-07:00 football dovecot: auth-worker(24847): Debug: mysql(localhost): Finished query 'SELECT email_username AS username, domain, email_password AS password FROM league WHERE email_username = 'scasl'' in 0 msecs 2024-08-05T06:33:18.786524-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<1>: sql(scasl,209.121.143.14,<Z41TuO8eENjReY8O>): username changed scasl -> scasl(a)scasl.ca 2024-08-05T06:33:18.786672-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<1>: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Finished passdb lookup 2024-08-05T06:33:18.786791-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<1>: Finished 2024-08-05T06:33:18.786940-07:00 football dovecot: auth: Debug: sql(scasl,209.121.143.14,<Z41TuO8eENjReY8O>): username changed scasl -> scasl(a)scasl.ca 2024-08-05T06:33:18.787098-07:00 football dovecot: auth: Debug: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Finished passdb lookup 2024-08-05T06:33:18.787239-07:00 football dovecot: auth: Debug: auth(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Auth request finished 2024-08-05T06:33:18.787379-07:00 football dovecot: auth: Debug: client passdb out: OK#0111#011user=scasl(a)scasl.ca#011#011original_user=scasl 2024-08-05T06:33:18.794297-07:00 football dovecot: auth: Debug: master in: REQUEST#011600309761#01124843#0111#0115343bacecb1c0282e3e40282e4ebd64d#011session_pid=24849#011request_auth_token 2024-08-05T06:33:18.794568-07:00 football dovecot: auth: Debug: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Performing userdb lookup 2024-08-05T06:33:18.794712-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<2>: Handling USER request 2024-08-05T06:33:18.794859-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<2>: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Performing userdb lookup 2024-08-05T06:33:18.795004-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<2>: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): SELECT CONCAT('/var/vmail/',email_username) A S home, 5000 AS uid, 5000 AS gid FROM league WHERE email_username = 'scasl' AND domain = 'scasl.ca' 2024-08-05T06:33:18.795222-07:00 football dovecot: auth-worker(24847): Debug: mysql(localhost): Finished query 'SELECT CONCAT('/var/vmail/',email_username) AS home, 5000 AS uid, 5000 AS gid FROM league WHERE email_username = 'scasl' AND domain = 'scasl.ca'' in 0 msecs 2024-08-05T06:33:18.795387-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<2>: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Finished userdb lookup 2024-08-05T06:33:18.795526-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): auth-worker<2>: Finished 2024-08-05T06:33:18.795660-07:00 football dovecot: auth: Debug: sql(scasl(a)scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Finished userdb lookup 2024-08-05T06:33:18.795899-07:00 football dovecot: auth: Debug: master userdb out: USER#011600309761#011scasl@scasl.ca#011home=/var/vmail/scasl#011uid=5000#011gid=5000#011auth_mech=PLAIN#011auth_token=e9d7425913886e014c83af029551e70f8db2 98f9#011auth_user=scasl 2024-08-05T06:33:18.796199-07:00 football dovecot: imap-login: Login: user=<scasl(a)scasl.ca>, method=PLAIN, rip=209.121.143.14, lip=209.121.143.10, mpid=24849, TLS, session=<Z41TuO8eENjReY8O> 2024-08-05T06:33:18.797562-07:00 football dovecot: imap(scasl(a)scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/scasl 2024-08-05T06:33:18.797718-07:00 football dovecot: imap(scasl(a)scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug: open(/proc/self/io) failed: Permission denied 2024-08-05T06:33:18.798021-07:00 football dovecot: imap(scasl(a)scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/scasl/M aildir:INBOX=/var/vmail/scasl/Maildir/INBOX 2024-08-05T06:33:18.798286-07:00 football dovecot: imap(scasl(a)scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug: maildir++: root=/var/vmail/scasl/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/scasl/Maildir/INBOX, alt= 2024-08-05T06:33:18.799780-07:00 football dovecot: imap(scasl(a)scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug: Mailbox INBOX: Mailbox opened 2024-08-05T06:34:18.830024-07:00 football dovecot: auth-worker(24847): Debug: conn unix:auth-worker (pid=24845,uid=121): Disconnected: Connection closed (fd=-1) 2024-08-05T06:34:18.882117-07:00 football dovecot: auth-worker(24847): Debug: mysql(localhost): Connection finished (queries=2, slow queries=0) 2024-08-05T06:34:19.349925-07:00 football dovecot: auth: Debug: mysql(localhost): Connection finished (queries=0, slow queries=0) Sorry this is so long. What am I doing wrong here? Thank you in advance Cam

2 2

username_filter settings in passdb
by zaxwat93＠gmail.com 06 Aug '24

06 Aug '24

got a problem when configured passdb with username_filter — looks like the option doesn't work OS: FreeBSD 13 and 14. Dovecot version: 2.3.21 Part of config: passdb { args = /usr/local/bin/php /usr/local/dovecot/bin/checkpassword.php driver = checkpassword } passdb { args = /usr/local/bin/php /usr/local/dovecot/bin/checkpassword.php driver = checkpassword username_filter = user1(a)postmaster.local.one default_fields = domain=local.one override_fields = user=postmaster(a)local.one } passdb { args = /usr/local/bin/php /usr/local/dovecot/bin/checkpassword.php driver = checkpassword username_filter = user3(a)user2.local.one default_fields = domain=local.one override_fields = user=user2(a)local.one } When I try command "doveadm auth test user1(a)postmaster.local.one" and enter a password of user1 — it works as planned — change user1(a)postmaster.local.one to user1(a)local.one check it's password and override user to postmaster(a)local.one But when I try "doveadm auth test user3(a)user2.local.one" — it also change user3(a)user2.local.one to user3(a)local.one, and after password check — override it to postmaster(a)local.one Debug logs, when I try "doveadm auth test user3(a)user2.local.one": Aug 1 11:01:03 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Aug 1 11:01:03 auth: Debug: Module loaded: /usr/local/lib/dovecot/auth/lib20_auth_var_expand_crypt.so Aug 1 11:01:03 auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat Aug 1 11:01:03 auth: Debug: passwd-file /usr/local/etc/dovecot.users.list:Read 7 users in 0 secs Aug 1 11:01:03 auth: Debug: auth client connected (pid=0) Aug 1 11:01:03 auth: Debug: client in: AUTH 1 PLAIN service=doveadm debug resp=<hidden> Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): Performing passdb lookup Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): execute: /usr/local/bin/php /usr/local/dovecot/bin/checkpassword.php /usr/local/libexec/dovecot/checkpassword-reply Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): Received input: Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): exit_status=1 Aug 1 11:01:03 auth: checkpassword(user3(a)user2.local.one): Login failed (status=1) Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): Finished passdb lookup Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): Performing passdb lookup Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)user2.local.one): username changed user3(a)user2.local.one -> user3(a)local.one Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)local.one): execute: /usr/local/bin/php /usr/local/dovecot/bin/checkpassword.php /usr/local/libexec/dovecot/checkpassword-reply Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)local.one): Received input: user=user3(a)local.one userdb_home=/var/spool/mail/ userdb_uid=dovecot userdb_gid=dovecot Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)local.one): exit_status=0 Aug 1 11:01:03 auth: Debug: checkpassword(user3(a)local.one): username changed user3(a)local.one -> postmaster(a)local.one Aug 1 11:01:03 auth: Debug: checkpassword(postmaster(a)local.one): Finished passdb lookup Aug 1 11:01:03 auth: Debug: auth(postmaster(a)local.one): Auth request finished Aug 1 11:01:03 auth: Debug: client passdb out: OK 1 user=postmaster(a)local.one original_user=user3(a)user2.local.one I've checked sources and find in " core/src/auth/auth-request.c (from line 617) " code that check username_filter and should send "skipping passdb: username filtered" message in debug, but it doesn't do it. Is it a bug or I've missed something in setup?

3 10

dsync crashing
by Benjamin Rose 05 Aug '24

05 Aug '24

Hello, I am running Dovecot 2.3.16 (7e2e900c1a) on RHEL 9.2. I attach my "doveconf -n" configuration. I have replication enabled between 2 servers, both very beefy with 16 cores of Intel(R) Xeon(R) Gold 6244 CPU @ 3.60GHz, 768gb memory, and 100-gig ethernet. The configs are the same except the replication part which points at each other via a puppet template. It seems to work well for most users on modern email clients using the mdbox storage format. The issue I'm having is that some of my users are on the old-style mbox storage format so they can use legacy mail readers such as pine and mutt natively. For some of these users, syncing works just fine. For others, right now about a dozen users, the sync never completes, and I get the following error & backtrace in /var/log/maillog: Aug 4 23:54:22 mail6 dovecot[1177530]: doveadm: Panic: file dsync-mailbox-import.c: line 2163 (dsync_mailbox_import_handle_mail): assertion failed: (array_count(&wanted_uids) > 0) Aug 4 23:54:22 mail6 dovecot[1177530]: doveadm: Error: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0(backtrace_append+0x46) [0x7fa6ab05c486] -> /usr/lib64/dovecot/libdovecot.so.0(backtrace_get+0x22) [0x7fa6ab05c5a2] -> /usr/lib64/dovecot/libdovecot.so.0(+0x10a41b) [0x7fa6ab06b41b] -> /usr/lib64/dovecot/libdovecot.so.0(+0x10a4b7) [0x7fa6ab06b4b7] -> /usr/lib64/dovecot/libdovecot.so.0(+0x5d11a) [0x7fa6aafbe11a] -> dovecot/doveadm-server(+0x24029) [0x56433f2f7029] -> dovecot/doveadm-server(dsync_mailbox_import_changes_finish+0x29c) [0x56433f32fb9c] -> dovecot/doveadm-server(dsync_brain_sync_mails+0x8d5) [0x56433f331f15] -> dovecot/doveadm-server(+0x52255) [0x56433f325255] -> dovecot/doveadm-server(+0x52639) [0x56433f325639] -> dovecot/doveadm-server(+0x5fa53) [0x56433f332a53] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x6d) [0x7fa6ab081cbd] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x13a) [0x7fa6ab083bba] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x54) [0x7fa6ab083c64] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x40) [0x7fa6ab083e20] -> dovecot/doveadm-server(+0x37d7c) [0x56433f30ad7c] -> dovecot/doveadm-server(+0x3974d) [0x56433f30c74d] -> dovecot/doveadm-server(+0x5020b) [0x56433f32320b] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x6d) [0x7fa6ab081cbd] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x13a) [0x7fa6ab083bba] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x54) [0x7fa6ab083c64] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x40) [0x7fa6ab083e20] -> /usr/lib64/dovecot/libdovecot.so.0(master_service_run+0x17) [0x7fa6aaff2337] -> dovecot/doveadm-server(main+0x102) [0x56433f2f8f92] -> /lib64/libc.so.6(+0x3feb0) [0x7fa6aac3feb0] -> /lib64/libc.so.6(__libc_start_main+0x80) [0x7fa6aac3ff60] -> dovecot/doveadm-server(_start+0x25) [0x56433f2f9015] Aug 4 23:54:22 mail6 dovecot[1177530]: doveadm: Fatal: master: service(doveadm): child 1117475 killed with signal 6 (core dumped) I'm not sure what might be causing this, and wanted to see if anyone here could offer any suggestions. Please let me know if any additional information is needed. Thanks, Ben

3 7

Strange ssl/dso troubles on freeBSD13.3
by Georg Graf 02 Aug '24

02 Aug '24

Hi, I'm George and I think I've been running dovecot for like more than a decade now without any troubles, so: WOW! Nevertheless, after an upgrade from FreeBSD 13.2 to 13.3 plus "pkg upgrade" my dovecot installation refuses to load the ssl certificates. I've tried a version built from source as well as the package. The Problem seems to be something with loading of DSO's: ========================================================================================================= Jul 31 16:42:11 murl dovecot[10801]: imap-login: Error: Failed to initialize SSL server context: Can't load SSL certificate (ssl_cert setting): error:25066067:DSO support routines:dlfcn_load:could not load the shared library: filename(libproviders.so): Shared object "libproviders.so" not found, required by "imap-login", error:25070067:DSO support routines:DSO_load:could not load the shared library, error:0E07506E:configuration file routines:module_load_dso:error loading dso: module=providers, path=providers, error:0E076071:configuration file routines:mo ========================================================================================================= I have never seen 'libproviders' and there's not a lot on it on the internet as well. Here comes my (dead-simple) 'dovecot -n': ========================================================================================================= # 2.3.21 (47349e2482): /usr/local/etc/dovecot/dovecot.conf # OS: FreeBSD 13.3-RELEASE-p4 amd64 # Hostname: murl.graf.priv.at auth_mechanisms = plain login disable_plaintext_auth = no mail_location = maildir:~/Maildir:LAYOUT=fs:INBOX=~/Maildir passdb { driver = pam } protocols = imap ssl_cert = </root/.acme.sh/graf.priv.at/fullchain.cer ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it userdb { args = blocking=yes driver = passwd } verbose_ssl = yes protocol imap { imap_client_workarounds = delay-newmail tb-extra-mailbox-sep } ========================================================================================================= My openssl s_client shows that the server hangs up (while producing the above log entry): ========================================================================================================= # openssl s_client -servername graf.priv.at -connect graf.priv.at:imaps CONNECTED(00000003) write:errno=0 --- no peer certificate available --- No client certificate CA names sent --- SSL handshake has read 0 bytes and written 314 bytes Verification: OK --- New, (NONE), Cipher is (NONE) Secure Renegotiation IS NOT supported Compression: NONE Expansion: NONE No ALPN negotiated Early data was not sent Verify return code: 0 (ok) --- ========================================================================================================= Just to mention: plaintext IMAP is still working: ========================================================================================================= # telnet graf.priv.at imap Trying 78.41.116.33... Connected to graf.priv.at. Escape character is '^]'. * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ STARTTLS AUTH=PLAIN AUTH=LOGIN] Dovecot ready. u login georg <mysupersecretpassword> u OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAM ESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY PREVIEW STATUS=SIZE SAVEDATE LITE RAL+ NOTIFY] Logged in r select INBOX * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded $MDNSent $label5 $label3) * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded $MDNSent $label5 $label3 \*)] Flags permitted. * 359 EXISTS * 0 RECENT * OK [UNSEEN 2] First unseen. * OK [UIDVALIDITY 1509040425] UIDs valid * OK [UIDNEXT 11767] Predicted next UID * OK [HIGHESTMODSEQ 19640] Highest r OK [READ-WRITE] Select completed (0.006 + 0.000 + 0.005 secs). s logout * BYE Logging out s OK Logout completed (0.001 + 0.000 secs). Connection closed by foreign host. ========================================================================================================= Any helping hint is highly appreciated! Thank you very much, George

2 3