Task: Logging Improvements

[John Adams]

Since our Logging is not as good as it can be, and we have a couple new folks interested in getting their feet wet in C++ (including myself), I propose we tackle some logging improvements in the Server (and loginserver) code.

We're not really implementing any major systems, and bug hunting would be tons easier with proper logging... so what do you think? If you're game, we can discuss what we want to do here and get started.

A few things I'd like to see first:

• - Finish converting all printf/cout statements to pass through the log system
  - Finish implementing proper "categories" like Info, Debug, Error, Fatal, etc.
  - Implement the use of log.ini, though this can be done later as long as we're considering it during development
  - Convert the raw HEX output to human-readable logging

This last one will probably be the hardest, but I feel it must be done. Too many times I see a player doing something that causes an error (which just says, "Error doing ____") and i can not interpret, easily, what it is they were doing.

I would like the option to disable DEBUG/ERROR logging entirely if I want, and generate logging at different levels for things like INFO, or Debug... ie., if in debug level 1, only show critical debug info, but if at level 5, log every freakin thing that's happening (which I know will slow down the world, but that's ok - we're debugging).

Just some ideas to get us started, with converting printf/couts being #1 on my list of wants. Ie., anything that outputs to the console screen needs to end up in a txt log somehow...

Anyway, let me know what you think. Getting a good, solid logsys in place now means future development will be made a whole lot easier, imo.

[John Adams]

Some places where I suggest we can improve our situation:

eq2emu_error_world.log

Code: Select all

3032 [20100701 20:28:37] Error LUA spell ''
3032 [20100701 20:28:37] Error LUA spell '.lua'

This would be a nice place to also put what spell (name/id) is being attempted, and by whom (char, account + target)

Code: Select all

3032 [20100702 09:03:55] Error, command index of 999 was requested, but max command is 472

I don't even know what this error message is. Likely a UI command pushed to the server that is not yet handled, so we burp out this error. How about the name of the command attempted so we can start building handlers?

Code: Select all

3032 [20100702 10:00:09] Unknown Index: 0

Unknown Index, of what?

Code: Select all

2184 [20100715 10:28:53] Invalid bug list:
	Mechanics
	Combat
	Affects gameplay
	Sometimes Happens
	SapswillInvaders

Not really sure what this is... a bug submission that had invalid data? the invalid data would be nice to see here, in a better format. If there's an error submitting a bug, detailed logging could help still see what the bug is, so the players effort is not lost.

Code: Select all

2184 [20100723 16:38:30] HandleExamineInfoRequest: Unknown Item ID = 0

Not sure how we got this error, but maybe with player, slot, or what the world seems to think it was examining could help.

Code: Select all

2184 [20100724 16:50:02] Invalid parameters for AddSpellBonus.

What spell?

Code: Select all

2184 [20100724 19:59:49] Error in EQ2Emu_lua_Zone: invalid zone or spawn input.

What zone? What lua script? What spawn? If this is generic, maybe we could break the single error about zone OR spawn into 2 separate errors, so we can provide additional data in the error message.

Code: Select all

3952 [20100725 18:43:10] Unknown examine request: 126
3952 [20100725 18:43:13] Unknown examine request: 206

Again, no idea what this is. Maybe who it is, slot, what is being examined, etc.

Code: Select all

3952 [20100725 18:43:16] Invalid ZoneAuthRequest, disconnecting client.

Who had invalid ZoneAuthRequest, and what zone, from where to where? etc...

You get the idea These are the errors I found in TessEQ2's logs so far. More to come as we create new log entries, I am sure.

[John Adams]

Here is an example of a Console Output that is currently not being filtered through the Log System (does not end up in a text file anywhere), and how poorly formatted it is. This data probably should only be on in DEBUG mode, since it's a ton of data otherwise.

Code: Select all

[20100822 22:53:45] [Debug] Zone Killing 'a Morak mangler'
   0: 09 01 00 00                                        | ....
   0: 09 01 00 00                                        | ....
   0: 09 01 00 00                                        | ....
   0: 22 00 06 00 32 33 30 30 - 30 32                    | "...230002
   0: 22 00 06 00 32 33 30 30 - 30 32                    | "...230002
   0: 22 00 06 00 32 33 30 30 - 30 30                    | "...230000
   0: 22 00 06 00 32 33 30 30 - 30 31                    | "...230001
   0: 22 00 06 00 32 33 30 30 - 30 30                    | "...230000
   0: 22 00 06 00 32 33 30 30 - 30 31                    | "...230001
   0: 22 00 06 00 32 33 30 30 - 30 30                    | "...230000
   0: 22 00 06 00 32 33 30 30 - 30 31                    | "...230001
   0: 22 00 06 00 32 33 30 30 - 30 30                    | "...230000
   0: 22 00 06 00 32 33 30 30 - 30 31                    | "...230001
   0: 22 00 06 00 32 33 30 30 - 30 30                    | "...230000
   0: 22 00 06 00 32 33 30 30 - 30 30                    | "...230000
   0: 22 00 06 00 32 33 30 30 - 30 31                    | "...230001

