MySQL logging of calls to Stored Procedures
Here at Otreva, we use MySQL stored procedures (SPs) in the back end of our projects. It gives very precise security controls and modularity to functionality across multiple applications. This is a performance booster for us in most cases because of the complexity of the functionality. This article is not to discuss the pros and cons of using SPs though.
If you are using SPs in your applications, then you may have run into the problem of logging calls with the passed parameters (our advanced search SP takes over 50 parameters). This becomes most apparent when the front-end team integrates the SPs into their code. During development, I used to spend a large amount of time working with the front-end guys to do two things: see if parameters are being passed incorrectly and check the expected functionality against passed parameters. There was no way to go back (without the logs) and see what was going on. When running applications on a schedule, there wasn’t an easy way to check the parameters that were being passed and at what time.
My solution was to create a log table so that every SP call would be logged and anyone on the development team could see what was called when with the parameters that were passed. I made a few tools to go along with the table because it gets big quickly and makes finding what you’re looking for more difficult (30k+ entries per day on our development db).
1. Here is the table DDL. This will keep an execution time, the name of the sp, and the parameters of the sp.
CREATE TABLE spCalls( spCallId SERIAL PRIMARY KEY, execTime DATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP, spName ENUM(...) NOT NULL, params LONGTEXT NOT NULL );
2. You may notice spName does not have a correct ENUM definition. Here is an “ADMIN” SP I wrote to update the DDL based on the SPs the connected database has. It will not add a name for SPs that start with “TEST” or “ADMIN”.
DELIMITER ~ DROP PROCEDURE IF EXISTS ADMIN_makeENUM_definition~ CREATE PROCEDURE ADMIN_makeENUM_definition( ) MODIFIES SQL DATA SQL SECURITY DEFINER BEGIN DECLARE enumText TEXT DEFAULT ''; DECLARE moreProcs BOOLEAN DEFAULT TRUE; DECLARE curProc VARCHAR(100); DECLARE procedures CURSOR FOR SELECT name FROM mysql.proc WHERE db = DATABASE() && type = 'PROCEDURE' && name NOT LIKE 'TEST\_%' && name NOT LIKE 'ADMIN\_%' ; DECLARE CONTINUE HANDLER FOR NOT FOUND SET moreProcs = FALSE; DECLARE CONTINUE HANDLER FOR 1396 BEGIN END; OPEN procedures; FETCH procedures INTO curProc; WHILE moreProcs DO SET enumText = IF(enumText = '', CONCAT('ENUM(',QUOTE(curProc)), CONCAT_WS(', ', enumText, QUOTE(curProc))); FETCH procedures INTO curProc; END WHILE; SET @t = CONCAT("ALTER TABLE spCalls CHANGE COLUMN spName spName ", enumText,") NOT NULL"); PREPARE stmt FROM @t; EXECUTE stmt; DEALLOCATE PREPARE stmt; COMMIT; END~ DELIMITER ;
3. Here is an example SP with the logging call. I am currently just using ‘!#!’ as a delimiter, but I am working on making it a comma separated list and logging the parameters as they would appear in the terminal. This would make “recalling” the SP a simple copy/paste. You probably don’t want to store any sensitive data like passwords (_password in this example)!
DELIMITER ~ DROP PROCEDURE IF EXISTS userLogin~ CREATE PROCEDURE userLogin( _email VARCHAR(50), _password VARCHAR(30) ) MODIFIES SQL DATA SQL SECURITY DEFINER BEGIN BEGIN INSERT INTO spCalls (spName, params) VALUES('userLogin',CONCAT_WS('!#!',IFNULL(_email,'NuLL'),IFNULL(_password,'NuLL'))); COMMIT; END; /* Awesome SP code */ END~ DELIMITER ;
4. Once this table grows large, it is not easy to write your own queries to get the rows you are looking for. Here is the SP I wrote to get recent SP calls.
DELIMITER ~ DROP PROCEDURE IF EXISTS ADMIN_getRecentSPCalls~ CREATE PROCEDURE ADMIN_getRecentSPCalls( _spName VARCHAR(100), _numResults INT UNSIGNED ) MODIFIES SQL DATA SQL SECURITY DEFINER BEGIN DECLARE totalCalls BIGINT UNSIGNED DEFAULT 0; DECLARE offset INT UNSIGNED; SET _numResults = LEAST(IFNULL(_numResults, 0), 100); SELECT COUNT(*) INTO totalCalls FROM spCalls WHERE IF(_spName IS NULL || _spName = '', TRUE, spName = _spName); SET offset = IF(totalCalls <= _numResults, 0, totalCalls - _numResults); SELECT spName, execTime, params FROM spCalls WHERE IF(_spName IS NULL || _spName = '', TRUE, spName = _spName) ORDER BY execTime LIMIT offset, _numResults ; COMMIT; END~ DELIMITER ;
Hopefully this structure will help MySQL SP users with logging without cluttering up the code too much. Next week I’ll get into our solution for functional error handling in the SPs.
Depending on business rules this may not be a good idea for a production environment!