Logging

by Nickr5
A convenient and easy-to-use logging system for DM.
ID:106449
 
Since people began using BYOND, many games have been plagued with an information problem. Is yours one of them?

The problem is not a lack of information, but rather too much of it. It arises from an idea that is innocent enough - a game developer just wants to know what's going on in his game. Maybe, for example, to keep track of each battle that happens. So let's say our developer's first idea is to send out a message whenever someone performs an attack.
mob/verb/attack(mob/M as mob in oview(1))
usr << "You attack [M]!"
var/damage = rand(1,10)
world << "[usr] attacks [M] for [damage] damage!"
M.HP -= damage

He tests out the code with some friends and is delighted to see that he finds out every time someone is attacked. But soon players start complaining that their chat window is being filled up with useless information about other player's battles! Even the developer realizes that most of the time, he doesn't care about the battle. And annoyingly, whenever he logs out, he loses the whole record!

Once he realizes that there must be a better solution, our developer - being the diligent and studious programmer that he is - goes straight to the DM Reference. There he finds information on a useful var - world.log. With this, he can record a message along with the messages the BYOND may send (like runtime errors) without sending it to the whole world!
mob/verb/attack(mob/M as mob in oview(1))
usr << "You attack [M]!"
var/damage = rand(1,10)
world.log << "[usr] attacks [M] for [damage] damage!"
M.HP -= damage

As a bonus, he can set world.log to a file name and have all the messages saved to a file to be read later even if he leaves the game.
world.log = "log.txt"

This works so well that the developer forgets about it for a while and goes about adding more features to his game. One morning, however, he logs into his game's ad-infested, eyeache-inducing, free PhpBB forums and finds that one player is very upset because another one has been calling him horrid names. The other player denies it. The owner decides that the second player can't be punished because there's no proof he did anything wrong. But he thinks it would be best to keep a chat log to prevent this from happening again. So, he has the game write to the log again, just like he did for the battle log:
mob/verb/say(msg as text)
world << "[usr]: [msg]"
world.log << "[usr]: [msg]"

That solves that problem, but soon he hears reports of 10 different admins (nearly a quarter of them!) abusing their powers. To keep track of what they're doing, the developer also writes to the log whenever they perform an administrative action - like banning, kicking, or muting.

This alls seemed like it would work fine, but eventually he takes a look at the log file. It looks something like this:

someGuy logged in.
naruto930284738302392032893820490283 attacked naruto930284738302392032893820490284 for 1 damage!
xXYoMamaXx logged in.
lulz kicked someGuy.
someGuy logged in.
naruto930284738302392032893820490284 attacked naruto930284738302392032893820490283 for 2 damage!
runtime error: No put usr in proc. Ungh.
proc name: GiveSuperPowers (/mob/proc/GiveSuperPowers)
source file: naruto.dm,70
usr: null
src: lulz (/mob)
call stack:
lulz (/mob): GiveSuperPowers()
lulz kicked someGuy.
someGuy logged in.
naruto930284738302392032893820490283 attacked naruto930284738302392032893820490284 for 3 damage!
someGuy: hey stop it.
bleach930284738302392032893820490285 attacked naruto930284738302392032893820490283 for 4 damage!
lulz kicked someGuy.
SuperGoku9001 logged in.
xXYoMamaXx: stop abusing!
lulz banned xXYoMamaXx.
naruto930284738302392032893820490284 attacked naruto930284738302392032893820490283 for 5 damage!
someGuy logged in.
someOtherGuy logged in.
someOtherGuy attacked SuperGoku9001 for 0 damage!
someGuy: hey
naruto930284738302392032893820490283 attacked bleach930284738302392032893820490285 for 6 damage!
someOtherGuy: hi
lulz banned someGuy.
SuperGoku9001 attacked someOtherguy for 99999999999999999999999 damage!
lulz banned bleach930284738302392032893820490285.
naruto930284738302392032893820490284 attacked naruto930284738302392032893820490283 for 7 damage!
lulz banned naruto930284738302392032893820490283.
runtime error: No put usr in proc. Ungh.
proc name: GiveSuperPowers (/mob/proc/GiveSuperPowers)
source file: naruto.dm,70
usr: null
src: SuperGoku9001 (/mob)
call stack:
SuperGoku9001 (/mob): GiveSuperPowers()
lulz banned someOtherGuy.
SuperGoku9001 banned lulz.
naruto930284738302392032893820490284 attacked the sheep for 8 damage!
SuperGoku9001 unbanned someGuy
The cat attacked naruto930284738302392032893820490284 for 9 damage!
naruto930284738302392032893820490284: darn it
SuperGoku9001 unbanned someOtherGuy.
naruto930284738302392032893820490284 logged out.
someGuy logged in.
SuperGoku9001: wb
The sheep attacked someGuy for 10 damage!
someOtherGuy logged in.

You get the idea - it's not the easiest thing to read through. Plus, wouldn't it be nice to know when all of this happened? The game developer decided that he needed a better way to organize his log in order to be able to find out what happened, when, and who did it to whom.

An Introduction to n_Log (Finally!)


