Postfix often finds MySQL inaccessible

[ande]

Hi there,

I have had this kind of errors quite frequently (using IPSConfig 3.0.3.3 on Debian Squeeze) - and now it is bothering me as many people that want to send mail geht

"unexpected reply: 451 4.3.5 : Client host rejected: Server configuration error"

Nov  3 10:37:34 eins postfix/trivial-rewrite[8905]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Nov  3 10:37:36 eins postfix/trivial-rewrite[8914]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Nov  3 10:39:36 eins postfix/trivial-rewrite[8923]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Nov  3 10:39:38 eins postfix/trivial-rewrite[8924]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Nov  3 10:41:35 eins postfix/trivial-rewrite[9004]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Nov  3 10:41:37 eins postfix/trivial-rewrite[9005]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem

We have no overload problem here, even at the moments the messages occur the load (top) is below 0.1 . Nothing is visible in the MySQL logs.

The problem has always been here since the beginning, but often it was not bothering too much. At the beginning, I was testing the mailserver so we could have had overload problems. I then changed

max_connections        = 500
max_user_connections   = 500
wait_timeout = 15

as indicated by someone here. It did not help, for we have no overload problem.

This is very typical:

Nov 3 10:44:44 eins postfix/smtpd[9074]: warning: 61.19.66.247: hostname Nat-Pool-61-19-66-247.cdma.cat.net.th verification failed: Name or service not known
Nov 3 10:44:44 eins postfix/smtpd[9074]: connect from unknown[61.19.66.247]
Nov 3 10:44:45 eins postfix/proxymap[9032]: warning: mysql query failed: MySQL server has gone away
Nov 3 10:44:45 eins postfix/trivial-rewrite[9063]: fatal: proxy:mysql:/etc/postfix/mysql-virtual_domains.cf(0,lock|fold_fix): table lookup problem
Nov 3 10:44:46 eins postfix/master[29367]: warning: process /usr/lib/postfix/trivial-rewrite pid 9063 exit status 1
Nov 3 10:44:47 eins pop3d: Connection, ip=[::ffff:217.92.21.225]
Nov 3 10:44:47 eins postfix/smtpd[9001]: warning: mysql query failed: MySQL server has gone away
Nov 3 10:44:47 eins postfix/smtpd[9001]: warning: mysql:/etc/postfix/mysql-virtual_client.cf: table lookup problem
Nov 3 10:44:47 eins postfix/smtpd[9001]: NOQUEUE: reject: RCPT from unknown[61.19.66.247]: 451 4.3.5 : Client host rejected: Server configuration error; from= to=<xxxx> proto=ESMTP helo=

Our total database space on a machine with 8 GB RAM is 953 MByte. We have no cpu-intensive things here, and as I said, the load is most of the time below 0.1 (on an 4-core machine)

The only thing I changed yesterday is that I enabled replication as a master (which works) for only ONE of the databases. (BTW: Same changes worked fine with ISPConfig 2)

MySQL load (even if it is very low) appears to play a role.

When I have a look at the MYSQL status, I see no red numbers that indicate a performance problem normally. In the last 15 hours, MYSQL had to process about 8 queries per second. Not too much, hm?

Any help is appreciated..

[till]

Do you find any information about restarts of mysql in the log files?

[ande]

No.. Not in /var/log/messages, not in /var/log/mysql/mysql-bin.err - /var/log/mysql.log is empty.

It is said that MYSQL logging can be turned on while running..? I don't know how to do it nor found something when googlin'..

Further investigation gave:

/etc/postfix/mysql-virtual_client.cf has access to the Postfix blacklist. The blacklist contained only three rows, but I have deleted them.

I think it could have been a race condition: IPSConfig or Postfix throws two queries at MYSQL at the same time: Maybe to check "sender" with one query and "client" with another almost simultaneously. As there are many postfix processes (anvil, pickup, qmgr etc.) this could likely happen.

And the postfix timeout must be very low.

And mysql_virtual_client.cf is not the only spot the problems occur. Must be similar every time postfix interacts with MySQL. Besides, I have no problem with MySQL. However, 20% of the queries get smashed (!):

max. gleichzeitige Verbindungen	24	---	---
Fehlversuche	7	12,79	0,58%
Abgebrochen	247	451,14	20,43%
Insgesamt	1,209	2,208,22	100,00%

[till]

I think it could have been a race condition: IPSConfig or Postfix throws two queries at MYSQL at the same time: Maybe to check "sender" with one query and "client" with another almost simultaneously. As there are many postfix processes (anvil, pickup, qmgr etc.) this could likely happen.

I dont think that there is any general problem in this setup as it works quite nicely on many large mailservers and I dont see such problems on our mailsystems. On website scripts in busy websites you might have hundreds of simultanious accesses to the same database table, mysql is made to handle this.

How many mail accounts do you have on that server?

Also queries in state "Abgebrochen" dont have to be same queries that were logged in the postfix table.

[ande]

Originally Posted by till

I dont think that there is any general problem in this setup as it works quite nicely on many large mailservers and I dont see such problems on our mailsystems.

OK - could you point me to an example my.cnf please that runs fine with ISConfig3?

On website scripts in busy websites you might have hundreds of simultanious accesses to the same database table, mysql is made to handle this.

Exactly. With ISPConfig 2 on a much weaker machine and the same occupation, I've almost never had these logs.

How many mail accounts do you have on that server?

25 so far. ISPConfig2 handled more that 100.

Also queries in state "Abgebrochen" dont have to be same queries that were logged in the postfix table.

True, but at the moment I see what is hitting on the MySQL and it is almost exclusively ispconfig. ispconfig alone has usually more than 10 processes open / sleeping with 50% of them over 10 seconds duration. Is that normal?

[till]

OK - could you point me to an example my.cnf please that runs fine with ISConfig3?

the default configuration of all supported Linux distributions is fine. No need to alter them, jsut add:

max_connections = 500
max_user_connections = 500

in the [mysqld] section of the file.

Exactly. With ISPConfig 2 on a much weaker machine and the same occupation, I've almost never had these logs.

Comparuing ispconfig 2 and 3 makes no sense. The setup is not comparable. Thats is as if you compare windows with Linux.

ISPConfig 3 handles much higher loads then ispconfig 2.

25 so far. ISPConfig2 handled more that 100.

Thats a very small setup which can definately not have a bottleneck in mysql. ISPConfig 3 is known to handle a few thousand accounts per server and even on our server here we have a few hundred in the default configuration.

True, but at the moment I see what is hitting on the MySQL and it is almost exclusively ispconfig. ispconfig alone has usually more than 10 processes open / sleeping with 50% of them over 10 seconds duration. Is that normal?

Yes, thats normal and does not indicate any problems.

[concept21]

Check mysql error.log!!!

It may be a mysql db corruption!!!

[Dehumanizer]

No it itsn't. The database is clean, mysql reports no errors in error log and since increasing the wait_time I haven't got any errors in the posfix error log either.