Logs as a testing tool
In my last post about unit testing I told you that I only have unit tests on my core functions in the application. To catch the rest of the bugs I use logs. Let me explain.
Release your bugs
I can allow myself to deploy an application that have some flaws because I know I can fix them with lightening speed. So if some of my users run in to a problem they can actually expect to get the issue fixed before they even send me a bug report. And that is a good thing because 90% of users do not bather to report bugs, the find workarounds or just stop using the faulty part of the system. Don't get me wrong, I do test my code before I deploy, but in order to test for every eventuality you need to take a lot of time from development to ensure that your code is in order. And you will still not get all bugs. So just make sure that the important stuff work and let your users find the rest.
What do I want to know
But if my user do not report bugs, why trust in them? Well that is it. I don't, I use the debug features of PHP in order to have the system send me mails every time something goes south. I also implement additional logs where I want to analyse the code in order to figure out how much a feature is used or what values are posted when the system breaks. Then I let the users give me the data so that I can correct my functions to handle the failing input.
Her is a sample of how one of my error messages could look like:
// Log extract
Message: (Either the error message from the server or a text that I have hard coded in my code)
Trace:
Area.php: info() - (459)
Area.php: getCityByIP() - (495)
Calendar.php: getCityByIP() - (3544)
front_page.php: eventListTeaser() - (26)
index.php: include() - (43)
main_template.php: vPrintContentAlt() - (439)
index.php: include() - (57)
Browser agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.97 Safari/537.36
URL: http://www.mywebsite.com
User: 9 - Johan jb@front-it.com [2.107.127.43]
Date time: 2016-02-06 23:09:51
POST: array('submit'=>'Send', 'msg'=>'test');
With this information I can look at the error message, open the file where the error was reported and scroll down to the correct line and fix the problem. Then if I like I can send a mail to the user informing that the bug has been fixed. Apart from errors I use this to check what users are doing on my site. If I want to know how often they use a specific feature or if one particular user has an issue I can choose to only log when that user is using the application.
These messages are also classified in three categories. Info: these are just logged in the database, Warning and Error: these are also sent to me as a mail. So I get noticed right away when an issue occurs.
Next step
After using this for 5 years I feel that I want to organise it a bit more, so my next project here is to have the logs grouped by error and organised in a sort of ticket system, so if I do not fix an error it just gets added to one and the same ticket that is raised in priority with every error. This is because there are some errors that are not critical, and those mails are just annoying to get if I do not take the time to fix them. This might be when someone is trying to upload a pdf to a function that expects an image of type jpg, gif or png. The user realises that it does not work, but I might want to create a better error message but since the image function has so low priority in my application I never get to fixing it until I decide to rewrite the entire thing.
The code
This is what I currently have and use in order to log stuff.
// The log table
CREATE TABLE IF NOT EXISTS `debug_log` (
`date` datetime NOT NULL,
`message` text COLLATE utf8mb4_swedish_ci NOT NULL,
`type` tinyint(4) NOT NULL COMMENT '0: info; 1: warn; 2: err;',
`lable` varchar(20) COLLATE utf8mb4_swedish_ci NOT NULL,
`ip` varchar(20) COLLATE utf8mb4_swedish_ci NOT NULL,
KEY `date` (`date`),
KEY `type` (`type`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_swedish_ci
Notice that I do not have an ID table. This is because there will be a lot of entries and I do not care about the id, I just want the timestamp. You might also want to ignore the indexes to speed up the inserts.
//classes/Log.php
user;
$msg = String::slashText($message . '
' . PHP_EOL
. Log::getTrace() . '
' . PHP_EOL
. String::htmlSpecialChars($_SERVER['HTTP_USER_AGENT']) . '
' . PHP_EOL
. 'URL: ' . Log::currentURL() . '
' . PHP_EOL
. 'usr: ' . $user->id . '; ' . $user->username . ' [' . $_SERVER['REMOTE_ADDR'] . ']
' . PHP_EOL
. 'user_agent: ' . String::htmlSpecialChars($_SERVER['HTTP_USER_AGENT']) . ' #
' . PHP_EOL
. 'Date time: ' . date('Y-m-d H:i:s') . '
'
. 'POST: ' . $post . '
' . PHP_EOL . PHP_EOL
. Log::getTrace() . '
' . PHP_EOL
. $_SESSION['trace']
);
$sql = 'INSERT INTO debug_log
(date, message, type, ip)
VALUES
("' . date('Y-m-d H:i:s') . '", "' . $msg . '", ' . $status . ', "' . $_SERVER['REMOTE_ADDR'] . '")';
switch ($status) {
case 0: $status = 'Info: ';
break;
case 1: $status = 'Warning: ';
break;
case 2: $status = 'Error: ';
break;
}
Db::query($sql, false);
if ($mail) {
$post = 'No $_POST[] data';
if (count($_POST) > 0) {
ob_start();
var_dump($_POST);
$post = ob_get_contents();
ob_end_clean();
}
Log::sendMail(String::slashText('' . $status . '' . $message . '
'
. 'from: ' . $_SERVER['HTTP_REFERER'] . '
'
. 'to: ' . Log::currentURL() . '
'
. $user->iID
. ' - ' . $user->username . '
'
. ' [' . $_SERVER['REMOTE_ADDR'] . ']
'
. String::htmlSpecialChars($_SERVER['HTTP_USER_AGENT']) . '
'
. 'Date time: ' . date('Y-m-d H:i:s') . '
'
. 'POST: ' . $post . '
'
. Log::getTrace() . '
'
. $_SESSION['trace'])
, $status . '' . String::part($message, 200));
}
}
function error($message, $label = '') {
Log::message($message . ' ' . $label, 2, true);
}
function warning($message, $label = '') {
Log::message($message . ' ' . $label, 1, true);
}
function information($message, $label = '') {
Log::message($message . ' ' . $label);
}
function err($message, $label = '') {
Log::error($message . ' ' . $label);
}
function warn($message, $label = '') {
Log::warning($message . ' ' . $label);
}
function info($message, $label = '') {
Log::information($message . ' ' . $label);
}
function msg($message, $label = '') {
Log::message($message . ' ' . $label, 0, true);
}
function getTrace() {
$tArr = debug_backtrace();
ob_start();
foreach ($tArr as $item) {
if (basename($item['file']) != 'Log.php') {
echo basename($item['file']) . ': ' . $item['function'] . '() - (' . $item['line'] . ')
';
}
}
$trace = ob_get_contents();
ob_end_clean();
return $trace;
}
function currentURL($sPart = 'full') {
$pageURL = '';
$http = 'http';
if ($_SERVER["HTTPS"] == "on") {
$http .= "s";
}
$http .= '://';
$port = '';
if ($_SERVER["SERVER_PORT"] != "80") {
$port = ':' . $_SERVER["SERVER_PORT"];
}
$pageURL .= $http . $_SERVER["SERVER_NAME"] . $port . $_SERVER["REQUEST_URI"];
if ($sPart == 'base') {
$pageURL = preg_replace("/(https?://(.+?/))[^/]+?.[^/]+?$/i", "$1", $pageURL);
}
return $pageURL;
}
// type: 0=info; 1:warn; 2=err;
function getDebug($type = -1, $limit = 10, $dateLimit = true) {
$aRet = array();
$sqlType = '';
if ($type != -1) {
$sqlType = ' and type=' . $type . ' ';
}
$sqlDate = '';
if ($dateLimit) {
$date = date('Y-m-d H:i:s', strtotime('120 seconds ago'));
$sqlDate = ' and date > '' . $date . '' ';
}
$sSQL = 'SELECT `date`, message, type FROM debug_log WHERE 1 ' . $sqlType . $sqlDate . ' ORDER BY `date` DESC LIMIT ' . $limit;
#print $sSQL.'
';
//Log::warn('SQL: '.$sSQL);
$oRs = Db::query($sSQL, false);
while ($row = Db::fetch_assoc($oRs)) {
//print $row['id'].'
';
$l = new Log();
$l->date = $row['date'];
$l->message = $row['message'];
$l->type = $row['type'];
$l->ip = $_SERVER['REMOTE_ADDR'];
$aRet[] = $l;
}
return $aRet;
}
function sendMail($message, $subject = 'Error in you website') {
$m = new Mail();
$m->message = $message;
$m->to = 'jb@front-it.com';
$m->subject = $subject;
$m->sendMail();
}
}
And the way you implement this is
// global.php
function myErrorHandler($errno, $errstr, $errfile, $errline) {
// Do something other than output message.
// Read more about the constants here http://php.net/manual/en/errorfunc.constants.php
// 8: E_NOTICE (integer)- Run-time notices. Indicate that the script encountered something that could indicate an error, but could also happen in the normal course of running a script.
// 2048: E_STRICT (integer) - Enable to have PHP suggest changes to your code which will ensure the best interoperability and forward compatibility of your code.
// You can decide which errors you want sent here
if ($errno != 2048 and $errno != 8) {
Log::warn('Error: ' . $errno . ' - ' . $errstr . ' * ' . $errfile . ' ln: ' . $errline);
}
return true;
}
set_error_handler("myErrorHandler");
// And if you just want to create a log entry you can do that by typing
Log::info('My message: ' . $someData);
Log::warn('My message: ' . $someData);
Log::err('My message: ' . $someData);
WARNING! Be careful if you use the error or warning log in a place where you can end up in a loop. This might cause the application to spam your inbox and I even have had google block my account for a period of time due to a flood of log mails. So be careful. This is one of the reasons I want to add a ticket system on top of the log in order to skip the mails and only send one mail even if an error occurs many times.
- framework, php, log, test, software