postfix/trivial-rewrite

[digitalage]

Hello,

I followed Virtual Users And Domains With Postfix, Courier, MySQL And SquirrelMail (Debian Lenny) to configure email on my server. Everything went smooth and I could used it for about 1 month. For 1 day, no emails enter my server and some errors appear in logs:

Jun 28 12:04:43 hostname postfix/master[3302]: daemon started -- version 2.5.5, configuration /etc/postfix
Jun 28 12:04:43 hostname postfix/qmgr[3310]: 58D86A34E0: from=<>, size=3758, nrcpt=1 (queue active)
Jun 28 12:04:43 hostname postfix/proxymap[3317]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 28 12:04:43 hostname postfix/proxymap[3317]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 28 12:04:43 hostname postfix/trivial-rewrite[3316]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 28 12:04:44 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 3316 exit status 1
Jun 28 12:04:44 hostname postfix/master[3302]: warning: /usr/lib/postfix/trivial-rewrite: bad command startup -- throttling
Jun 28 12:04:45 hostname postfix/master[3302]: reload configuration /etc/postfix
Jun 28 12:04:47 hostname postfix/pickup[3437]: 1FAABA3507: uid=0 from=<root>
Jun 28 12:04:50 hostname postfix/master[3302]: reload configuration /etc/postfix
Jun 28 12:05:44 hostname postfix/proxymap[3750]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 28 12:05:44 hostname postfix/proxymap[3750]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 28 12:05:44 hostname postfix/trivial-rewrite[3749]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 28 12:05:45 hostname postfix/cleanup[3450]: warning: problem talking to service rewrite: Connection reset by peer
Jun 28 12:05:45 hostname postfix/qmgr[3310]: warning: problem talking to service rewrite: Success
Jun 28 12:05:45 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 3749 exit status 1
Jun 28 12:05:45 hostname postfix/master[3302]: warning: /usr/lib/postfix/trivial-rewrite: bad command startup -- throttling
Jun 28 12:06:45 hostname postfix/proxymap[3755]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 28 12:06:45 hostname postfix/cleanup[3450]: 1FAABA3507: message-id=<20090628090447.1FAABA3507@server.myhost.com>
Jun 28 12:06:45 hostname postfix/proxymap[3755]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 28 12:06:45 hostname postfix/trivial-rewrite[3754]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 28 12:06:46 hostname postfix/qmgr[3310]: warning: problem talking to service rewrite: Success
Jun 28 12:06:46 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 3754 exit status 1
Jun 28 12:06:46 hostname postfix/pickup[3437]: EEB19A33F7: uid=0 from=<root>
Jun 28 12:06:46 hostname postfix/cleanup[3757]: EEB19A33F7: message-id=<20090628090646.EEB19A33F7@server.myhost.com>
Jun 28 12:06:47 hostname postfix/trivial-rewrite[3758]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 28 12:06:47 hostname postfix/pickup[3437]: EFA95A34E7: uid=0 from=<root>
Jun 28 12:06:48 hostname postfix/qmgr[3310]: warning: problem talking to service rewrite: Success
Jun 28 12:06:48 hostname postfix/cleanup[3757]: warning: problem talking to service rewrite: Connection reset by peer
Jun 28 12:06:48 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 3758 exit status 1
Jun 28 12:06:49 hostname postfix/trivial-rewrite[3760]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 28 12:06:50 hostname postfix/qmgr[3310]: warning: problem talking to service rewrite: Success
Jun 28 12:06:50 hostname postfix/cleanup[3757]: warning: problem talking to service rewrite: Connection reset by peer
Jun 28 12:06:50 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 3760 exit status 1
Jun 28 12:06:50 hostname postfix/master[3302]: warning: /usr/lib/postfix/trivial-rewrite: bad command startup -- throttling

Note: the real domain name was replaced with "myhost.com"

I really don't understand what's going on. I need some help, please.

[falko]

It seems as if MySQL isn't running. What's the output of

netstat -tap

?

[digitalage]

# netstat -tap | grep mysql

tcp        0      0 localhost:mysql         *:*                     LISTEN      12566/mysqld
tcp        0      0 localhost:mysql         localhost:51517         TIME_WAIT   -
tcp        0      0 localhost:mysql         localhost:51516         TIME_WAIT   -
tcp        0      0 localhost:mysql         localhost:51515         TIME_WAIT   -
tcp        0      0 localhost:mysql         localhost:51514         TIME_WAIT   -

[digitalage]

MySQL works fine, I guess. I can connect to databases using PhpMyAdmin. Also, if I run /etc/init.d/mysql restart, I get the following output:

