Dovecot error
I checked my logs and was receiving an error that /etc/ssl/certs/dovecot.pem and /etc/ssl/private/dovecot.pem were both missing and after checking the directories I recreated the keys and resolved the error. The only remaining problem seems to be this error:
auth-worker(4826): Warning: mysql: Query failed, retrying: Table 'mailserver.users' doesn't exist
I enabled verbose logging and the same error message appears in both Dovecot and Postfix error logs but I'm almost positive it's a problem with Dovecot. I had no problems with MySQL and was able to verify the database and tables. Same thing with the configuration for Postfix.
Should I remove Dovecot and got through it again step by step? I've gone over the conf files several times now line by line and I don't see anything wrong. Does anyone know why it would refer to mailserver.users table? I read on the internet to check main Postfix cf file to ensure that "alias_maps" is set correctly, and it is (hash:/etc/aliases). I also have a feeling I will have the same problem if I remove Dovecot and set it up again.
One more thing, the user mailboxes are never created in /var/mail. I assume they will be created when I receive my first mail. I also tried manually creating them and that didn't help. Any guidance would be most appreciated. I will post part of the log file below. This is right after I tried sending an email to my user account from the root account:
Aug 6 08:36:06 neptune postfix/pickup[4700]: C782D148DC: uid=0 from= <root>Aug 6 08:36:06 neptune postfix/cleanup[4823]: C782D148DC: message-id=<20130806133606.C782D148DC@neptune.laftechsecure.net>
Aug 6 08:36:06 neptune postfix/qmgr[4701]: C782D148DC: from=<root@laftechsecure.net>, size=452, nrcpt=1 (queue active)
Aug 6 08:36:06 neptune dovecot: lmtp(4825): Connect from local
Aug 6 08:36:06 neptune dovecot: auth: Debug: master in: USER#0111#011steve@laftechsecure.net#011service=lmtp
Aug 6 08:36:06 neptune dovecot: auth-worker(4826): Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Aug 6 08:36:06 neptune dovecot: auth-worker(4826): Debug: Module loaded: /usr/lib/dovecot/modules/auth/libdriver_mysql.so
Aug 6 08:36:06 neptune dovecot: auth-worker(4826): mysql(127.0.0.1): Connected to database mailserver
Aug 6 08:36:06 neptune dovecot: auth-worker(4826): Debug: sql(steve@laftechsecure.net): SELECT home, uid, gid FROM users WHERE username = 's$
Aug 6 08:36:06 neptune dovecot: auth-worker(4826): Warning: mysql: Query failed, retrying: Table 'mailserver.users' doesn't exist
Aug 6 08:36:06 neptune dovecot: auth-worker(4826): Error: sql(steve@laftechsecure.net): User query failed: Table 'mailserver.users' doesn't $
Aug 6 08:36:06 neptune dovecot: auth: Debug: master out: FAIL#0111
Aug 6 08:36:06 neptune dovecot: lmtp(4825): Error: user steve@laftechsecure.net: Auth USER lookup failed
Aug 6 08:36:06 neptune postfix/lmtp[4803]: C782D148DC: to=<steve@laftechsecure.net>, relay=neptune.laftechsecure.net[private/dovecot-lmtp], $
Aug 6 08:36:06 neptune dovecot: lmtp(4825): Disconnect from local: Client quit (in reset)</steve@laftechsecure.net></root@laftechsecure.net></root>
3 Replies
4. Does the table being referenced actually exist?
Do Dovecot and Postfix reference the correct MySQL settings?
Add an alias pointing to an email address you have on another service (e.g. Gmail, Yahoo, …) restart Postfix/Dovecot, have someone send an email to that alias, and see if it gets forwarded correctly.
That last one is just to verify that Postfix can actually receive emails. If it can, it should forward the email, and at least you'll know that it's mostly working.
I also checked the MySQL settings for Postfix and Dovecot 4 or 5 times. Followed the instructions to the letter and all looks good.
Update: I have made some progress though and I'm no longer getting the same error. I can actually see email (sent from gmail.com) hit Postfix and I've never gotten this far before. The problem now is when it hands it off to Dovecot so I know that I'm very close.
All I did was reinstall and at first I got an error about missing .pem and .key:
Aug 6 12:02:06 neptune postfix/smtpd[12272]: warning: cannot get RSA private key from file /etc/ssl/private/dovecot.pem: disabling TLS suppo$
Aug 6 12:02:06 neptune postfix/smtpd[12272]: warning: TLS library problem: 12272:error:0B080074:x509 certificate routines:X509_check_private$
This time I copied them from the default directory to /etc/ssl, where they should be according to Linode instructions and as they have been referenced in some of the config files.
That took care of that error now I'm getting a very generic MySQL Could not connect to database error:
Aug 6 12:40:10 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:10 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:11 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:11 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:16 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:16 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:41 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:41 neptune dovecot: auth-worker(12795): Error: mysql(127.0.0.1): Connect failed to data$
Aug 6 12:40:45 neptune dovecot: lmtp(12780): Error: userdb lookup(steve@laftechsecure.net): Request$
Aug 6 12:40:45 neptune postfix/lmtp[12779]: 0B66E148A6: to=<steve@laftechsecure.net>, relay=neptune$
Aug 6 12:40:45 neptune dovecot: lmtp(12780): Disconnect from local: Client quit (in reset)</steve@laftechsecure.net>
One thing, when I do a service dovecot status I get a return that it is running and ok but it doesn't display a pid. According to the instructions it should give this value, not just say ok but that is all Postfix says and I wonder how accurate this is.
I also tried to disable the ssl requirement in Dovecot but got errors about an exisiting socket when I tried to restart. Had to go back to ssl=yes for it to start properly.
Anway, here is the latest entry from /var/log/mail.log where I think it shows the email from Google at least hitting my server. I think the problem now is delivery from the mda:
Aug 6 12:36:43 neptune postfix/smtpd[12766]: auto_clnt_create: transport=local endpoint=private/tlsmgr
Aug 6 12:36:43 neptune postfix/smtpd[12766]: auto_clnt_open: connected to private/tlsmgr
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr request = seed
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr size = 32
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute value: 0
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: seed
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: seed
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute value: GGHnsLpqGuBSQZkKEeHvKFlauXX1s1hgiFQGaspxVxk=
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: (list terminator)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: (end)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr request = policy
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr cache_type = smtpd
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute value: 0
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: cachable
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: cachable
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute value: 0
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: (list terminator)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: (end)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_string: fast_flush_domains ~? debug_peer_list
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_string: fast_flush_domains ~? fast_flush_domains
Aug 6 12:36:43 neptune postfix/smtpd[12766]: auto_clnt_create: transport=local endpoint=private/anvil
Aug 6 12:36:43 neptune postfix/smtpd[12766]: connection established
Aug 6 12:36:43 neptune postfix/smtpd[12766]: master_notify: status 0
Aug 6 12:36:43 neptune postfix/smtpd[12766]: name_mask: resource
Aug 6 12:36:43 neptune postfix/smtpd[12766]: name_mask: software
Aug 6 12:36:43 neptune postfix/smtpd[12766]: connect from mail-oa0-f52.google.com[209.85.219.52]
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: mail-oa0-f52.google.com: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: 209.85.219.52: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: mail-oa0-f52.google.com: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: 209.85.219.52: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: smtp_stream_setup: maxtime=300 enable_deadline=0
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_hostname: mail-oa0-f52.google.com ~? 127.0.0.0/8
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_hostaddr: 209.85.219.52 ~? 127.0.0.0/8
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_hostname: mail-oa0-f52.google.com ~? [::ffff:127.0.0.0]/104
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_hostaddr: 209.85.219.52 ~? [::ffff:127.0.0.0]/104
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_hostname: mail-oa0-f52.google.com ~? [::1]/128
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_hostaddr: 209.85.219.52 ~? [::1]/128
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: mail-oa0-f52.google.com: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: 209.85.219.52: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: auto_clnt_open: connected to private/anvil
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr request = connect
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr ident = smtp:209.85.219.52
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/anvil: wanted attribute: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: (end)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 220 neptune.laftechsecure.net ESMTP Postfix (Debian/G$
Aug 6 12:36:43 neptune postfix/smtpd[12766]: < mail-oa0-f52.google.com[209.85.219.52]: EHLO mail-oa0-f52.google.com
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: mail-oa0-f52.google.com: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: match_list_match: 209.85.219.52: no match
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-neptune.laftechsecure.net
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-PIPELINING
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-SIZE 10240000
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-VRFY
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-ETRN
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-STARTTLS
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-ENHANCEDSTATUSCODES
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250-8BITMIME
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 250 DSN
Aug 6 12:36:43 neptune postfix/smtpd[12766]: < mail-oa0-f52.google.com[209.85.219.52]: STARTTLS
Aug 6 12:36:43 neptune postfix/smtpd[12766]: > mail-oa0-f52.google.com[209.85.219.52]: 220 2.0.0 Ready to start TLS
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr request = seed
Aug 6 12:36:43 neptune postfix/smtpd[12766]: send attr size = 32
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: status
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute value: 0
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: seed
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: seed
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute value: 9mgiwNzazAIS3TPAzz0gc8tpFQvKXV15qJrZ+rIoMnk=
Aug 6 12:36:43 neptune postfix/smtpd[12766]: private/tlsmgr: wanted attribute: (list terminator)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: input attribute name: (end)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: xsasl_dovecot_server_create: SASL service=smtp, realm=(null)
Aug 6 12:36:43 neptune postfix/smtpd[12766]: name_mask: noanonymous
Aug 6 12:36:43 neptune postfix/smtpd[12766]: xsasl_dovecot_server_connect: Connecting
I still think it would be cool to do it myself but I know this might also save a lot of headache and trouble down the road. I'm confident that I'll be able to get it to work in the near future. I've learned a lot and I continue to study Dovecot and Postfix.