This is a command coming in from the Client to the server:

Code: Select all

0: 22 00 06 00 32 33 30 30 - 30 32                    | "...230002

The command is the first index mark (22h, or 34d) which is "useability", and the ability being used are the next values (32 33 30 30 30 32 hex, or 230002d). I am not sure what the 00 06 00 is - anyone?

Changing this single entry to something like:

PID [DATE TIME] [DEBUG] Useability: <player name> [char_id] used ability <ability name> [230002] on <target|targets>. [Success|Fail]!

• Results: <list of effects, and actual values>

PID: ProcessID of the world
Date/Time: yeah.
DEBUG: log mode
Useability: the conversion of the hex "22" via commands.handler value
Player Name: The player
char_id: Players characters.id value
Ability Name: Fire Chamber
Spell_id: 230002
Target(s): List single target name/id, or group of targets if AOE
Status: Success if it successfully cast, Fail if it did not (some people seem to get off on spamming the ability 200 times a second )
Results: List damage, buff, debuff, or whatever actual values applied to <target> on a separate line, indented.

If we can create a filter that converts hex to readable logging like this, we can shove a lot of stuff through it besides just abilities, cuz there are tons of commands so it probably won't be a simple task... but I have faith!

[Scatman]

That sounds like a good idea. This wouldn't be necessarily difficult to do. Just lots of work Did anyone take interest in doing this?

[John Adams]

I figured it might need to be a team effort, since it's so much work to plan and implement. But no, no one has leaped up just yet.

[Sylaei]

/em Raises hand! Ooh-ooh-ooooh!
(Horshack for those that remember. Google it, for those that don't. )

I'd be willin'. With the proper planning I think one person could code it. It would take a team to plan it.

A couple enums with the different error types. A function to take the hex and spit it out as char/string. Possibly using try/catch to grab all errors. I don't recall seeing any in the code but I didn't look at many .cpp files. Errors can be output in different colors to signify severity or other designations. Doesn't help much in the log file but might be useful in the world console.

I'm not sure I like the try/catch statements, haven't used them in cpp, but they do have the ability to recover from most errors without a crash.

(Need to make sure that linux will compile try/catch, but seems like it should.)

Just a couple ideas off the top of my head.


Just found this: http://www.codeproject.com/KB/cpp/exceptionlogging.aspx
It uses Macros, with possibly one spot to turn on or off the logging. Not saying we should use this, but the idea is intriguing.

[ilythor]

I'm interested, and willing to learn C++ if everyone else is diving into it too! Can at least plan, if time is of a huge essence.

I might be thinking about this in a round-a-bout-way, but if we implemented a database system for errors, that "auto-converts" the numbers into phrases that we can understand. For example you get a massive error burp from the system, and our "logging program" immediately enters this information as a query, then the report comes back as the actual error itself.

I think this differs from the other ideas, as it's a database. Or we could embed this into the logging/debugging program. An all in one fixer tool, me thinks.

[John Adams]

I'm not really looking for an error-trapping mechanism specifically, anything more than we already have in the code. What this task is about is merely cleaning up the existing logging system, finishing the conversions to printf/cout to the existing EQEmuLog system, and maybe once we're in there, expanding on the types that are available.

I recommend you review the debug.cpp file for how the existing system works. I'd also like it if we could look into either EQEmu, or EVEmu, because EQ2Emulator's logging is derived from EQ Emu's system, only missing about 1/2 it's functionality.

Also, I am not super-keen on using 15 different log files, and think every output should be into a single log file, governed by a log.ini, which allows us to turn on/off specific log entries based on Category:Type. There's nothing more annoying when trying to troubleshoot an issue than having 15 log files open and trying to match timestamps to see what's going on.


EQEMu: http://www.eqemulator.net/wiki/wikka.ph ... rverLogSys

The EVEmu has yet to document their logsys features, but they are also derived from EQEmu.



Ref: http://eq2emulator.net/phpBB3/viewtopic ... 02&p=11017 one of my original posts on the subject, probably more around this site.

I realize there are probably better ways to implement logging, and I am totally open to suggestions. But since this is what we (kinda) have already, I thought we could tackle this as a "learning experience" together, and see how far we can take it.

[Sylaei]

Ok with me. I agree that the error logging should be as robust as possible to speed dev. Lets plan and go from there.

[John Adams]

/bump

For those not working on other issues, or community members offering a hand but not sure where to start... this is a great project to "get your feet wet" so to speak.

Ask questions, discuss, let's see if we can get others involved in this cleanup effort. Scatman already implemented the new log system, now we just need to convert all cout/printf/hex_dump output to a cleaner log format.

[John Adams]

Bumping once again, and asking once again, for help with World logging. The LogWrite() system is defined and shouldn't be changing anytime soon unless a critical scenario presents itself.

This is a great way for non-Developers who are interested in C++ to dive in and get an idea of how things work in our code, AND help the project greatly.

The more logging, the more bugs we can identify.