Jun 29 17:22:48 hostname mysqld[13464]: 090629 17:22:48  InnoDB: Shutdown completed; log sequence number 0 233495
Jun 29 17:22:48 hostname mysqld[13464]: 090629 17:22:48 [Note] /usr/sbin/mysqld: Shutdown complete
Jun 29 17:22:48 hostname mysqld[13464]:
Jun 29 17:22:48 hostname mysqld_safe[13997]: ended
Jun 29 17:22:49 hostname mysqld_safe[14073]: started
Jun 29 17:22:49 hostname mysqld[14077]: 090629 17:22:49  InnoDB: Started; log sequence number 0 233495
Jun 29 17:22:49 hostname mysqld[14077]: 090629 17:22:49 [Note] /usr/sbin/mysqld: ready for connections.
Jun 29 17:22:49 hostname mysqld[14077]: Version: '5.0.51a-24+lenny1-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)
Jun 29 17:22:50 hostname /etc/mysql/debian-start[14117]: Upgrading MySQL tables if necessary.
Jun 29 17:22:50 hostname /etc/mysql/debian-start[14123]: Looking for 'mysql' in: /usr/bin/mysql
Jun 29 17:22:50 hostname /etc/mysql/debian-start[14123]: Looking for 'mysqlcheck' in: /usr/bin/mysqlcheck
Jun 29 17:22:50 hostname /etc/mysql/debian-start[14123]: This installation of MySQL is already upgraded to 5.0.51a, use --force if you still need to run mysql_upgrade
Jun 29 17:22:50 hostname /etc/mysql/debian-start[14129]: Checking for insecure root accounts.
Jun 29 17:22:50 hostname /etc/mysql/debian-start[14133]: Triggering myisam-recover for all MyISAM tables
Jun 29 17:23:18 hostname postfix/smtpd[30085]: fatal: watchdog timeout
Jun 29 17:23:19 hostname postfix/master[3302]: warning: process /usr/lib/postfix/smtpd pid 30085 exit status 1
Jun 29 17:23:19 hostname postfix/master[3302]: warning: /usr/lib/postfix/smtpd: bad command startup -- throttling
Jun 29 17:23:48 hostname postfix/proxymap[3874]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 29 17:23:48 hostname postfix/proxymap[3874]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 29 17:23:48 hostname postfix/trivial-rewrite[14167]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 29 17:23:48 hostname postfix/trivial-rewrite[14168]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 29 17:23:48 hostname postfix/trivial-rewrite[14169]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 29 17:23:48 hostname postfix/trivial-rewrite[14170]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 29 17:23:48 hostname postfix/proxymap[23943]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 29 17:23:48 hostname postfix/proxymap[23943]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0
Jun 29 17:23:48 hostname postfix/trivial-rewrite[14171]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 29 17:23:48 hostname postfix/trivial-rewrite[14172]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem

... (the same message, several times)

Jun 29 17:23:48 hostname postfix/trivial-rewrite[14216]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jun 29 17:23:49 hostname postfix/smtpd[8074]: warning: problem talking to service rewrite: Success
Jun 29 17:23:49 hostname postfix/smtpd[866]: warning: problem talking to service rewrite: Connection reset by peer
Jun 29 17:23:49 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 14167 exit status 1
Jun 29 17:23:49 hostname postfix/master[3302]: warning: /usr/lib/postfix/trivial-rewrite: bad command startup -- throttling
Jun 29 17:23:49 hostname postfix/smtpd[3678]: warning: problem talking to service rewrite: Success
Jun 29 17:23:49 hostname postfix/smtpd[31378]: warning: problem talking to service rewrite: Connection reset by peer
Jun 29 17:23:49 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 14168 exit status 1
Jun 29 17:23:49 hostname postfix/smtpd[32233]: warning: problem talking to service rewrite: Connection reset by peer
Jun 29 17:23:49 hostname postfix/smtpd[30244]: warning: problem talking to service rewrite: Success
Jun 29 17:23:49 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 14169 exit status 1
Jun 29 17:23:49 hostname postfix/smtpd[30193]: warning: problem talking to service rewrite: Success
Jun 29 17:23:49 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 14170 exit status 1
Jun 29 17:23:49 hostname postfix/smtpd[31429]: warning: problem talking to service rewrite: Success
Jun 29 17:23:49 hostname postfix/smtpd[30400]: warning: problem talking to service rewrite: Connection reset by peer
Jun 29 17:23:49 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 14171 exit status 1
Jun 29 17:23:49 hostname postfix/smtpd[31807]: warning: problem talking to service rewrite: Connection reset by peer

... this group of messages, several times)

Jun 29 17:23:48 hostname postfix/trivial-rewrite[14172]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem

... (the same message, several times)

