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 = postmas...@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 ->
sc...@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(sc...@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 ->
sc...@scasl.ca
2024-08-05T06:33:18.787098-07:00 football dovecot: auth: Debug:
sql(sc...@scasl.ca,209.121.143.14,<Z41TuO8eENjReY8O>): Finished passdb
lookup
2024-08-05T06:33:18.787239-07:00 football dovecot: auth: Debug:
auth(sc...@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=sc...@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(sc...@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(sc...@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(sc...@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(sc...@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(sc...@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#011sc...@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=<sc...@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(sc...@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(sc...@scasl.ca)<24849><Z41TuO8eENjReY8O>: Debug:
open(/proc/self/io) failed: Permission denied
2024-08-05T06:33:18.798021-07:00 football dovecot:
imap(sc...@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(sc...@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(sc...@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
_______________________________________________
dovecot mailing list -- dovecot@dovecot.org
To unsubscribe send an email to dovecot-le...@dovecot.org
