Debugging MariaDB stored procedures with the SQL Error Log_MySQL

MariaDB

A very old version of the MySQL site contained a nice header:Speed, Power, Ease of Use. I don’t think thatstored programs(routines, triggers, events) were supported, at that time. Now they are, and… developing them is amazingly hard.

There are many problems, for example the language is not flexible and the execution is sloooow. But the biggest problem is that there is no debug API.

In details, one of the biggest problems is that, if you have complex procedures (accessing multiple tables, having error handling, and/or calling other procedures) in practiceyou have no ideaof what warnings occur within your procedures.

MariaDB 10.0 makes things much easier by adding theSQL_ERROR_LOGplugin.Well, I don’t think that they had stored programs in mind when they developed it. But what’s important for us is that… it makes stored programs debug decent.

This article explains how. Its use in application debugging is not covered here, because it seems to me quite obvious.

Enabling SQL_ERROR_LOG

We will use theSQL_ERROR_LOGplugin. Its purpose is to log SQL errors into a text file. To enable it:

INSTALL SONAME 'sql_errlog';

Note that specifying the file extension isnot necessary; this makes the statement platform-independent. The MySQL syntax is still supported.

When the plugin is installed, the logging is always active. To stop the logging, uninstall the plugin:

UNINSTALL PLUGIN SQL_ERROR_LOG;

Unfortunately, you might see a warning like this:

Warning (Code 1620): Plugin is busy and will be uninstalled on shutdown

I don’t know any way to avoid this. But I don’t think thatSQL_ERROR_LOGis meant to be ran on a production server. However, if this is a problem for you, just ask the list or file a bug.

Errors are written in a file calledsql_errors.log, in the data directory:

MariaDB [test]> SELECT CONCAT(@@global.datadir, @@global.sql_error_log_filename) AS sql_errlog;+--------------------------------------+| sql_errlog |+--------------------------------------+| /usr/local/mysql/data/sql_errors.log |+--------------------------------------+1 row in set (0.00 sec)

To make debug and life easier, I rotate the file very often:

SET @@global.sql_error_log_rotate = 1;

The format is the following:

2014-06-301:22:30 root[root] @ localhost [] ERROR 1051: Unknown table 'test.unknown_table' : DROP TABLE `unknown_table`

Limitations

• The session id is not written to the log. The hostname and the user account are written, but they don't help us distinguishing one session from others. I supose it is meant for being executed by application developers on their local machines.
• In theory, only errors are logged - no warnings, no notes. But keep on reading.
• The file format is not safely parseable. It's designed for humans.

Debug Messages

Look at the following procedure:

DROP PROCEDURE IF EXISTS do_something;DELIMITER ||CREATE PROCEDURE do_something(IN p TEXT)	READS SQL DATABEGIN	DECLARE CONTINUE HANDLER		FOR SQLSTATE '45000'	BEGIN END;		IF @debug = TRUE THEN		SET GLOBAL sql_error_log_rotate = 1;	END IF;		IF @debug = TRUE THEN		SET @error = CONCAT('p = ', IF(p IS NULL, 'NULL', QUOTE(p)));		SIGNAL SQLSTATE '45000' SET			MYSQL_ERRNO = 9999,			MESSAGE_TEXT = @error;	END IF;		-- why do something? let's do nothing!	DO NULL;END ||DELIMITER ;SET @debug = TRUE;CALL do_something('x');

Got the trick? If the@debugvariable is set toTRUE, an error is produced. The error is immediately suppressed by an emptyCONTINUE HANDLER, so the procedure's execution continues and nothing happens. Well, almost nothing: the error is logged!

So:

1. Write yourCONTINUE HANDLERs.
2. Set@debugto 1.
3. CALLyour procedure.
4. catthesql_errors.log.

Warning Logging

Look at this example:

DROP PROCEDURE IF EXISTS do_something;DELIMITER ||CREATE PROCEDURE do_something()	READS SQL DATABEGIN	DECLARE CONTINUE HANDLER		FOR SQLWARNING	BEGIN		DECLARE CONTINUE HANDLER			FOR SQLSTATE '45000'		BEGIN END;				GET DIAGNOSTICS CONDITION 1			@errno = MYSQL_ERRNO			, @error = MESSAGE_TEXT			;		IF @debug = TRUE THEN			SIGNAL SQLSTATE '45000' SET				MYSQL_ERRNO = @errno,				MESSAGE_TEXT = @error;		END IF;		RESIGNAL;	END;		IF @debug = TRUE THEN		SET GLOBAL sql_error_log_rotate = 1;	END IF;		-- here goes the 'real' procedure.	-- let's produce a warning to trigger the main HANDLER...	DO 1/0;END ||DELIMITER ;

I know: this is tricky. Writing this has been hard. But don't worry: reusing this template will be quite easy.

The mainHANDLERcatches the warnings (in this case division by 0, if you have a goodSQL_MODE). Then we get the warning properties (GET DIAGNOSTICS) and we use them to issue an error (SIGNAL). The error is suppressed by the internal emptyHANDLER, but it is logged. Finally, the error isRESIGNAL'd, because we don't want the debug code to suppress warnings.

A final note. Do you want to log warnings only if they appear within a particular portion of your procedure? You can. Just enclose those lines in aBEGIN ... ENDconstruct, and define your handlers inside the construct.

Enjoy!