MySQL Bugs: #60884: Enable logging of all errors to the error log

Bug #60884	Enable logging of all errors to the error log
Submitted:	15 Apr 2011 20:31	Modified:	20 Apr 2011 22:28
Reporter:	Anoop John	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S4 (Feature request)
Version:	Ver 14.12 Distrib 5.0.91	OS:	Linux (CentOS 5.5)
Assigned to:		CPU Architecture:	Any

Description:
I have a PHP application that is inserting a record into an innodb table (node) with an insert query using the PHP function mysql_query(). The application works fine and inserts happen regularly except that it fails once in a while. When it fails to insert the record, mysql_errno() returns 0 and mysql_error() returns empty string. So the insert fails silently. 

The specific query which failed when re-executed via phpmyadmin works fine without any problem.

Additionally the connection is not dropped and further queries, after the problematic insert into the node, runs correctly without problems till the php request is executed completely.

This is the structure of the node table

CREATE TABLE IF NOT EXISTS `node` (
  `nid` int(10) unsigned NOT NULL auto_increment,
  `vid` int(10) unsigned NOT NULL default '0',
  `type` varchar(32) NOT NULL default '',
  `language` varchar(12) NOT NULL default '',
  `title` varchar(255) NOT NULL default '',
  `uid` int(11) NOT NULL default '0',
  `status` int(11) NOT NULL default '1',
  `created` int(11) NOT NULL default '0',
  `changed` int(11) NOT NULL default '0',
  `comment` int(11) NOT NULL default '0',
  `promote` int(11) NOT NULL default '0',
  `moderate` int(11) NOT NULL default '0',
  `sticky` int(11) NOT NULL default '0',
  `tnid` int(10) unsigned NOT NULL default '0',
  `translate` int(11) NOT NULL default '0',
  PRIMARY KEY  (`nid`),
  UNIQUE KEY `vid` (`vid`),
  KEY `node_changed` (`changed`),
  KEY `node_created` (`created`),
  KEY `node_title_type` (`title`,`type`(4)),
  KEY `uid` (`uid`),
  KEY `node_uid_profile` (`uid`,`type`),
  KEY `node_moderate` (`moderate`),
  KEY `node_promote_status` (`promote`,`status`),
  KEY `node_status_type` (`status`,`type`,`nid`),
  KEY `tnid` (`tnid`)
) ENGINE=InnoDB  DEFAULT CHARSET=utf8 AUTO_INCREMENT=1008371 ;

Since the error only happens randomly and the conditions that triggers this failure is unknown I have not been able to isolate as to what causes the error. I have however pinpointed that the failure happens at this particular mysql_query call with the insert statement.

How to repeat:
I have not been able to replicate this on other installations of the application and the actual error only happens randomly on the live server. However the error has been happening pretty regularly and I will be able to add further debug statements to collect additional information if required.

Thank you for the bug report. Take a look in the err log file if there a warning or message error. On the another hand why do you think if a server bug if the offended query success in another client application?. Thanks in advance.

My suspicion is that something with MySQL is not working correctly. This could be a configuration error or this could be an actual bug in the application. The reason is that I have isolated the error to the specific insert statement which fails.

a) The SQL query is correct and runs correctly via MyAdmin (or even in the same application)

b) The mysql_query call is effectively a hand off from the PHP application to the MySQL server and it should either get a successful execution or an error should be triggered.

Both the above reasons force me to suspect that something is wrong somewhere between the mysql_query() call and the mysql server. Could be config issue, could be PHP API bug, could be MySQL bug.

There is no warning or error related to this query in the mysql error log. There are only two different warnings in the log

[Warning] Aborted connection 33987497 to db: 'dbname' user: 'user' host: '100.100.100.100' (Got an error reading communication packets)

and

[Warning] Aborted connection 33987490 to db: 'dbname' user: 'user' host: '100.100.100.100' (Got timeout reading communication packets)

These errors happen only around 10-15 times a day. The insert failures happen around 300 times a day. So I had discounted these errors as possible causes for the insert failure.

Please, send the output of

SHOW INNODB STATUS\G

from mysql command line client and exact INSERT statement that silently fails.

Innodb show status output

Attachment: innodb.log (text/x-log), 21.52 KiB.

I have attached the innodb status as a file to the thread. 

The following is one of the queries that have failed silently

INSERT INTO node (vid, type, language, title, uid, status, created, changed, comment, promote, moderate, sticky, tnid, translate) VALUES (1010206, 'story', '', 'Why the Euro Is in the Path of a Slow-Moving Train', 0, 1, 1302953434, 1302954548, 0, 1, 0, 0, 0, 0)

