Yzis Log System
From Yzis Wiki
Yzis uses a flexible powerful log system.
Contents |
Generic description of the log system
Many developers take debugging as a kind of printf. They put a lot of printf code during debug and then comment it once the code is supposed to be working. This has several drawbacks:
- when you need to debug a specific area, you need to uncomment a lot of stuff
- if you want to debug a program which you can not control (on somebody else computer), you can not have the debug log
- you get either too much logs because there is too much debug statements, or not enough information because the debug statement have been kept minmal.
The proper way for good debugging is a good log system. The log system of Yzis has several features:
- output can be sent to file, stdout, stderr
- 5 log levels: deepdebug, debug, warning, error and fatal
- the debug log can be assigned to areas and subareas
- each area can have its own log level, indepandentely of the others.
- the log level areas can be controlled dynamically, either with a .yzdebugrc file or with command line arguments.
With such a system, the developers are encouraged to put as much information as possible in the debug log, knowing that they can easily disable or enable it when necessary.
Having a lot of precise debug log allows to follow Yzis execution path very accurately and is very practical to learn what Yzis is doing and how.
Taking advantage of the log system in the code
On the code side, using the log system is quite simple.
call YZSession::initDebug()
Each frontend should call YZSession::initDebug( argc, argv ) as early as possible to get logging into activity. The function is static and does not depend on anything being initialised priori to it.
Have log shortcuts
Each cpp file should have shortcuts to calling log functions, with a proper area:
Example:
#define dbg() yzDebug("YZSession")
#define err() yzError("YZSession")
Prefix the log output with the function name
When using the log functions, always prefix them with the name of the current function being executed.
A very good practice is to log the current function call with every argument as the first thing in the function, and then only to log more stuff. This makes the whole log file a lot easier to understand. The idea is that you can follow the code execution with the log file.
Example:
QString YZResourceMgr::findResource( ResourceType type, const QString & fname )
{
dbg() << "findResource(" << type << ", " << fname << ")" << endl;
// [...]
foreach( QString candidate, dirCandidates ) {
resource = candidate + fname;
dbg() << "findResource(): looking up " << resource << endl;
if (QFile::exists( resource )) {
dbg() << "findResource(): Found at " << resource << endl;
return resource;
}
// [...]
}
Log output:
YZResourceMgr:findResource(ConfigResource, yzis.conf) YZResourceMgr:findResource(): looking up C:/Documents and Settings/User/.yzis//yzis.conf YZResourceMgr:findResource(): looking up d:/program/yzis/share/yzis//yzis.conf
If you just want to log the fact that a given line of code was executed, the macro HERE() returns the file:line and function name information.
Example:
void YZLuaEngine::cleanLuaStack( lua_State * L ) {
lua_pop(L,lua_gettop(L));
dbg() << HERE() << " done" << endl;
}
Will generate the following log:
YZLuaEngine:static void YZLuaEngine::cleanLuaStack(lua_State*):188 done
Generate intelligent log for your own types
If you are using an enum, please provide an output function to display a string for that enum.
Example:
enum ResourceType {
UserScriptResource,
ConfigScriptResource,
IndentResource,
SyntaxHlResource,
ConfigResource,
WritableConfigResource,
};
YZDebugStream& operator<<( YZDebugStream& out, const ResourceType & type )
{
switch( type ) {
case IndentResource: out << "IndentResource"; break;
case SyntaxHlResource: out << "SyntaxHlResource"; break;
case ConfigScriptResource: out << "ConfigScriptResource"; break;
case UserScriptResource: out << "UserScriptResource"; break;
case ConfigResource: out << "ConfigResource"; break;
case WritableConfigResource: out << "WritableConfigResource"; break;
}
return out;
}
The above code is what allows the following code to generate a text output for type instead of an decimal value:
QString YZResourceMgr::findResource( ResourceType type, const QString & fname )
{
dbg() << "findResource(" << type << ", " << fname << ")" << endl;
Output example:
YZResourceMgr:findResource(ConfigResource, yzis.conf)
More is better than less
It is better to log more than less, and to log with the maximum level of detail if you can. You should be thinking in terms of "How can I make sure that I can diagnose a bug just with a log file ?"
If you are afraid that too much log lines will be generated, use deepdbg(). By default, deepdbg() stuff is not logged, but this can be changed with a command line option (qyzis --level=deepdebug).
Using the log when running Yzis
To configure the log level that you want, and where the log stream should go, check the documentation of YZDebugBackend::parseArgv() and YZDebug::parseRcFile().
If yzis is built in release mode, the default level is Warning, and no stream is defined (no log is written anywhere).
If yzis is built in debug mode, the default level is Debug and the log are saved in a temporary file (usually in /tmp).
(See Build Yzis for more information about release/debug modes)
An example of how to control the log level:
nyzis --level=deepdebug --area-level=YZLuaEngine,debug --area-level=YZSession,debug --debug-output=~/tmp/yzis.log
You can achieve the same effect with a file .yzdebugrc in the current directory containing:
level: deepdebug YZLuaEngine: debug YZSession: debug
To watch the debug log on windows, the best thing is to launch debugview from DebugView
On linux, the best way to watch the debug log is:
tail --follow=name -s 0.2 /tmp/yzdebug-[your user name].log