Jun 29 17:23:49 hostname postfix/smtpd[31429]: warning: problem talking to service rewrite: Success
Jun 29 17:23:49 hostname postfix/smtpd[30400]: warning: problem talking to service rewrite: Connection reset by peer
Jun 29 17:23:49 hostname postfix/master[3302]: warning: process /usr/lib/postfix/trivial-rewrite pid 14171 exit status 1
Jun 29 17:23:49 hostname postfix/smtpd[31807]: warning: problem talking to service rewrite: Connection reset by peer

... this group of messages, several times)

[falko]

What's in /etc/hosts?
Is the MySQL login that Postfix uses correct?

[digitalage]

hostname:~# cat /etc/hosts

127.0.0.1       localhost
127.0.1.1       hostname.myprovider.com        hostname

# The following lines are desirable for IPv6 capable hosts
::1     localhost ip6-localhost ip6-loopback
fe00::0 ip6-localnet
ff00::0 ip6-mcastprefix
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters
ff02::3 ip6-allhosts

Notes: My hostname was replaced with the word "hostname"


I don't know how to answer to the 2nd question. I assume MySQL login is fine, otherwise it didn't work in first place for 1 month. I didn't do any upgrade or update to packages since the install. The MySQL user that Postfix is using is mail_admin.

# postconf -n shows:

alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_dot_mydomain = no
biff = no
broken_sasl_auth_clients = yes
config_directory = /etc/postfix
content_filter = amavis:[127.0.0.1]:10024
html_directory = /usr/share/doc/postfix/html
inet_interfaces = all
mailbox_size_limit = 0
message_size_limit = 31457280
mydestination = server.mydomain.com, localhost, localhost.localdomain
myhostname = server.mydomain.com
mynetworks = 127.0.0.0/8
myorigin = /etc/mailname
proxy_read_maps = $local_recipient_maps $mydestination $virtual_alias_maps $virtual_alias_domains $virtual_mailbox_maps $virtual_mailbox_domains $relay_recipient_maps $relay_domains $canonical_maps $sender_canonical_maps $recipient_canonical_maps $relocated_maps $transport_maps $mynetworks $virtual_mailbox_limit_maps
readme_directory = /usr/share/doc/postfix
receive_override_options = no_address_mappings
recipient_delimiter = +
relayhost =
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination
smtpd_sasl_auth_enable = yes
smtpd_sasl_authenticated_header = yes
smtpd_tls_cert_file = /etc/postfix/smtpd.cert
smtpd_tls_key_file = /etc/postfix/smtpd.key
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_use_tls = yes
transport_maps = proxy:mysql:/etc/postfix/mysql-virtual_transports.cf
virtual_alias_domains =
virtual_alias_maps = proxy:mysql:/etc/postfix/mysql-virtual_forwardings.cf, mysql:/etc/postfix/mysql-virtual_email2email.cf
virtual_gid_maps = static:5000
virtual_mailbox_base = /home/vmail
virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql-virtual_domains.cf
virtual_mailbox_limit_maps = proxy:mysql:/etc/postfix/mysql-virtual_mailbox_limit_maps.cf
virtual_mailbox_limit_override = yes
virtual_mailbox_maps = proxy:mysql:/etc/postfix/mysql-virtual_mailboxes.cf
virtual_maildir_extended = yes
virtual_maildir_limit_message = "The user you are trying to reach is over quota."
virtual_overquota_bounce = yes
virtual_uid_maps = static:5000

Note: My domain was replaced with the word "mydomain.com"

Searching the internet I found this link where someone suggests to grant privileges again to the MySQL user that Postfix is using. I'm afraid I don't know how to do this and if it's appropriate to my issue, so I didn't touch the server.

Any idea?


Edit: I found another user having the same issue. He gave up on finding the problem, but I wish I'll find the cause. Hope it won't take too long, otherwise I'll be forced to rebuild the server because my main emails comes on it.

[falko]

What's the output of

ifconfig

?
Can you log in to MySQL like this?

mysql -u mail_admin -p

Then type in the password that you use in the mysql*.cf files.

[digitalage]

Everything looks good, either. I don't know why would you need ifconfig - I sent it as private message to stay away of public.


I checked also passwords used in MySql, like this:
# cat /etc/postfix/mysql-virtual_* | grep password

password = xxx
password = xxx
password = xxx
password = xxx
password = xxx
password = xxx

... and I got the same answer. Then I logged into console of MySql:

# /etc/postfix# mysql -u mail_admin -p

Enter password: xxx
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 41
Server version: 5.0.51a-24+lenny1-log (Debian)

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| mail               |
+--------------------+
2 rows in set (0.00 sec)

mysql> use mail
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> show tables;
+----------------+
| Tables_in_mail |
+----------------+
| domains        |
| forwardings    |
| transport      |
| users          |
+----------------+
4 rows in set (0.00 sec)