I have more information about the error. There is indeed a return value from mysqli_error and mysqli_errno. Apologies about the statement that MySQL was not returning any error value. 

Apparently the php application is not catching this particular MySQL error. I have to dig into that later. However this error is not being logged in /var/log/mysqld as well. I was able to catch the errno and error by adding my own debug statements right after the mysqli_query statement.

query => 'INSERT INTO node (vid, type, language, title, uid, status, created, changed, comment, promote, moderate, sticky, tnid, translate) VALUES (1013759, 'marketwire_story', '', 'Med Biogene Announces Closing of Partnership With Precision Therapeutics to Commercialize LungExpress DX', 6, 1, 1303139524, 1303139524, 0, 0, 0, 0, 0, 0)'

errno => 1205

error => 'Lock wait timeout exceeded; try restarting transaction'

Why was this not logged in the mysqld.log?

The table has around 1M records and there are quite a few simultaneous authors. But still I would think that this is a situation that MySQL should handle comfortably. Could it be that the configuration of the server is not right? What could I possibly change to prevent this from happening.

I see that innodb_lock_wait_timeout is set at 50s. isn't that long enough? What other configuration might play a role in this problem?

Changing title to make the error report more meaningful

I am not sure that you really want to have every error message that every session gets (or even every error 1205) logged in the error log. If you do want this, it will be a feature request.

@Valeriy - I guess that makes sense. But it would have been good to have some option to log errors just like there is an option to log all queries in the general query log. It would help debug issues like this where a supposedly fail-safe application actually was not so. 

Changing title again to help people searching for the exact error find this. 

I have also changed the Severity to Feature. So the feature request would be to enable logging of all errors like in General Query Log.

Let's say we have a valid feature request here for the option to log every error from the user session into the error log.

That's definitely not a reasonable feature request.

Furthermore, similar information will be provided by P_S tables. See WL#2515.

I am curious as to why this feature would be far different from the General Query Log? If all queries from across all sessions can be logged, why can't all errors from all sessions.

"The general query log can be very useful when you suspect an error in a client and want to know exactly what the client sent to mysqld."

Hence, the general log will show up what it actually received from the client, information that is not available by other means. On the other hand, what the server replied (be it a error, or a result) can be easily collected by the client application.

Also, this bug report talks about the error log, which would be a inappropriate destination for the kind of information you request:

"The error log contains information indicating when mysqld was started and stopped and also any critical errors that occur while the server is running."

@Davi Arnaut - Forgive me if I am wrong here but I still am not clear about why a feature to log Queries would be different from a feature to log errors.

Why did you say that the only way that we can get the information about the queries sent from the client is via the General Query Log itself? Can't the client itself keep track of the queries? Or if the implication was that the client would always be calling an API abstraction be it PHP or Perl to send the queries to the server and that something could happen after the query is sent from the client application then shouldn't the same logic be applicable in reverse?

I agree with you on the specific error log file part. If the default error log is not the place to log session level errors then the errors could definitely be logged in another log file.

The general log is useful to track globally who did what and when. It adds value besides simple debugging by providing a server wide audit log. I don't see much value in a log of errors being stored by the server -- in contrast to the cost of maintaining it within the server.

Furthermore, the debugging scenario that you describe is something that can be accomplished with MySQL proxy (http://forge.mysql.com/wiki/MySQL_Proxy) or with perhaps with the MySQL Enterprise Monitor.

@Davi Arnaut - Thanks for the explanation. I still do not agree with you but I am leaving the issue to rest. @Miguel Solorzano, @Valeriy Kravchuk - thanks for your inputs. 

@Davi Arnaut - But thanks for the pointer to the MySQL proxy. It would help debug in such situations as this with very good flexibilities. For those who come across this thread here is a howto on how to set the proxy to catch and log errors

http://www.chriscalender.com/?p=66

Here are some relevant links on MySQL proxy

http://dev.mysql.com/tech-resources/articles/proxy-gettingstarted.html
http://dev.mysql.com/doc/refman/5.0/en/mysql-proxy.html
http://forge.mysql.com/wiki/MySQL_Proxy

And for those who are curious about what was the cause for the problem and the solution

a) I increased the innodb_lock_wait_timeout parameter to increase the timeout to fix the symptom
b) Identified and fixed slow queries on the node table to prevent the locking issue from happening.

Anoop,

It is fine to disagree, we both have different perspectives. I tend to think that features which can be (reasonable) implemented outside the database don't have to be in the database.

In spite of this, I actually remembered that this is not the first time such a feature has been requested. For example, see Bug#59019. So, setting the bug status to verified as it might be valuable to more users after all.

There was also some request, which I can't find right now, to include the query status in the slow query log.