MDL-14990 implemented query loggin in new native DML drivers

diff --git a/lib/db/install.php b/lib/db/install.php
index 1f46bf843b15d4dbbc97d7d3fffc563b21761c07..7c748b28f4180ec1b90aed364ce782ca07a2b56f 100644 (file)
--- a/lib/db/install.php
+++ b/lib/db/install.php
@@ -7,7 +7,7 @@ function xmldb_main_install() {
     global $CFG, $DB, $SITE;
 
 /// make sure system context exists
-    $syscontext = get_context_instance(CONTEXT_SYSTEM);
+    $syscontext = get_system_context(false);
     if ($syscontext->id != 1) {
         throw new moodle_exception('generalexceptionmessage', 'error', '', 'Unexpected system context id created!');
     }

diff --git a/lib/db/install.xml b/lib/db/install.xml
index 74032e80057dd6e2a9106a545b73ccd97b0777f6..63412c2575d3aecb8b98cef8d514489e1faaf63d 100644 (file)
--- a/lib/db/install.xml
+++ b/lib/db/install.xml
@@ -1,5 +1,5 @@
 <?xml version="1.0" encoding="UTF-8" ?>
-<XMLDB PATH="lib/db" VERSION="20090602" COMMENT="XMLDB file for core Moodle tables"
+<XMLDB PATH="lib/db" VERSION="20090613" COMMENT="XMLDB file for core Moodle tables"
     xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
     xsi:noNamespaceSchemaLocation="../../lib/xmldb/xmldb.xsd"
 >
@@ -378,7 +378,7 @@
         <INDEX NAME="timemodified" UNIQUE="false" FIELDS="timemodified" COMMENT="Mainly to help deletion of expired records from cron" PREVIOUS="md5key"/>
       </INDEXES>
     </TABLE>
-    <TABLE NAME="log" COMMENT="Every action is logged as far as possible" PREVIOUS="cache_text" NEXT="log_display">
+    <TABLE NAME="log" COMMENT="Every action is logged as far as possible" PREVIOUS="cache_text" NEXT="log_queries">
       <FIELDS>
         <FIELD NAME="id" TYPE="int" LENGTH="10" NOTNULL="true" UNSIGNED="true" SEQUENCE="true" NEXT="time"/>
         <FIELD NAME="time" TYPE="int" LENGTH="10" NOTNULL="true" UNSIGNED="true" DEFAULT="0" SEQUENCE="false" PREVIOUS="id" NEXT="userid"/>
@@ -402,7 +402,23 @@
         <INDEX NAME="cmid" UNIQUE="false" FIELDS="cmid" PREVIOUS="userid-course"/>
       </INDEXES>
     </TABLE>
-    <TABLE NAME="log_display" COMMENT="For a particular module/action, specifies a moodle table/field" PREVIOUS="log" NEXT="message">
+    <TABLE NAME="log_queries" COMMENT="Logged database queries." PREVIOUS="log" NEXT="log_display">
+      <FIELDS>
+        <FIELD NAME="id" TYPE="int" LENGTH="10" NOTNULL="true" UNSIGNED="true" SEQUENCE="true" NEXT="qtype"/>
+        <FIELD NAME="qtype" TYPE="int" LENGTH="5" NOTNULL="true" UNSIGNED="true" SEQUENCE="false" COMMENT="query type constant" PREVIOUS="id" NEXT="sqltext"/>
+        <FIELD NAME="sqltext" TYPE="text" LENGTH="medium" NOTNULL="true" SEQUENCE="false" COMMENT="query sql" PREVIOUS="qtype" NEXT="sqlparams"/>
+        <FIELD NAME="sqlparams" TYPE="text" LENGTH="big" NOTNULL="false" SEQUENCE="false" COMMENT="query parameters" PREVIOUS="sqltext" NEXT="error"/>
+        <FIELD NAME="error" TYPE="int" LENGTH="5" NOTNULL="true" UNSIGNED="true" DEFAULT="0" SEQUENCE="false" COMMENT="is error" PREVIOUS="sqlparams" NEXT="info"/>
+        <FIELD NAME="info" TYPE="text" LENGTH="small" NOTNULL="false" SEQUENCE="false" COMMENT="detailed info such as error text" PREVIOUS="error" NEXT="backtrace"/>
+        <FIELD NAME="backtrace" TYPE="text" LENGTH="small" NOTNULL="false" SEQUENCE="false" COMMENT="php execution trace" PREVIOUS="info" NEXT="exectime"/>
+        <FIELD NAME="exectime" TYPE="number" LENGTH="10" NOTNULL="true" UNSIGNED="false" SEQUENCE="false" DECIMALS="5" COMMENT="query execution time in seconds as float" PREVIOUS="backtrace" NEXT="timelogged"/>
+        <FIELD NAME="timelogged" TYPE="int" LENGTH="10" NOTNULL="true" UNSIGNED="true" SEQUENCE="false" COMMENT="timestamp when log info stored into db" PREVIOUS="exectime"/>
+      </FIELDS>
+      <KEYS>
+        <KEY NAME="primary" TYPE="primary" FIELDS="id"/>
+      </KEYS>
+    </TABLE>
+    <TABLE NAME="log_display" COMMENT="For a particular module/action, specifies a moodle table/field" PREVIOUS="log_queries" NEXT="message">
       <FIELDS>
         <FIELD NAME="id" TYPE="int" LENGTH="10" NOTNULL="true" UNSIGNED="true" SEQUENCE="true" NEXT="module"/>
         <FIELD NAME="module" TYPE="char" LENGTH="20" NOTNULL="true" SEQUENCE="false" PREVIOUS="id" NEXT="action"/>

diff --git a/lib/db/upgrade.php b/lib/db/upgrade.php
index 0bde28f14b10d5eaf6dfaed4f7ac028760b808bc..05dbd154e3977c7a4ac96062fe98564848231c17 100644 (file)
--- a/lib/db/upgrade.php
+++ b/lib/db/upgrade.php
@@ -2149,6 +2149,35 @@ WHERE gradeitemid IS NOT NULL AND grademax IS NOT NULL");
         upgrade_main_savepoint($result, 2009060200);
     }
 