So by now (assuming you were good and didn't skip the first section of the article) you're probably wondering how to solve this information plague. The answer (or at least one answer) lies with the n_Log library. What does it do? A few things actually. First it provides procedures that let you easily write to and categorize a log. Things like the date and time are automatically recorded so you don't have to worry about them. Second, by default, it writes your log entries to a structured XML file. If you don't know what that is, don't worry! The library comes with a windows application that will let you view the log - without making your eyes bleed!

Rolling Logs


The library is pretty simple to use. To log a message, just do this:
record(notes = "Hello, world!")

Now let's go back to an example of a say verb.
mob/verb/say(msg as text)
msg = html_encode(msg) // prevent the user from messing with the log... or other users!
world << "[usr]: [msg]"
record( action = ACTION_SAY,
user = usr.key,
notes = msg )

ACTION_SAY just categorizes the log message. See the library's documentation for other built-in actions. The user argument logs which user did the speaking. This might seem like a little extra unnecessary code right now, but don't worry - it will pay off later.
For one more example, consider the attack verb. There is no ACTION_ATTACK - what do we do? This isn't a problem, an action is actually just text. So we can just pass "Attack".
mob/verb/attack(mob/M as mob in oview(1))
usr << "You attack [M]!"
var/damage = rand(1,10)
record( action = "Attack",
user = usr.key,
target = M.key,
notes = "[damage] damage" )
M.HP -= damage

Notice that the record() proc takes a target parameter for logging which player something happened to, but all four parameters are optional.
If you get these examples running and do some fighting and talking, you'll notice a 'log.xml' file in the dmb folder. When you open it up, it might look even worse than the log you saw earlier! But that's just because you don't have the right tool yet...

The Log Viewer Application


In order to use the Log Viewer program, go and download n_Log if you haven't already. In Dream Maker, make sure the 'Show All Files' checkbox is checked, expand the 'LogViewer' folder, and double-click 'LogViewer.exe'. Then select File > Open, and find the log.xml file that the library created. The viewer should load the file and look similar to this:

You can hide and reorder columns to your liking by using the Options menu and by clicking and dragging the headers. Notice that the library logged the date and time for every event automatically. Also notice that now you can sort through all of the events by left-clicking a column header. You can already see how it's a great deal more flexible than an ordinary log file. Finally, you can right-click the top of a column to make a textbox appear at the bottom of the window. There, you can filter the columns. For example, if you right-click 'User' and type your key into the box, you will see only the actions that were performed by you. Also the * character is a wildcard, so entering *om* will show Tom, Dantom, Tommy, Mom, etc.

You can have more than one column filtered at a time. So if you filter the Action column for 'Ban' and the User column for 'Dan', you will see all of the times Dan banned someone (similarly if you filter the Target column instead of the User column, you can see all of the times Dan has been banned). See the program's help menu for more information on the Log Viewer app.

Advanced Functionality


The n_Log library holds a few more secrets. For example, you don't have to log to an XML file. Of course, if you don't then you'll lose the ability to read the logs with the Log Viewer.
// For some outrageous reason, /output/default is not (usually) the output type used by default!
logger.SetOutput(new/output/default(world))

The code above makes the record() proc log to the world basically as if you were doing world << "message".

One last problem to solve: have you ever sent debug messages out to the world for debugging, and then accidently forgotten to remove them before having players try your game? The n_Log library provides a debug() proc for this purpose:
debug("message")

But the catch is that it is only defined when the game is compiled in DEBUG mode. Otherwise you'll get a compiler error telling you to get rid of your debugging message!
Read the first half, skimmed the rest. Sounds interesting, and this probably saves me a day or two of work on just about the same thing I was gonna add to my games. Nice work. :)
Why not use DM to make the log viewer?
It would be awesome if the log files saved as a excel sheet by default.
Flame Sage wrote:
It would be awesome if the log files saved as a excel sheet by default.

What the heck?
Airjoe wrote:
Flame Sage wrote:
It would be awesome if the log files saved as a excel sheet by default.

What the heck?

What the heck do you mean what the heck?
Why would you ever want logfiles in an excel spreadsheet?
Is this not almost exactly what this is?

http://www.byond.com/members/Nickr5/files/ map%20Screenshot%20-%2012_28_2010%20%2C%203_40_37%20PM.png

Or a database, or some kind of way we can easily manipulate the log files for the purpose of clarity / curling.
It's called plaintext, and its the preferred format for logging for a reason. Be glad this gives you XML (though personally I think that's silly).
True. I didn't realize it also generated XML. As long as it can output to another format that we can import elsewhere, it gets a gold star in my book!

Thanks for this awesome library. I'll be sure to use it for my upcoming project.
Saves me a lot of work, was just about to start working on my own log system when I saw this post.
Why not use DM to make the log viewer?
Because BYOND skins are a pain to use (particularly compared to windows forms) and I would have ended up spending more time working for a worse product.

It would be awesome if the log files saved as a excel sheet by default.
Adding a .csv output format would be extremely easy. I think I originally meant to write a section on creating new outputs, so I might update the article with a csv logger at some point.

It's called plaintext, and its the preferred format for logging for a reason.
The library includes a plain text output format, though it's probably not worth using just for that. The only gain would be automatic timestamps, while the output isn't as nice and easy to read as a simpler solution would be.
The only thing missing from this post is the suggestion not to log every punch, kick, etc. (It was hinted at when saying developers log too much.) I can only imagine how quickly that XML file would grow.
Kuraudo wrote:
The only thing missing from this post is the suggestion not to log every punch, kick, etc. (It was hinted at when saying developers log too much.) I can only imagine how quickly that XML file would grow.

lol, making a rand() wouldnt work werry well at this purpose :/ It is a reason why they log everything XD
The easiest way to log in my opinion, is to make a log folder, then use different log-files to diferent usages.
files as:
AtkLog.xml
GMLog.xml
verbLog.xml
etc.


Anyways... idk why u used oview(1) in the attack verb, ether u had short time or just thought it would give its meaning. get_step(usr) would be more intresting though XD