mysql> quit
Bye

[falko]

Can you modify /etc/hosts so that it looks as follows?

127.0.0.1       localhost.localdomain localhost
192.168.0.1      hostname.myprovider.com        hostname

# The following lines are desirable for IPv6 capable hosts
::1     localhost ip6-localhost ip6-loopback
fe00::0 ip6-localnet
ff00::0 ip6-mcastprefix
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters
ff02::3 ip6-allhosts

[digitalage]

I changed that and the issue is still there. During my research in logs, I found some lines which might or might not be related to this issue. I took them before the last change - you can see the date:

Jun 30 18:15:07 postfix/pickup[7303]: F0157A3551: uid=0 from=<root>
Jun 30 18:15:13 postfix/master[4812]: warning: service "smtp" (25) has reached its process limit "100": new clients may experience noticeable delays
Jun 30 18:15:13 postfix/master[4812]: warning: to avoid this condition, increase the process count in master.cf or reduce the service time per client
Jun 30 18:15:13 postfix/master[4812]: warning: see http://www.postfix.org/STRESS_README.html for examples of stress-adapting configuration settings
...
Jul  1 09:27:32 209-145-MZA-enternet postfix/smtpd[7724]: fatal: watchdog timeout
Jul  1 09:27:33 postfix/master[4812]: warning: process /usr/lib/postfix/smtpd pid 7724 exit status 1
Jul  1 09:27:33 postfix/master[4812]: warning: /usr/lib/postfix/smtpd: bad command startup -- throttling
...
Jul  1 11:02:12 postfix/trivial-rewrite[4191]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Jul  1 11:02:13 postfix/qmgr[4068]: warning: problem talking to service rewrite: Success
Jul  1 11:02:13 postfix/master[3306]: warning: process /usr/lib/postfix/trivial-rewrite pid 4191 exit status 1
Jul  1 11:02:13 postfix/master[3306]: warning: /usr/lib/postfix/trivial-rewrite: bad command startup -- throttling
Jul  1 11:02:35 postfix/qmgr[4068]: fatal: watchdog timeout
Jul  1 11:02:36 postfix/master[3306]: warning: process /usr/lib/postfix/qmgr pid 4068 exit status 1
Jul  1 11:02:36 postfix/master[3306]: warning: /usr/lib/postfix/qmgr: bad command startup -- throttling

I checked the config using the following commands:
# cat /etc/postfix/mysql-virtual_domains.cf

user = mail_admin
password = xxx
dbname = mail
query = SELECT domain AS virtual FROM domains WHERE domain='%s'
hosts = 127.0.0.1

# cat /etc/postfix/mysql-virtual_* | grep user

user = mail_admin
user = mail_admin
query = SELECT email FROM users WHERE email='%s'
user = mail_admin
user = mail_admin
query = SELECT CONCAT(SUBSTRING_INDEX(email,'@',-1),'/',SUBSTRING_INDEX(email,'@',1),'/') FROM users WHERE email='%s'
user = mail_admin
query = SELECT quota FROM users WHERE email='%s'
user = mail_admin

# cat /etc/postfix/mysql-virtual_* | grep dbname

dbname = mail
dbname = mail
dbname = mail
dbname = mail
dbname = mail
dbname = mail

# cat /etc/postfix/mysql-virtual_* | grep query

query = SELECT domain AS virtual FROM domains WHERE domain='%s'
query = SELECT email FROM users WHERE email='%s'
query = SELECT destination FROM forwardings WHERE source='%s'
query = SELECT CONCAT(SUBSTRING_INDEX(email,'@',-1),'/',SUBSTRING_INDEX(email,'@',1),'/') FROM users WHERE email='%s'
query = SELECT quota FROM users WHERE email='%s'
query = SELECT transport FROM transport WHERE domain='%s'

# cat /etc/postfix/mysql-virtual_* | grep hosts

hosts = 127.0.0.1
hosts = 127.0.0.1
hosts = 127.0.0.1
hosts = 127.0.0.1
hosts = 127.0.0.1
hosts = 127.0.0.1

Everything looks good. However, if I look at my logs, I see lines that I don't know to "translate". Particularly, these:

Jul  2 23:29:24 postfix/proxymap[3859]: warning: connect to mysql server 127.0.0.1: Lost connection to MySQL server at 'reading initial communication packet', system error: 0

and

Jul  2 23:29:24 postfix/trivial-rewrite[3923]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem

I don't know what is proxymap and proxy:mysql. Are you kind to explain me (maybe it's useful for others too), like to a novice, how the system works? How is the email received by the server and what is its way to the mailbox, in this particular setup?