Logging frustration

[pickardj79]

I am having trouble getting logging to work and I think there are some fundamental things I'm not understanding. Is is possible that logging is not initialized until some point and log messages before that point are lost to the internet ether? Is there a way around this?

More details...

I have sprinkled self::trace() calls through out my game.php, but the only log that shows in the "request&SQL logs" is when starting getAllData(). I see this line repeated periodically throughout the logs (requesting back 1000 lines). The log timestamps show periodic jumps which correspond to me starting new games. Each section in the logs (corresponding to one Express-start / Express-stop cycle) starts with "22/08 18:48:01 [info] [M] [2332172/pickardj0] /1/pickardjgt?table=1819332" and then ends with what I think is an ajax call: "22/08 18:45:29 [notice] [T188833] [2332172/pickardj0] OK-0 485 d1 c0 e230 m179 I483 A2 V0 T0 /1/pickardjgt/pickardjgt/notificationHistory.html?table=188833&from=2&privateinc=1&history=1&testuser=2332172&dojo.preventCache=15981146779842". Logs calls during setupNewGame and the other automatic "game" states do not show up. It's not until I'm getting player interaction that the logs start to work.

In an attempt to get around this by logging to the web console, I created a "logConsole" notif with a handler that just does a "console.log(notif);". This exhibits the same behavior. Log messages fired before a player action disappear (though will err if there's a badly formatted string) but those after player action work fine.

[Victoria_La]

Where are looking? Do you click button [BGA request&SQL logs]? It very verbose, it is better probably to use exception log as log as "warn" level.

[pickardj79]

I've looked both places. Yes, [BGA request&SQL logs] is very verbose, but I do get all logs after a player action. Warn logs also do not work for me without a player action. :shrug:

[CuriousTerran]

I have had a similar logging frustration during the game setup phase. I have resorted to making a bad SQL call to have a logging string show up on the client side during setup to debug things. It unfortunately has the side effect of also killing the game, but it seems the only reliable way to get information out during setup for me.
For example
$str = 'Debugging info to display';
$this->DEBUG_with_badsql($str);

with function defined
function DEBUG_with_badsql($debug_str)
{
$sql = "INSERT INTO foo VALUES ('".$debug_str."');";
self::DbQuery( $sql );
}

This is very inelegant, but works.

[Victoria_La]

Ah, right where exactly you have logging? During game initialization notification system is not working yet for example, logging may not be initialized either.
If you have trouble with initialization I suggest to leave initialization barebone, just create the db tables and you can move table setup step into first game state, and this is easier to debug (also it can send notifications).

[pickardj79]

I guess it's during initialization. It's my code, but there hasn't been a player action yet, so I guess that's still initialization. It would be great if there were a a point in initialization where we could be sure logging was enabled. Like when entering setupNewGame(). Or after leaving that function.