6

I have been working on configuring my mail server for the last couple of weeks using postfix, dovecot, and mysql. I have one virtual domain and a few virtual mailboxes. Using squirrelmail I have been able to log into my accounts and send emails out (e.g. I can send to googlemail just fine), however I am not able to receive any emails--not from the outside world nor from within my own network.

I am able to telnet in using localhost, my private ip, and my public ip on port 25 without any problems (I've tried it from the server itself and from another computer on my network).

This is what I get in my logs when I send an email from my googlemail account to my mail server:

mail.log

Apr 14 07:36:06 server1 postfix/qmgr[1721]: BE01B520538: from=, >size=733, nrcpt=1 (queue active)

Apr 14 07:36:06 server1 postfix/pipe[3371]: 78BC0520510: to=, >relay=dovecot, delay=45421, delays=45421/0/0/0.13, dsn=4.3.0, status=deferred (temporary >failure. Command output: Can't open log file /var/log/mail-dovecot.log: Permission denied)

Apr 14 07:36:06 server1 postfix/pipe[3391]: 8261B520534: to=, >relay=dovecot, delay=38036, delays=38036/0.06/0/0.12, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:06 server1 postfix/pipe[3378]: 63927520532: to=, >relay=dovecot, delay=38105, delays=38105/0.02/0/0.17, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:06 server1 postfix/pipe[3375]: 07F65520522: to=, >relay=dovecot, delay=39467, delays=39467/0.01/0/0.17, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:06 server1 postfix/pipe[3381]: EEDE9520527: to=, >relay=dovecot, delay=38361, delays=38360/0.04/0/0.15, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:06 server1 postfix/pipe[3379]: 67DFF520517: to=, >relay=dovecot, delay=40475, delays=40475/0.03/0/0.16, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:06 server1 postfix/pipe[3387]: 3C7A052052E: to=, >relay=dovecot, delay=38259, delays=38259/0.05/0/0.13, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:06 server1 postfix/pipe[3394]: BE01B520538: to=, >relay=dovecot, delay=37682, delays=37682/0.07/0/0.11, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:36:07 server1 postfix/pipe[3384]: 3C7A052052E: to=, >relay=dovecot, delay=38261, delays=38259/0.04/0/1.3, dsn=4.3.0, status=deferred >(temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied )

Apr 14 07:39:23 server1 postfix/anvil[3368]: statistics: max connection rate 1/60s for (smtp:209.85.213.169) at Apr 14 07:35:32

Apr 14 07:39:23 server1 postfix/anvil[3368]: statistics: max connection count 1 for (smtp:209.85.213.169) at Apr 14 07:35:32

Apr 14 07:39:23 server1 postfix/anvil[3368]: statistics: max cache size 1 at Apr 14 07:35:32

Apr 14 07:41:06 server1 postfix/qmgr[1721]: ED6005203B7: from=, size=1463, nrcpt=1 (queue active)

Apr 14 07:41:06 server1 postfix/pipe[4594]: ED6005203B7: to=, relay=dovecot, delay=334, delays=334/0.01/0/0.13, dsn=4.3.0, status=deferred (temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: Permission denied )

Apr 14 07:51:06 server1 postfix/qmgr[1721]: ED6005203B7: from=, size=1463, nrcpt=1 (queue active)

Apr 14 07:51:06 server1 postfix/pipe[4604]: ED6005203B7: to=, relay=dovecot, delay=933, delays=933/0.02/0/0.12, dsn=4.3.0, status=deferred (temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: Permission denied )

mail-dovecot-log (the log I set for debugging):

Apr 14 07:28:26 auth: Info: mysql(127.0.0.1): Connected to database postfixadmin

Apr 14 07:28:26 auth: Debug: sql([email protected],127.0.0.1): query: SELECT >password FROM mailbox WHERE username = '[email protected]'

Apr 14 07:28:26 auth: Debug: client out: OK 1 [email protected]

Apr 14 07:28:26 auth: Debug: master in: REQUEST 1809973249 3356 1 7cfb822db820fc5da67d0776b107cb3f

Apr 14 07:28:26 auth: Debug: sql([email protected],127.0.0.1): SELECT '/home/vmail/mydomain.com/some.user1' as home, 5000 AS uid, 5000 AS gid FROM mailbox WHERE username = '[email protected]'

Apr 14 07:28:26 auth: Debug: master out: USER 1809973249 [email protected] home=/home/vmail/mydomain.com/some.user1 uid=5000 gid=5000

Apr 14 07:28:26 imap-login: Info: Login: user=, method=PLAIN, >rip=127.0.0.1, lip=127.0.0.1, mpid=3360, secured

Apr 14 07:28:26 imap([email protected]): Debug: Effective uid=5000, gid=5000, home=/home/vmail/mydomain.com/some.user1

Apr 14 07:28:26 imap([email protected]): Debug: maildir++: root=/home/vmail/mydomain.com/some.user1/Maildir, index=/home/vmail/mydomain.com/some.user1/Maildir/indexes, control=, inbox=/home/vmail/mydomain.com/some.user1/Maildir

Apr 14 07:48:31 imap([email protected]): Info: Disconnected: Logged out bytes=85/681

From the output above I'm pretty sure that my problems all stem from (temporary failure. Command output: Can't open log file /var/log/mail-dovecot.log: >Permission denied ), but I have no idea why I'm getting that error. I've have the permissions to that log set just like the other mail logs:

root@server1:~# ls -l /var/log/mail*
-rw-r----- 1 syslog adm 196653 2012-04-14 07:58 /var/log/mail-dovecot.log
-rw-r----- 1 syslog adm  62778 2012-04-13 21:04 /var/log/mail.err
-rw-r----- 1 syslog adm 497767 2012-04-14 08:01 /var/log/mail.log

Does anyone have any idea what I may be doing wrong?

Here are my main.cf and master.cf files: main.cf:

# See /usr/share/postfix/main.cf.dist for a commented, more complete version

# Debian specific:  Specifying a file name will cause the first
# line of that file to be used as the name.  The Debian default
# is /etc/mailname.
#myorigin = /etc/mailname

smtpd_banner = $myhostname ESMTP $mail_name (Ubuntu)
biff = no

# appending .domain is the MUA's job.
append_dot_mydomain = no

# Uncomment the next line to generate "delayed mail" warnings
#delay_warning_time = 4h

readme_directory = no

# TLS parameters
smtpd_tls_cert_file=/etc/ssl/certs/ssl-cert-snakeoil.pem
smtpd_tls_key_file=/etc/ssl/private/ssl-cert-snakeoil.key
smtpd_use_tls=yes
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache

# See /usr/share/doc/postfix/TLS_README.gz in the postfix-doc package for
# information on enabling SSL in the smtp client.

myhostname = server1.mydomain.com
alias_maps = hash:/etc/aliases
alias_database = hash:/etc/aliases
myorigin = /etc/mailname
mydestination = 
relayhost =
mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128
mailbox_command = procmail -a "$EXTENSION"
mailbox_size_limit = 0
recipient_delimiter = +
inet_interfaces = all

# Virtual Configs

virtual_uid_maps = static:5000
virtual_gid_maps = static:5000
virtual_mailbox_base = /home/vmail
virtual_mailbox_domains = mysql:/etc/postfix/mysql_virtual_mailbox_domains.cf
virtual_mailbox_maps = mysql:/etc/postfix/mysql_virtual_mailbox_maps.cf
virtual_alias_maps = mysql:/etc/postfix/mysql_virtual_alias_maps.cf
relay_domains = mysql:/etc/postfix/mysql_relay_domains.cf
smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_non_fqdn_hostname, reject_non_fqdn_sender, reject_non_fqdn_recipient, reject_unauth_destination, reject_unauth_pipelining, reject_invalid_hostname
smtpd_sasl_auth_enable = yes
smtpd_sasl_security_options = noanonymous

virtual_transport=dovecot
dovecot_destination_recipient_limit = 1

master.cf:

#
# Postfix master process configuration file.  For details on the format
# of the file, see the master(5) manual page (command: "man 5 master").
#
# Do not forget to execute "postfix reload" after editing this file.
#
# ==========================================================================
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (yes)   (never) (100)
# ==========================================================================
smtp      inet  n       -       -       -       -       smtpd
#smtp      inet  n       -       -       -       1       postscreen
#smtpd     pass  -       -       -       -       -       smtpd
#dnsblog   unix  -       -       -       -       0       dnsblog
#tlsproxy  unix  -       -       -       -       0       tlsproxy
#submission inet n       -       -       -       -       smtpd
#  -o smtpd_tls_security_level=encrypt
#  -o smtpd_sasl_auth_enable=yes
#  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
#  -o milter_macro_daemon_name=ORIGINATING
#smtps     inet  n       -       -       -       -       smtpd
#  -o smtpd_tls_wrappermode=yes
#  -o smtpd_sasl_auth_enable=yes
#  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
#  -o milter_macro_daemon_name=ORIGINATING
#628       inet  n       -       -       -       -       qmqpd
pickup    fifo  n       -       -       60      1       pickup
cleanup   unix  n       -       -       -       0       cleanup
qmgr      fifo  n       -       n       300     1       qmgr
#qmgr     fifo  n       -       -       300     1       oqmgr
tlsmgr    unix  -       -       -       1000?   1       tlsmgr
rewrite   unix  -       -       -       -       -       trivial-rewrite
bounce    unix  -       -       -       -       0       bounce
defer     unix  -       -       -       -       0       bounce
trace     unix  -       -       -       -       0       bounce
verify    unix  -       -       -       -       1       verify
flush     unix  n       -       -       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
proxywrite unix -       -       n       -       1       proxymap
smtp      unix  -       -       -       -       -       smtp
# When relaying mail as backup MX, disable fallback_relay to avoid MX loops
relay     unix  -       -       -       -       -       smtp
    -o smtp_fallback_relay=
#       -o smtp_helo_timeout=5 -o smtp_connect_timeout=5
showq     unix  n       -       -       -       -       showq
error     unix  -       -       -       -       -       error
retry     unix  -       -       -       -       -       error
discard   unix  -       -       -       -       -       discard
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       -       -       -       lmtp
anvil     unix  -       -       -       -       1       anvil
scache    unix  -       -       -       -       1       scache
#
# ====================================================================
# Interfaces to non-Postfix software. Be sure to examine the manual
# pages of the non-Postfix software to find out what options it wants.
#
# Many of the following services use the Postfix pipe(8) delivery
# agent.  See the pipe(8) man page for information about ${recipient}
# and other message envelope options.
# ====================================================================
#
# maildrop. See the Postfix MAILDROP_README file for details.
# Also specify in main.cf: maildrop_destination_recipient_limit=1
#
maildrop  unix  -       n       n       -       -       pipe
  flags=DRhu user=vmail argv=/usr/bin/maildrop -d ${recipient}
#
# ====================================================================
#
# Recent Cyrus versions can use the existing "lmtp" master.cf entry.
#
# Specify in cyrus.conf:
#   lmtp    cmd="lmtpd -a" listen="localhost:lmtp" proto=tcp4
#
# Specify in main.cf one or more of the following:
#  mailbox_transport = lmtp:inet:localhost
#  virtual_transport = lmtp:inet:localhost
#
# ====================================================================
#
# Cyrus 2.1.5 (Amos Gouaux)
# Also specify in main.cf: cyrus_destination_recipient_limit=1
#
#cyrus     unix  -       n       n       -       -       pipe
#  user=cyrus argv=/cyrus/bin/deliver -e -r ${sender} -m ${extension} ${user}
#
# ====================================================================
# Old example of delivery via Cyrus.
#
#old-cyrus unix  -       n       n       -       -       pipe
#  flags=R user=cyrus argv=/cyrus/bin/deliver -e -m ${extension} ${user}
#
# ====================================================================
#
# See the Postfix UUCP_README file for configuration details.
#
uucp      unix  -       n       n       -       -       pipe
  flags=Fqhu user=uucp argv=uux -r -n -z -a$sender - $nexthop!rmail ($recipient)
#
# Other external delivery methods.
#
ifmail    unix  -       n       n       -       -       pipe
  flags=F user=ftn argv=/usr/lib/ifmail/ifmail -r $nexthop ($recipient)
bsmtp     unix  -       n       n       -       -       pipe
  flags=Fq. user=bsmtp argv=/usr/lib/bsmtp/bsmtp -t$nexthop -f$sender $recipient
scalemail-backend unix  -       n       n       -       2       pipe
  flags=R user=scalemail argv=/usr/lib/scalemail/bin/scalemail-store ${nexthop} ${user} ${extension}
mailman   unix  -       n       n       -       -       pipe
  flags=FR user=list argv=/usr/lib/mailman/bin/postfix-to-mailman.py
  ${nexthop} ${user}


dovecot   unix  -       n       n       -       -       pipe
  flags=DRhu user=vmail:vmail argv=/usr/lib/dovecot/deliver -d ${recipient}
2
  • The permission denied error is possibly the cause, although I don't know why Postfix is trying to access Dovecot's log file. Can you paste your main.cf, master.cf and any other Postfix configuration files?
    – mgorven
    Apr 14, 2012 at 17:08
  • I just posted them above Apr 14, 2012 at 19:13

1 Answer 1

9

Postfix is going to run /usr/lib/dovecot/deliver to deliver mail, and it seems that deliver is failing because it can't write to /var/log/mail-dovecot.log. I'm not sure what user it's running as, but I'd guess postfix, so try making mail-dovecot.log writable by the postfix user.

4
  • That got me on the right track. It turns out that mail-dovecot.conf was being written by my vmail account. I temporarily set 777 permissions on the log and sent another email, then using auditd I was able to see that the last user to modify the file was uid 5000, vmail. Thanks for the help! Apr 14, 2012 at 23:29
  • 4
    I had the same problem and managed to resolve it by changing ownership of dovecot.log to vmail:dovecot - chown vmail:dovecot dovecot.log
    – Grant
    Jul 26, 2015 at 19:48
  • OMG thank you SO MUCH! I was pulling my hair trying to figure out why in the world would postfix need to read dovecot's files and you reminded me that i too used deliver to send mail and i was running it with vmail... Aug 16, 2016 at 1:33
  • In my case it was vmail:mail (CentOS 7)
    – Hardoman
    May 5, 2022 at 11:13

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .