Centralise debug logging

[dreadnaut]

Originally reported on Google Code with ID 254

Currently, setting $debug=true creates a series of 'SQL' tags around the page, which
show more information on click, via javascript. The code to create these messages is
repeated here and there, mainly in the Database class.

I would like to:
- collect the output code in separate module
- collect the output itself in a continuous log, easier to scan and copy+paste for
error reporting
- remove the many occurences of "global $debug;" in the Database class

Attached below are:
- my idea of a Log class, which stores messages and produces a formatted log
- a screenshot of the code in action

Using this class requires minimal changes to the main code: adding 

  if ($debug) Log::start();

at the beginning and

  if ($debug) Log::output();

at the end. Existing debug output can be replaced with either

  Log::info(...)    adds a basic message
  Log::error(...)   adds a message highlited in red
  Log::query(...)   adds a query highlited in blue, using a monospace font
  Log::dump(...)    dumps the content of a variable in the log

I tried to keep the code very light, but we can reduce wasted cycles further guarding
the calls using

  if (Log::$enabled) Log::error(...);

or

  Log::$enabled  and  Log::error(...);


The code below also logs 'catchable' PHP errors, but does not produce output in case
of a FATAL error. I can work around that using register_shutdown_function(), I'm just
not sure if we want that or not.

Reported by dreadnaut on 2014-05-13 16:43:02

<hr> * Attachment: Log.php * Attachment: debug-log.png<br>

[Christopher Kramer]

In general a good idea in the right direction.

What I think is the main problem here: With the log being collected and echoed later,
it is difficult to see _where_ the log was produced. I mean SQL statements in the end
all are logged by the query() method, but that's not what I want to know. I want to
know where in the code the original call comes from.
With the SQL statement being echoed directly, I can easily see (guess) this. I'm not
saying this is the clean way to do this. I am just saying that your suggestion makes
debugging a little more difficult (at least for me :D) than what we currently have.

But we can fix this: We can send the current position in the code to the Log Class
at all important points:
Log->position('Delete an existing database');
In the end this would be at the top of every method, currently it would be spread all
around index.php (where the "//-" comments are, I guess).
What do you think?

Another idea: Why not collecting Debug messages and other messages like errors, warnings
and so on in the same place? It is more or less a matter of the level. There is not
really a big difference between debug and normal messages. A Debug message could be
a message like others, only normally not being echoed.

Reported by crazy4chrissi on 2014-05-13 19:05:47

[dreadnaut]

> With the log being collected and echoed later, it is difficult to see _where_
> the log was produced.

I'm getting the filename:line information form the stack trace, so I could skip the
first level (Database->query) and show the second (the original caller). Or show both,
for clarity.

If you want additional 'locations', we just need to add some calls to 

  Log::info('Delete an existing database')

which will make the debug log nice and structured.

About collecting everything together: uhmmmm... it could work, or it could be a very
messy solution :) It definitely works for console programs for example, where there
is a single flow of output. But we want important messages to appear near the top of
the page, while the debug log should be out of the way, maybe even collapsed by default.
Also, result/warning messages would be more complex than a single line, language dependent,
etc.

Reported by dreadnaut on 2014-05-13 19:30:32 - Status changed: Started

[dreadnaut]

Here's a screenshot of the revised log, showing the full call stack for each entry,
and showing the four formats: query, info, error and dump.

Reported by dreadnaut on 2014-05-19 16:28:39

<hr> * Attachment: debug-log.png<br>

[Christopher Kramer]

I like it. Go for it. Sorry for the late reply.

Reported by crazy4chrissi on 2014-05-22 20:06:28

[dreadnaut]

Here's a first patch then, with the following changes:
a) added a Log class;
b) initialize and output the Log in index.php;
c) replace output guarded by $debug with Log lines;
d) added css for the debug log.

A lot of debug output comes from alterTable(), could you double check my changes in
that function?

Regarding (d), the new build system introduced css and js minification, so we can be
more generous with comments and whitespace in new code :)

Reported by dreadnaut on 2014-05-26 17:05:51

<hr> * Attachment: debug-log.patch