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@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 =
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@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@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@scasl.ca 2024-08-05T06:33:18.787098-07:00 football dovecot: auth: Debug: sql(scasl@scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Finished passdb lookup 2024-08-05T06:33:18.787239-07:00 football dovecot: auth: Debug: auth(scasl@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@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@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@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@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@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@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@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@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@scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug: open(/proc/self/io) failed: Permission denied 2024-08-05T06:33:18.798021-07:00 football dovecot: imap(scasl@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@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@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