+    if ($result && $oldversion < 2009061300) {
+        //TODO: copy this to the very beginning of this upgrade script so that we may log upgrade queries
+
+    /// Define table log_queries to be created
+        $table = new xmldb_table('log_queries');
+
+    /// Adding fields to table log_queries
+        $table->add_field('id', XMLDB_TYPE_INTEGER, '10', XMLDB_UNSIGNED, XMLDB_NOTNULL, XMLDB_SEQUENCE, null);
+        $table->add_field('qtype', XMLDB_TYPE_INTEGER, '5', XMLDB_UNSIGNED, XMLDB_NOTNULL, null, null);
+        $table->add_field('sqltext', XMLDB_TYPE_TEXT, 'medium', null, XMLDB_NOTNULL, null, null);
+        $table->add_field('sqlparams', XMLDB_TYPE_TEXT, 'big', null, null, null, null);
+        $table->add_field('error', XMLDB_TYPE_INTEGER, '5', XMLDB_UNSIGNED, XMLDB_NOTNULL, null, '0');
+        $table->add_field('info', XMLDB_TYPE_TEXT, 'small', null, null, null, null);
+        $table->add_field('backtrace', XMLDB_TYPE_TEXT, 'small', null, null, null, null);
+        $table->add_field('exectime', XMLDB_TYPE_NUMBER, '10, 5', null, XMLDB_NOTNULL, null, null);
+        $table->add_field('timelogged', XMLDB_TYPE_INTEGER, '10', XMLDB_UNSIGNED, XMLDB_NOTNULL, null, null);
+
+    /// Adding keys to table log_queries
+        $table->add_key('primary', XMLDB_KEY_PRIMARY, array('id'));
+
+    /// Conditionally launch create table for log_queries
+        if (!$dbman->table_exists($table)) {
+            $dbman->create_table($table);
+        }
+
+    /// Main savepoint reached
+        upgrade_main_savepoint($result, 2009061300);
+    }
+
     return $result;
 }
 

diff --git a/lib/dml/adodb_moodle_database.php b/lib/dml/adodb_moodle_database.php
index 43b6babb86948ae2608a166c8ce9ff5550fd7d8b..d4b6ac0b4461c253f0d02de0a478d92b88ceaa40 100644 (file)
--- a/lib/dml/adodb_moodle_database.php
+++ b/lib/dml/adodb_moodle_database.php
@@ -130,6 +130,11 @@ abstract class adodb_moodle_database extends moodle_database {
         }
     }
 
+    public function query_log($error=false) {
+        // no logging for obsoleted adodb - it would require a lot more fixing
+        return;
+    }
+
     /**
      * Returns database server info array
      * @return array

diff --git a/lib/dml/moodle_database.php b/lib/dml/moodle_database.php
index 4073ed7788fb5e805d38e81049895c9ab3cbcb8a..2223f05b2907a700d4155573a59cb51fb44d5a10 100644 (file)
--- a/lib/dml/moodle_database.php
+++ b/lib/dml/moodle_database.php
@@ -282,8 +282,8 @@ abstract class moodle_database {
      */
     public function dispose() {
         if ($this->intransaction) {
-            // unfortunately we can not access global $CFG any more and can not print debug 
-            error_log('Active database transaction detected when disposing database!');  
+            // unfortunately we can not access global $CFG any more and can not print debug
+            error_log('Active database transaction detected when disposing database!');
         }
         if ($this->used_for_db_sessions) {
             // this is needed because we need to save session to db before closing it
@@ -339,21 +339,24 @@ abstract class moodle_database {
         if ($this->loggingquery) {
             return;
         }
-        // remember current info, log querie may alter it
+        if ($result !== false) {
+            $this->query_log();
+            // free memory
+            $this->last_sql    = null;
+            $this->last_params = null;
+            return;
+        }
+
+        // remember current info, log queries may alter it
         $type   = $this->last_type;
         $sql    = $this->last_sql;
         $params = $this->last_params;
         $time   = microtime(true) - $this->last_time;
+        $error  = $this->get_last_error();
 
-        if ($result !== false) {
-            $this->query_log($type, $sql, $params, $time, false);
-            return;
-        }
+        $this->query_log($error);
 
-        $error = $this->get_last_error();
-        $this->query_log($type, $sql, $params, $time, $error);
-
-        switch ($this->last_type) {
+        switch ($type) {
             case SQL_QUERY_SELECT:
             case SQL_QUERY_AUX:
                 throw new dml_read_exception($error, $sql, $params);
@@ -367,24 +370,40 @@ abstract class moodle_database {
     }
 
     /**
-     * Log database query if requested
-     * @param int $type constant
-     * @param string $sql
-     * @param array $params
-     * @param float time in seconds
+     * Log ast database query if requested
      * @param mixed string error or false if not error
      * @return void
      */
-    public function query_log($type, $sql, $params, $time, $error=false) {
+    public function query_log($error=false) {
         $logall    = !empty($this->dboptions['logall']);
         $logslow   = !empty($this->dboptions['logslow']) ? $this->dboptions['logslow'] : false;
         $logerrors = !empty($this->dboptions['logerrors']);
         $iserror   = ($error !== false);
 
+        $time = microtime(true) - $this->last_time;
+
         if ($logall or ($logslow and ($logslow < ($time+0.00001))) or ($iserror and $logerrors)) {
             $this->loggingquery = true;
             try {
-                //TODO: add db tables for logging and support for error_log()
+                $backtrace = debug_backtrace();
+                if ($backtrace) {
+                    //remove query_log()
+                    array_shift($backtrace);
+                }
+                if ($backtrace) {
+                    //remove query_end()
+                    array_shift($backtrace);
+                }
+                $log = new object();
+                $log->qtype      = $this->last_type;
+                $log->sqltext    = $this->last_sql;
+                $log->sqlparams  = var_export((array)$this->last_params, true);
+                $log->error      = (int)$iserror;
+                $log->info       = $iserror ? $error : null;
+                $log->backtrace  = print_backtrace($backtrace, true, true);
+                $log->exectime   = $time;
+                $log->timelogged = time();
+                $this->insert_record('log_queries', $log);
             } catch (Exception $ignored) {
             }
             $this->loggingquery = false;

diff --git a/lib/dml/mysqli_native_moodle_database.php b/lib/dml/mysqli_native_moodle_database.php
index 30fe8463056da2060e2f237759258fb95f52fef6..9a4c26742d90d5b5bb2ccdc323fba454ed1e2e49 100644 (file)
--- a/lib/dml/mysqli_native_moodle_database.php
+++ b/lib/dml/mysqli_native_moodle_database.php
@@ -659,9 +659,10 @@ class mysqli_native_moodle_database extends moodle_database {
 
         $this->query_start($sql, $params, SQL_QUERY_INSERT);
         $result = $this->mysqli->query($rawsql);
+        $id = @$this->mysqli->insert_id; // must be called before query_end() which may insert log into db
         $this->query_end($result);
 
-        if (!$id = $this->mysqli->insert_id) {
+        if (!$id) {
             throw new dml_write_exception('unknown error fetching inserted id');
         }
 

diff --git a/lib/upgradelib.php b/lib/upgradelib.php
index c6b5144719df837bc933b87b175ee780d341e509..edbaee21428e542561678a8d088c76f6013109f3 100644 (file)
--- a/lib/upgradelib.php
+++ b/lib/upgradelib.php
@@ -748,7 +748,7 @@ function upgrade_log($type, $plugin, $info, $details=null, $backtrace=null) {
 
     $plugin = ($plugin==='moodle') ? null : $plugin;
 
-    $backtrace = print_backtrace($backtrace, true);
+    $backtrace = print_backtrace($backtrace, true, true);
 
     $version = null;
 

diff --git a/lib/weblib.php b/lib/weblib.php
index 86004558287a2428cbdc84ff047a99c6904df15d..7b134088a3e8df2ca30d28e17b11d11fa40186f7 100644 (file)
--- a/lib/weblib.php
+++ b/lib/weblib.php
@@ -5728,7 +5728,7 @@ function _print_normal_error($errorcode, $module, $a, $link, $backtrace, $debugi
             if ($debuginfo) {
                 debugging($debuginfo, DEBUG_DEVELOPER, $backtrace);
             } else {
-                notify('Stack trace:'.print_backtrace($backtrace, true), 'notifytiny');
+                notify('Stack trace:'.print_backtrace($backtrace, true, true), 'notifytiny');
             }
         }
         exit(1); // general error code
@@ -5776,7 +5776,7 @@ function _print_normal_error($errorcode, $module, $a, $link, $backtrace, $debugi
             if ($debuginfo) {
                 debugging($debuginfo, DEBUG_DEVELOPER, $backtrace);
             } else {
-                notify('Stack trace:'.print_backtrace($backtrace, true), 'notifytiny');
+                notify('Stack trace:'.print_backtrace($backtrace, false, true), 'notifytiny');
             }
         }
     }
@@ -5845,7 +5845,7 @@ function _print_early_error($errorcode, $module, $a, $backtrace=null, $debuginfo
         if ($debuginfo) {
             debugging($debuginfo, DEBUG_DEVELOPER, $backtrace);
         } else if ($backtrace) {
-            notify('Stack trace:'.print_backtrace($backtrace, true), 'notifytiny');
+            notify('Stack trace:'.print_backtrace($backtrace, false, true), 'notifytiny');
         }
     }
 
@@ -7009,7 +7009,7 @@ function debugging($message='', $level=DEBUG_NORMAL, $backtrace=null) {
             if (!$backtrace) {
                 $backtrace = debug_backtrace();
             }
-            $from = print_backtrace($backtrace, true);
+            $from = print_backtrace($backtrace, CLI_SCRIPT, true);
             if (!isset($CFG->debugdisplay)) {
                 $CFG->debugdisplay = ini_get_bool('display_errors');
             }
@@ -7035,7 +7035,7 @@ function debugging($message='', $level=DEBUG_NORMAL, $backtrace=null) {
  * @param bool $return return as string or print
  * @return string|bool Depending on $return
  */
-function print_backtrace($callers, $return=false) {
+function print_backtrace($callers, $plaintext=false, $return=false) {
     global $CFG;
 
     if (empty($callers)) {
@@ -7046,7 +7046,7 @@ function print_backtrace($callers, $return=false) {
         }
     }
 
-    $from = '<ul style="text-align: left">';
+    $from = $plaintext ? '' : '<ul style="text-align: left">';
     foreach ($callers as $caller) {
         if (!isset($caller['line'])) {
             $caller['line'] = '?'; // probably call_user_func()
@@ -7054,7 +7054,8 @@ function print_backtrace($callers, $return=false) {
         if (!isset($caller['file'])) {
             $caller['file'] = $CFG->dirroot.'/unknownfile'; // probably call_user_func()
         }
-        $from .= '<li>line ' . $caller['line'] . ' of ' . substr($caller['file'], strlen($CFG->dirroot) + 1);
+        $from .= $plaintext ? '* ' : '<li>';
+        $from .= 'line ' . $caller['line'] . ' of ' . substr($caller['file'], strlen($CFG->dirroot) + 1);
         if (isset($caller['function'])) {
             $from .= ': call to ';
             if (isset($caller['class'])) {
@@ -7064,9 +7065,9 @@ function print_backtrace($callers, $return=false) {
         } else if (isset($caller['exception'])) {
             $from .= ': '.$caller['exception'].' thrown';
         }
-        $from .= '</li>';
+        $from .= $plaintext ? "\n" : '</li>';
     }
-    $from .= '</ul>';
+    $from .= $plaintext ? '' : '</ul>';
 
     if ($return) {
         return $from;

diff --git a/version.php b/version.php
index 73e92f9efd9c821c1b7ba71ebac7d8db7f3bfdb6..83185f34199642c8bae830084c7defc2868b2087 100644 (file)
--- a/version.php
+++ b/version.php
@@ -6,9 +6,7 @@
 // This is compared against the values stored in the database to determine
 // whether upgrades should be performed (see lib/db/*.php)
 
-    $version = 2009060200;  // YYYYMMDD   = date of the last version bump
+    $version = 2009061300;  // YYYYMMDD   = date of the last version bump
                             //         XX = daily increments
 
     $release = '2.0 dev (Build: 20090613)';  // Human-friendly version name
-
-?>