Debugging MariaDB stored procedures with the SQL Error Log

A very old version of the MySQL site contained a nice header: Speed, Power, Ease of Use. I don’t think that stored 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 practice you have no idea of what warnings occur within your procedures.

MariaDB 10.0 makes things much easier by adding the SQL_ERROR_LOG plugin. 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 the SQL_ERROR_LOG plugin. Its purpose is to log SQL errors into a text file. To enable it:

INSTALL SONAME 'sql_errlog';

Note that specifying the file extension is not 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 that SQL_ERROR_LOG is 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 called sql_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-30  1: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 DATA
BEGIN
    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 @debug variable is set to TRUE, an error is produced. The error is immediately suppressed by an empty CONTINUE HANDLER, so the procedure's execution continues and nothing happens. Well, almost nothing: the error is logged!

So:

  1. Write your CONTINUE HANDLERs.
  2. Set @debug to 1.
  3. CALL your procedure.
  4. cat the sql_errors.log.

Warning Logging

Look at this example:

DROP PROCEDURE IF EXISTS do_something;
DELIMITER ||
CREATE PROCEDURE do_something()
    READS SQL DATA
BEGIN
    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 main HANDLER catches the warnings (in this case division by 0, if you have a good SQL_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 empty HANDLER, but it is logged. Finally, the error is RESIGNAL'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 a BEGIN ... END construct, and define your handlers inside the construct.

Enjoy!

About these ads

Leave a comment

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s