LogWrite() - Advanced Options
Posted: Fri Oct 21, 2011 1:04 pm
In our last article, Logging - The Basics, we discussed the configuration and basic usage of the EQ2Emulator LogWrite functions. In this article, we'll get into some more granular config options and more complex examples.
EQDEBUG definition
In the common files folder is a header file: debug.h
Right at the top of this file is a definition for EQDEBUG - a hard-coded definition used by developers during compile time to cause different parts of the code to perform differently, based on it's value. You utilize EQDEBUG by performing #if checks on it's value like this:
The #if / #endif blocks
We recently implement logging Debug Levels as an added config option. The purpose of these additional debug levels is to give you just a little more control over what you want to see in your logging, without inventing dozens of otherwise unused Logger definitions. One example of this is the use of the ITEM__DETAIL logger.
Let's say you wanted to turn on ITEM__DETAILS to see a log entry whenever items in general were being loaded from the database - BUT - you did NOT want to see the individual ITEM__DETAILS for each single item being loaded. You could make separate logger definitions, but with Debug Levels, you can still use ITEM__DETAILS only. Here's how (this code is completely made up, for example only):
In this example, the SQL query runs, and if there are results (meaning it found Shield items to load), a simple logger fires off saying that you "Found some items to load!". So this level of detail is basic, no Debug Level requirements.
Inside the while() loop, you will notice the logger is wrapped inside an #if statement. This tells the compiler that if the definition for EQDEBUG is not greater-than or equal to at least "7", then ignore this logger completely.
Let's say in debug.h, you set EQDEBUG = 3. This ITEM__DETAIL entry would not output any log entries.
However, if EQDEBUG = 9, this logger would put out a detailed line every loop of the while().
You, as the designer of the log entry itself, must make the decision about at what level you want your log entry to show up. Always be conscientious of others when making this choice, since too much is not always better in the case of logging.
The "cat_text" parameter
In our LogWrite() command, the 2nd option is one called cat_text, or "category text". Again, it is there to give you even more control over what you want your logger to output. Let's say you want to see ITEM__DETAILS as explained above, but there is no SHIELD__DETAILS logger - there is no need to create one, because Shields are Items, so you can use the Items loggers - but in cat_text, you can define "Shields" if you wanted.
Note that the 2nd parameter changed from the above example from generic "Items" to "Shields". We're still using ITEM logger category, so this means the admin can turn on ITEM__DETAILS logging, and when Shields get loaded, the admin will see that detail in your log output:
The Logger Event - Formatted String output
This will probably be the place that bites you the hardest.
Simple Logger:
This is fairly straight forward. Just text outputted as it is passed through.
But our LogWrite function has the ability to behave like any other string formatter/parser, as long as the data being passed in matches the format you supply.
Complex Logger:
In this example, you see the top logger passing the item ID as determined by a value set in code (we'll get into that later).
The second logger, immediately following the first, can contain more detailed breakdown of the first. In this case, the item Type definition, and 2 values from the SQL query we are currently iterating through - in this example, low and high mitigation of a shield item. This is where things get more complex, but the more you dive into it, the easier it will become.
The biggest danger here is trying to pass invalid values into the string. This will usually cause the World to crash outright, or at least the zone that is running when the logger is encountered. An example of a BAD logger would be:
The "%s" tag represents a String value, but you are trying to pass an INT32 (id) into it. That is a no-no in C++. There are of course ways around that, but this isn't a C++ tutorial 
So be sure the values you are trying to pass match the string you are passing them to.
90% of your formatted string values will be values already calculated in code that you are just trying to log. There will be some cases where you want to pass new values, like a sum value, to the logger that is not in code - and you have to calculate it yourself. Again, all the formatted string functions like is just like a C++ printf() statement... meaning, you can pass variables, constants, functions, or calculations in-line.
Example - let's say you wanted to output how long (in seconds) it takes to load your items:
This is a perfect example to show a mixture of many types of data into a formatted string.
First you have a "total" value, which is being incremented each time an Item is loaded successfully (total++).
Then, you have an inline "if" to determine if 1 Item loaded, or many Items (meaning if the value was 0 or more-than 1, append an "s" to the word "Item" in the formatted string)
And finally, you have a function call to Timer::GetUnixTimeStamp() - t_now, to determine how much time has passed since you first set t_now, and "now".
This is definitely getting more complex, but you can see the power of the logging functions and how to get data to appear on the screen. One last advanced topic, and you'll be ready!
Where to send Log Entries
If you are using our pre-defined loggers in LogTypes.h, then where the output goes is already defined (ENABLED, ENABLED, ENABLED means Enabled logger, to file AND console).
Should you decide to create your own logger definitions though, you need to decide a) if it is enabled by default at all, b) does it go to File Only, or c) does it go to console only (or both)?
My recommendation is that any logger that puts out enough logging to render the console un-viewable, should be both disabled by default, and sent only to the File (text) log. Remember, any logger defined in code can be overridden in log_config.xml by the admin, without recompiling code. So don't be shy putting your loggers to sleep by default
A great example of really chatty log entries would be DATABASE__QUERY, which is disabled by default. If it were not, you would see every single SQL query the code performs (thousands upon thousands) in a normal run -- and it never stops to take a breath!
However, if I am debugging something wrong with a query (not getting my expected results), I would open log_config.xml, and find the DATABASE section, the QUERY item, and I would Enable that log entry. I would then change the default Logs option from 3 (file AND console) to be just 1 (file only). Enabling QUERY means I could not see the console screen data at all, so many queries would be zooming by. But piping DATABASE__QUERY output only to the File means I could review it in a text editor, while still seeing the other debug info in the console.
I hope these tutorials help reduce your fear of adding logging to our code.
EQDEBUG definition
In the common files folder is a header file: debug.h
Right at the top of this file is a definition for EQDEBUG - a hard-coded definition used by developers during compile time to cause different parts of the code to perform differently, based on it's value. You utilize EQDEBUG by performing #if checks on it's value like this:
Code: Select all
#if EQDEBUG >= {value}
...code to execute...
#endifThe #if / #endif blocks
We recently implement logging Debug Levels as an added config option. The purpose of these additional debug levels is to give you just a little more control over what you want to see in your logging, without inventing dozens of otherwise unused Logger definitions. One example of this is the use of the ITEM__DETAIL logger.
Let's say you wanted to turn on ITEM__DETAILS to see a log entry whenever items in general were being loaded from the database - BUT - you did NOT want to see the individual ITEM__DETAILS for each single item being loaded. You could make separate logger definitions, but with Debug Levels, you can still use ITEM__DETAILS only. Here's how (this code is completely made up, for example only):
Code: Select all
int32 WorldDatabase::LoadShields(){
(...sql query here...)
if(result){
LogWrite(ITEM__DETAIL, "Items", "Found some items to load!");
while(result && (row = mysql_fetch_row(result))){
#if EQDEBUG >= 7
LogWrite(ITEM__DETAIL, "Items", "Loading each item 1 at a time!");
#endif
}
}
}Inside the while() loop, you will notice the logger is wrapped inside an #if statement. This tells the compiler that if the definition for EQDEBUG is not greater-than or equal to at least "7", then ignore this logger completely.
Let's say in debug.h, you set EQDEBUG = 3. This ITEM__DETAIL entry would not output any log entries.
However, if EQDEBUG = 9, this logger would put out a detailed line every loop of the while().
You, as the designer of the log entry itself, must make the decision about at what level you want your log entry to show up. Always be conscientious of others when making this choice, since too much is not always better in the case of logging.
The "cat_text" parameter
In our LogWrite() command, the 2nd option is one called cat_text, or "category text". Again, it is there to give you even more control over what you want your logger to output. Let's say you want to see ITEM__DETAILS as explained above, but there is no SHIELD__DETAILS logger - there is no need to create one, because Shields are Items, so you can use the Items loggers - but in cat_text, you can define "Shields" if you wanted.
Code: Select all
int32 WorldDatabase::LoadShields(){
(...sql query here...)
if(result){
LogWrite(ITEM__DETAIL, "Shields", "Found some Shield items to load!");
while(result && (row = mysql_fetch_row(result))){
#if EQDEBUG >= 7
LogWrite(ITEM__DETAIL, "Shields", "\tLoading each Shield item 1 at a time!");
#endif
}
}
}Code: Select all
20:56:30 T Shields: Found some Shield items to load!
20:56:30 T Shields: Loading each Shield item 1 at a time!
20:56:30 T Shields: Loading each Shield item 1 at a time!
20:56:30 T Shields: Loading each Shield item 1 at a time!- Note that the "T" is the same value defined in LogTypes.h, for the type DETAIL.
The Logger Event - Formatted String output
This will probably be the place that bites you the hardest.
Simple Logger:
Code: Select all
LogWrite(ITEM__INFO, "Items", "This is an item.");But our LogWrite function has the ability to behave like any other string formatter/parser, as long as the data being passed in matches the format you supply.
Complex Logger:
Code: Select all
LogWrite(ITEM__DETAIL, "Items", "\tItem Shield for item_id: %u", id);
LogWrite(ITEM__DETAIL, "Items", "\ttype: %i, mit_low: %i, mit_high: %i", ITEM_TYPE_SHIELD, atoi(row[1]), atoi(row[2]));The second logger, immediately following the first, can contain more detailed breakdown of the first. In this case, the item Type definition, and 2 values from the SQL query we are currently iterating through - in this example, low and high mitigation of a shield item. This is where things get more complex, but the more you dive into it, the easier it will become.
The biggest danger here is trying to pass invalid values into the string. This will usually cause the World to crash outright, or at least the zone that is running when the logger is encountered. An example of a BAD logger would be:
Code: Select all
LogWrite(ITEM__DETAIL, "Items", "\tItem Shield for item_id: %s", id);90% of your formatted string values will be values already calculated in code that you are just trying to log. There will be some cases where you want to pass new values, like a sum value, to the logger that is not in code - and you have to calculate it yourself. Again, all the formatted string functions like is just like a C++ printf() statement... meaning, you can pass variables, constants, functions, or calculations in-line.
Example - let's say you wanted to output how long (in seconds) it takes to load your items:
Code: Select all
int32 t_now = Timer::GetUnixTimeStamp();
(...perform the sql queries and code to load all items...)
LogWrite(ITEM__INFO, "Items", "Loaded %u Total Item%s (took %u seconds)", total, ( total == 1 ) ? "" : "s", Timer::GetUnixTimeStamp() - t_now);First you have a "total" value, which is being incremented each time an Item is loaded successfully (total++).
Then, you have an inline "if" to determine if 1 Item loaded, or many Items (meaning if the value was 0 or more-than 1, append an "s" to the word "Item" in the formatted string)
And finally, you have a function call to Timer::GetUnixTimeStamp() - t_now, to determine how much time has passed since you first set t_now, and "now".
This is definitely getting more complex, but you can see the power of the logging functions and how to get data to appear on the screen. One last advanced topic, and you'll be ready!
Where to send Log Entries
If you are using our pre-defined loggers in LogTypes.h, then where the output goes is already defined (ENABLED, ENABLED, ENABLED means Enabled logger, to file AND console).
Should you decide to create your own logger definitions though, you need to decide a) if it is enabled by default at all, b) does it go to File Only, or c) does it go to console only (or both)?
My recommendation is that any logger that puts out enough logging to render the console un-viewable, should be both disabled by default, and sent only to the File (text) log. Remember, any logger defined in code can be overridden in log_config.xml by the admin, without recompiling code. So don't be shy putting your loggers to sleep by default
A great example of really chatty log entries would be DATABASE__QUERY, which is disabled by default. If it were not, you would see every single SQL query the code performs (thousands upon thousands) in a normal run -- and it never stops to take a breath!
However, if I am debugging something wrong with a query (not getting my expected results), I would open log_config.xml, and find the DATABASE section, the QUERY item, and I would Enable that log entry. I would then change the default Logs option from 3 (file AND console) to be just 1 (file only). Enabling QUERY means I could not see the console screen data at all, so many queries would be zooming by. But piping DATABASE__QUERY output only to the File means I could review it in a text editor, while still seeing the other debug info in the console.
I hope these tutorials help reduce your fear of adding logging to our code.