Logging

The other day I was doing some php development on those "new technology experience projects" of mine. Then I've got a itch to scratch. Basically I needed to write a debug log from my php script to see what I was doing wrong. After some googling it turned out to as a best solution to use the file_put_contents function. I have added several of my own tricks to make it kind of better, because I didn't like the idea of having more file_put_contents statements in my source than actual code. That neat xml,xsl thingie came in naturally. The simpletest+xml is a interesting idea to explore later.

source modifications

Here are explained the conventions which have to be maintained to utilize the tools described later.

command

Use a statement which contains a time stamp, source, session and level of the log message. This is easily accomplished by using something like the line below. The colon is used as a field separator.

<?php
file_put_contents ( LOG_FILE, date("ymdHis").":".__FILE__.":".__FUNCTION__.":".__LINE__.":ERROR:".$_SESSION['uuid'].":login ".$login." does not exist!\n", FILE_APPEND );
?>

This lenghty file_put_contents can be folded into a simple "macro" which is then expanded by a sed command (see below the fold/unfol). Yes it is the idea of define in c.

<?php
debug_log ( "ERROR:login ".$login." does not exist!\n");
?>

parsing helper

At the end of every function/method/class add to the closing curly bracket the info about the closed function/method/class. In the example below it is the line } /* function confirmLogin */

<?php
    function confirmLogin ( $login, $password ) {
    file_put_contents ( LOG_FILE, date("ymdHis").":".__FILE__.":".__FUNCTION__.":".__LINE__.":ENTER:".$_SESSION['uuid'].":login=\"".$login."\", password=\"".$password."\"\n", FILE_APPEND );
    if ( !loginExists($login,DB_PATH_USERS)    ) {
    ...
    return true;
} /* function confirmLogin */
?>

tools

unfold debug_log

You can use a debug_log kind of macro which will be then expanded to a full blown file_put_contents because of the readability. Having a lot of those FILE, LINE etc. variables is quite messy and a pain to read.

sed -i -e 's!^\([^\s]*\)debug_log\s*(\s*"\(.*\));$!\1file_put_contents ( LOG_FILE, date("ymdHis").":".__FILE__.":".__FUNCTION__.":".__LINE__.":\2, FILE_APPEND );!g' *.php

fold debug_log

This is the sed command to fold that bloated file_put_contents into a neat debug_log statement.

sed -i -e 's!^\([^\s]*\)file_put_contents\s*(\s*LOG_FILE, date("ymdHis").":".__FILE__.":".__FUNCTION__.":".__LINE__.":\(.*\),\s*FILE_APPEND\s*)\s*;\s*$!\1debug_log ( "\2);!g' *.php

disable debug

The debug messages can be easily commented out by a simple sed command so there will be no debugging in the "production" code. You can run this on a whole subtree of files commenting out the debugging in the whole sources. Or selectively for given sources.

sed -i -e 's!^\(\s*[^/]\s*\)file_put_contents\s*(\s*LOG_FILE\s*,!\1// file_put_contents ( LOG_FILE,!g' *.php

enable debug

If you ever need the debugging messages again just run the sed command below and your debugging messages are back. Again can be done selectively for given files.

sed -i -e 's!^\(\s*\)//\s*file_put_contents\s*(\s*LOG_FILE\s*,!\1file_put_contents ( LOG_FILE,!g' *.php

fine tune granularity

You have marked the end of the function body. So you can use sed to remove/restore debugging messages on a function level. Admitted if I woudn't be lazy I could do the "body" parsing by a script (and so I wouldn't need the special markup at the end of the function/class/whatever) but for my purposes it's enough.

sed -i -e '/function\s*confirmLogin/,/}\s*\/\*\s*function\s*confirmLogin\s*\*\//s!^\(\s*\)//\s*file_put_contents\s*(\s*LOG_FILE\s*,!\1file_put_contents ( LOG_FILE,!g' *.php

make xml debug

The debug is simple and easy to read but you can have it fancier if you wish. Just run the awk script below and get a nice xml output. To get a xml compliant output you have to extend probably the sed command to replace all xml restricted characters with metas. You can use for example xmllint to format the outputted data to get a nice xml.

echo '<?xml version="1.0" encoding="ISO-8859-1"?>'
echo '<?xml-stylesheet type="text/xsl" href="application.xsl"?>'
echo '<debug>'
sed -e 's!&!\&amp;!g' \
    -e 's!"!\&quot;!g' \
    -e 's!<!\&lt;!g' \
    -e 's!>!\&gt;!g' \
    -e "s!'!\&apos;!g" application.log |\
awk -F: '{print "<entry number=\""NR"\">\n\t<timestamp>"$1"</timestamp>\n\t<file>"$2"</file>\n\t<function>"$3"</function>\n\t<line>"$4"</line>\n\t<level>"$5"</level>\n\t<session>"$6"</session>\n\t<message>"$7"</message>\n</entry>"}'
echo '</debug>'

make xsl2html

The xml which you get from above can be then transformed into a html output. I'll do a simple table where the lines containing the ERROR keyword will get a red background. This transformation is referenced in the xml file as application.xsl

<?xml version="1.0" encoding="ISO-8859-1"?>
<xsl:stylesheet version="1.0" xmlns:xsl="http://www.w3.org/1999/XSL/Transform">
<xsl:output method="html" encoding="ISO-8859-1" indent="yes" />
 
<xsl:template match="/">
<html>
    <body>
        <table>
        <xsl:apply-templates/>
        </table>
    </body>
</html>
</xsl:template>
 
<xsl:template match="entry">
<tr>
    <xsl:if test="level='ERROR'">
        <xsl:attribute name="bgcolor">red</xsl:attribute>
    </xsl:if> 
    <td><xsl:value-of select="timestamp"/></td>
    <td><xsl:value-of select="message"/></td>
</tr>
</xsl:template>
 
</xsl:stylesheet>

test the xml

The generated xml can be used with simpletest for testing. (will do … sometime)

Unless otherwise stated, the content of this page is licensed under Creative Commons Attribution-Share Alike 2.5 License.