Implementing: LogWrite()

[John Adams]

Yo Scat, linux seems to be puking on this. I think it's the logging mutex?

Sat Sep 8 02:51:14 MST 2012 World crashed.
Sat Sep 8 02:51:16 MST 2012 World crashed.

eq2dev@eq2dev:~/bin/world$ gdb current_world
(gdb) r

Starting program: /home/eq2dev/bin/world/current_world
[Thread debugging using libthread_db enabled]

Program received signal SIGSEGV, Segmentation fault.
0xb7f7f6d5 in std::string::assign(std::string const&) () from /usr/lib/libstdc++.so.6
(gdb) bt
#0 0xb7f7f6d5 in std::string::assign(std::string const&) () from /usr/lib/libstdc++.so.6
#1 0x080d771b in std::string::operator= (this=0x836dd00, in_name=...) at /usr/include/c++/4.4/bits/basic_string.h:506
#2 Mutex::SetName (this=0x836dd00, in_name=...) at ../common/Mutex.cpp:106
#3 0x080d1c1e in LogStart () at ../common/Log.cpp:244
#4 0x080d1e24 in LogQueueAdd (log_type=DATABASE__INFO, text=<value optimized out>, len=<value optimized out>, cat_text=0x8303c42 "DB") at ../common/Log.cpp:290
#5 0x080d2027 in LogWrite (type=DATABASE__INFO, cat_text=0x8303c42 "DB", fmt=0x82f3b1c "Using database '%s' at %s") at ../common/Log.cpp:330
#6 0x080f555a in Database (this=0x836ffc0) at ../common/database.cpp:99
#7 0x08275583 in WorldDatabase (this=0x836ffc0) at WorldDatabase.cpp:65
#8 0x08261d50 in __static_initialization_and_destruction_0 () at World.cpp:63
#9 global constructors keyed to master_quest_list () at World.cpp:2268
#10 0x082eda8d in __do_global_ctors_aux ()
#11 0x080cafdc in _init ()
#12 0x082eda29 in __libc_csu_init ()
#13 0xb7b22b74 in __libc_start_main () from /lib/tls/i686/cmov/libc.so.6
#14 0x080cbe51 in _start ()
(gdb)

[John Adams]

Holy crap, I fixed something.

Scat, this was the problem on Linux, apparently (?)

Code: Select all

mlogqs.SetName("log queue");

I changed this to -

Code: Select all

mlogqs.SetName("logqueue");

(removed the space)

And it's running now. WTF?

[Scatman]

That's strange. It was working fine on my linux box. I wonder why it didn't like that...

[Scatman]

So this isn't a problem with Mutex. If you keep following the backtrace down you'll see it came from the Database() constructor. Since we're reading database configs in the database constructor, that Database object got created before memory was even allocated for the mutex variable, hence a crash. This is a race condition and the fix is to take the config reading out of the constructor and put it into it's own function because it shouldn't be there anyway.

[John Adams]

Okay, Scatman has finished every annoying added-on tweak I could possibly dream up Thank you, Scattie! This means it's time to update all the other loggers in the system to the new format ( with level=# ) so please, as you are adding new LogWrites(), decide at what level (0 - 9) you want your log to show up - with 0 being minimal logging and 9 being hella spammy.

I'd also like to ask you guys who are putting printf()'s in to "troubleshoot" to stop taking them out, unless they are completely unnecessary. Logging helps with debugging, so the more logging we have, the less buggy our server is. I certainly understand during development, you may need to printf("here I am!") just to see how code works. Obviously, those are not the kind of loggers I wish to keep.

More like, when you are outputting data or entering/exiting a function, or spitting out what a packet might contain - those are things I would like to try and preserve.

BUTT!

Before you start adding logs yourself, allow me a few weeks to beat the living shit out of this queued logging concept to see if I can break it. I will be loading Process functions up with enter/exit trace logging and running world with a few clients to see who dies first; EQ2World, or my dev box

[Scatman]

Sounds fun

[John Adams]

Just a quick follow up to the Log Queuing enhancements. I have to say, WOW they rock! I haven't done any performance testing, but EQ2TC ran crazy with all logging enabled during a players session, and not only did the world survive, but the logging looks awesome. Cannot wait to start adding more loggers now Maybe we can finally trap the Loot issues.

Check it out. Great job as always, Scatman!

[alfa]

In log I see

18:14:14 D PVP: PVP is: Disabled.

It log that cause you try to cast à aggressive spell when targeting Group Member ?

[John Adams]

In log I see

18:14:14 D PVP: PVP is: Disabled.

It log that cause you try to cast à aggressive spell when targeting Group Member ?

No, that is just a generic logger inside the AttackAllowed function that I was using to test the new Rules for PVP.

PVP is nowhere near implemented, but the Rule that is in place does allow players to attack one another in a simulated PVP fashion

Note: "R_World:AllowPVP" rule was never committed to the DB, because I just didn't want anyone thinking PVP was available, but since Alfa is our only player, I'll go ahead and commit it now so I do not forget

[John Adams]

Scat, I may have figured out a simple way to see the crash I am getting when a logging app terminates. I had mis-configured my Parser to a non-existent database, and when it launches and goes into database.Init(), the result of course is a failed DB open, a logger event, and an "exit(1)". It is on the exit that the app is crashing, without seeing the log entry.

Does that make more sense?

PacketParser, right at main(), the line in database.cpp I am crashing on is:

Code: Select all

	if (!Open(host, user, passwd, database,port, &errnum, errbuf)) 
	{
		LogWrite(DATABASE__ERROR, 0, "DB", "Failed to connect to database: Error: %s", errbuf);
		HandleMysqlError(errnum);
here->	exit(1);
	}

[Scatman]

Ahh. That makes more sense. I'll take a look into it.

[John Adams]

Well, crap. I am just flip-flopping all over like a fish out of water here. Our constantly changing log_config.xml file is getting changed, yet again. SORRY!

I thought I was making things simpler by putting examples in and keeping the file LEAN and MEAN, but every time I go to test something, my fookin logger is off and it pisses me off so I will fix this soon. I'll re-add all loggers old-school and stop fiddling with it.

I promise.

[John Adams]

Hey, I waited a year to fiddle again but this is a good fiddle.

I've added a function to the Logging System you can use to check what current "level" the logger is set to.

Example (log_config.xml):

<LogConfig Category="WORLD">
<ConfigType Type="DEBUG" Level="3" Color="GreenBold" Enabled="True" Logs="3" />
</LogConfig>

In your code, if you wanted to perform an operation based on the dynamic logging level, you could check it like this --

Code: Select all

if( GetLoggerLevel(WORLD__DEBUG) >= 3 ) { // do stuff }

We already have levels in-line for Logging itself, but in a case I was working on in Login I needed different outputs based on what debug Level I was at... so, added this very simple check.

See it in action in the new uploaded EQ2Minilogin.exe, where you can set the LOGIN__DEBUG level to 1 or higher, and the OP_Unknown's will print to your console without having to mess with the code. If LOGIN__DEBUG = 0, you won't see it. Etc.

Not sure it will have any use anywhere else, but it's something I've been meaning to do for some time.