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:
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

[15 Apr 2011 20:31] Anoop John
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

  `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`)

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.
[15 Apr 2011 20:38] MySQL Verification Team
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.
[15 Apr 2011 20:43] Anoop John
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.
[15 Apr 2011 20:48] Anoop John
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: '' (Got an error reading communication packets)


[Warning] Aborted connection 33987490 to db: 'dbname' user: 'user' host: '' (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.
[16 Apr 2011 7:04] Valeriy Kravchuk
Please, send the output of


from mysql command line client and exact INSERT statement that silently fails.
[16 Apr 2011 14:49] Anoop John
Innodb show status output

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

[16 Apr 2011 14:52] Anoop John
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)
[18 Apr 2011 15:32] Anoop John
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?
[18 Apr 2011 15:33] Anoop John
Changing title to make the error report more meaningful
[19 Apr 2011 16:34] Valeriy Kravchuk
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.
[19 Apr 2011 19:47] Anoop John
@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.
[20 Apr 2011 11:09] Valeriy Kravchuk
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.
[20 Apr 2011 15:15] Davi Arnaut
That's definitely not a reasonable feature request.
[20 Apr 2011 15:28] Davi Arnaut
Furthermore, similar information will be provided by P_S tables. See WL#2515.
[20 Apr 2011 18:29] Anoop John
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.
[20 Apr 2011 18:39] Davi Arnaut
"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."
[20 Apr 2011 19:03] Anoop John
@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.
[20 Apr 2011 19:35] Davi Arnaut
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.
[20 Apr 2011 20:35] Anoop John
@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


Here are some relevant links on MySQL proxy

[20 Apr 2011 20:37] Anoop John
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.
[20 Apr 2011 22:28] Davi Arnaut

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.
[20 Apr 2011 22:30] Davi Arnaut
There was also some request, which I can't find right now, to include the query status in the slow query log.