#35 √ resolved
Predominant

The implementation of dbo_source.php logging needs changed.

Reported by Predominant | December 9th, 2009 @ 06:20 AM | in 1.3.0

(Reported by: iccle)

What happened:

The implemented database logging in cake/models/datasources/dbo_source.php is at best a quick dirty hack.

  • Database queries are stored in a temporary variable (in class DboSource->_queryLog) which is automatically output in HTML table format, triggered when the database connection is closed (DboSource::close()).
  • The output is injected after any document has been finished being sent by the users application, so the HTML table lies outside the document closing </html> tag making it difficult to style and requiring workarounds to parse or hide.
  • None of the class DboSource methods use cake_log, instead they rely on methods which print directly to the screen in pre-formatted HTML.
  • The current accepted advice for working around this flawed implementation, when developing AJAX clients is to disable the debugging in cakephp, instead the debugging information should be accesible to all client data formats and requirements.

What was expected:

  • The shutdown of the database connection should not cause output directly to the screen.
  • All of the database functions to use either cake_log, or the debugger when they log queries.
  • The auto generated query debug output to reside within the output DOM (at least).
  • And ideally: The database query log to be accessible via a variable like $cakeDebug ($cakeQuery?) so we can choose the final output format (XML,HTML table, JSON) etc by specifying an application specific default.ctp layout.

Comments and changes to this ticket

  • Mark Story

    Mark Story December 9th, 2009 @ 09:09 AM

    • → Milestone changed from “1.2.5” to “1.3.0”
  • Mark Story

    Mark Story December 9th, 2009 @ 06:02 PM

    (Comment by: iccle)

    Changes: description:

  • Mark Story

    Mark Story December 9th, 2009 @ 06:02 PM

    (Comment by: iccle)

    Changes: description:

  • Mark Story

    Mark Story December 9th, 2009 @ 06:02 PM

    (Comment by: iccle)

    Changes: description:

  • Mark Story

    Mark Story December 9th, 2009 @ 06:02 PM

    (Comment by: mark_story)

    While far from perfect, one advantage that the existing system has is that you always get a sql log as its dumped even when there are fatal errors. That is not necessarily something that would need to be removed for this change, but is something that should be retained as well.

    One other side effect of making this variable available in the layout would be loosing the ability to capture queries that happen inside of requestAction's in layout elements, as the variable would need to be prepared before the layout is rendered.

    Another solution is to change how showLog() works, so that you can clear the logs when showing them. This would allow you to create an element in your layout that could iterate over the available connections, get the logs, and clear them. Giving you control over the placement of the logs, keeping the sql logs on fatal errors, and leave the existing behavior intact.

    Changes:

  • Mark Story

    Mark Story December 9th, 2009 @ 06:03 PM

    (Comment by: iccle)

    Update:

    Thank you mark_story for your reply.

    My beef with the current implementation is simply this:

    • The closing of the database resource is entirely the wrong place to be injecting logs into the PHP output stream. The database connection is closed after the full document has been sent to the client.

    • None of the database logging functions actually store the query log on file, the DboSource::logQuery method simply caches the query, it does not log it.

    You stated: `one advantage that the existing system has is that you always get a sql log as its dumped even when there are fatal errorsunfortunately this behaviour is not actually reliable, because the injection of the log occurs in the DboSource::close() method, it is not a destructor so is not actually guaranteed to execute in exceptional circumstances.

    It seems odd and wastefull that there is a cake_log, and the cake Debugger class, and that the database connection does not use either of these, instead it uses its own quick and dirty log show, this is the equivalent of adding 'print' or 'echo' statements inside your Controller, instead of passing the information to a view for formatting and displaying.

    The current method works fine, if and only if you are developing a plain HTML application, as soon as you start developing RESTful web servers, or basic AJAX enabled pages, the output of this data corrupts your applications data recieved from the server, so you are left with a few options:

    • 1) Capture the output of all cake operations, remove the `<table>from the end of the DOM and insert it appropriately in a div or similar.
    • 2) Lower the cake debugging level and make do with no realtime log/debug information.
    • 3) Write workarounds in the client interface to deal with the query log being a) HTML table, b) appended after the DOM/JSON Packet closing tag.
    • 3) Hack the cakecode to stop it automatically outputting the SQL table during DboSource::close() and forgoe the query logs, this at least allows me to format and use the controller dumps.

    IMO the ideal long term fix would be:

    • Make cake_log observable.
    • Make all cake library functions use the cake_log (or via the Debugger class).

    This way all cake libraries and user libraries have a single Log route, which can be observed and acted upon by other classes.

    This would allow me for example, to easilly markup any logs sent (filtering them as i choose according to log level etc) and to store the logs in a database for querying later (perhaps in my admin interface).

    class CakeLog{
      /** Array of callable callbacks.
      */
      var _observers;
    
      /** Write an entry to the cake_log
      */
      function write($type, $msg) {
        // write to file as normal to keep existing behaviour...
        // Or do nothing and provide a default listener which writes to file, 
        // this could be overriden to write to database
    
        foreach($this->_observers as $callable)
             call_user_func($callable, $type, $msg);
       }
      /** add a callback 'listener' to be called each time an entry is written to the log.
      *@param callable $argCallable Any user function or class method.
      *@return bool true if the given listener was added, or already is listening.
      */
      function listen($argCallable){
        if(is_callable($argCallable)){
          if(!in_array($argCallable, $this->_observers))
            $this->_observers[] = $argCallable;
            return true;
        }
        return false;
      }
    
      /** Remove a callback listener.
      *@param callable $argCallable Any user function or class method.
      *@return bool true if the given listener was removed.
      */
      function forget($argCallable){
        $varKey = array_search($argCallable, $this->_observers));
        if($varKey){
          unset($this->_observers[$varKey]);
          return true;
        }
        return false;
      }
    };
    

    Changes: owner:mark_story

  • Mark Story

    Mark Story December 9th, 2009 @ 06:04 PM

    (Comment by: iccle)

    Changes: owner:

  • Mark Story

    Mark Story December 19th, 2009 @ 07:38 PM

    • → State changed from “new” to “resolved”
    • → Tag changed from “rfc” to “dbosource rfc”

    Database logging output has been implemented as a view element in 1.3. You can choose to not include this element if you do not wish to have logging output generated. Furthermore the automatic sql dumps have been removed from DboSource. I hope this solution works for you.

  • Jose Diaz-Gonzalez

    Jose Diaz-Gonzalez December 23rd, 2009 @ 11:51 AM

    How does this affect things such as DebugKit.Toolbar?

  • Mark Story

    Mark Story December 23rd, 2009 @ 12:06 PM

    It shouldn't affect it at all, because debugkit is being updated to include better sql dump features as well. Of course using both the sql_dump element and debugkit will probably result it double sql dumps, but I think if you are using debugkit you probably don't need to have the core sql dumps enabled too.

  • Jose Diaz-Gonzalez

    Jose Diaz-Gonzalez December 25th, 2009 @ 01:30 PM

    You mean the app/config/core.php need not be set to debug mode 2 in order to have something like DebugKit show queries in 1.3 head>

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.

New-ticket Create new ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

Shared Ticket Bins

People watching this ticket

Tags

You can update this ticket by sending an email to from your email client. (help)