diff options
author | thomascube <thomas@roundcube.net> | 2011-10-19 15:28:11 +0000 |
---|---|---|
committer | thomascube <thomas@roundcube.net> | 2011-10-19 15:28:11 +0000 |
commit | 5da48a95224e925f4b070f2581a121516df33829 (patch) | |
tree | fadc87888faae54cdb1efc6f7b73fbfce79e0fe7 /plugins/debug_logger | |
parent | b03854de3a36a322bf98c733ed9b75d996694e38 (diff) |
Copy plugins to release branch
Diffstat (limited to 'plugins/debug_logger')
-rw-r--r-- | plugins/debug_logger/debug_logger.php | 146 | ||||
-rw-r--r-- | plugins/debug_logger/runlog/runlog.php | 227 |
2 files changed, 373 insertions, 0 deletions
diff --git a/plugins/debug_logger/debug_logger.php b/plugins/debug_logger/debug_logger.php new file mode 100644 index 000000000..f04ba6a61 --- /dev/null +++ b/plugins/debug_logger/debug_logger.php @@ -0,0 +1,146 @@ +<?php + +/** + * Debug Logger + * + * Enhanced logging for debugging purposes. It is not recommened + * to be enabled on production systems without testing because of + * the somewhat increased memory, cpu and disk i/o overhead. + * + * Debug Logger listens for existing console("message") calls and + * introduces start and end tags as well as free form tagging + * which can redirect messages to files. The resulting log files + * provide timing and tag quantity results. + * + * Enable the plugin in config/main.inc.php and add your desired + * log types and files. + * + * @version 1.0 + * @author Ziba Scott + * @website http://roundcube.net + * + * Example: + * + * config/main.inc.php: + * + * // $rcmail_config['debug_logger'][type of logging] = name of file in log_dir + * // The 'master' log includes timing information + * $rcmail_config['debug_logger']['master'] = 'master'; + * // If you want sql messages to also go into a separate file + * $rcmail_config['debug_logger']['sql'] = 'sql'; + * + * index.php (just after $RCMAIL->plugins->init()): + * + * console("my test","start"); + * console("my message"); + * console("my sql calls","start"); + * console("cp -r * /dev/null","shell exec"); + * console("select * from example","sql"); + * console("select * from example","sql"); + * console("select * from example","sql"); + * console("end"); + * console("end"); + * + * + * logs/master (after reloading the main page): + * + * [17-Feb-2009 16:51:37 -0500] start: Task: mail. + * [17-Feb-2009 16:51:37 -0500] start: my test + * [17-Feb-2009 16:51:37 -0500] my message + * [17-Feb-2009 16:51:37 -0500] shell exec: cp -r * /dev/null + * [17-Feb-2009 16:51:37 -0500] start: my sql calls + * [17-Feb-2009 16:51:37 -0500] sql: select * from example + * [17-Feb-2009 16:51:37 -0500] sql: select * from example + * [17-Feb-2009 16:51:37 -0500] sql: select * from example + * [17-Feb-2009 16:51:37 -0500] end: my sql calls - 0.0018 seconds shell exec: 1, sql: 3, + * [17-Feb-2009 16:51:37 -0500] end: my test - 0.0055 seconds shell exec: 1, sql: 3, + * [17-Feb-2009 16:51:38 -0500] end: Task: mail. - 0.8854 seconds shell exec: 1, sql: 3, + * + * logs/sql (after reloading the main page): + * + * [17-Feb-2009 16:51:37 -0500] sql: select * from example + * [17-Feb-2009 16:51:37 -0500] sql: select * from example + * [17-Feb-2009 16:51:37 -0500] sql: select * from example + */ +class debug_logger extends rcube_plugin +{ + function init() + { + require_once(dirname(__FILE__).'/runlog/runlog.php'); + $this->runlog = new runlog(); + + if(!rcmail::get_instance()->config->get('log_dir')){ + rcmail::get_instance()->config->set('log_dir',INSTALL_PATH.'logs'); + } + + $log_config = rcmail::get_instance()->config->get('debug_logger',array()); + + foreach($log_config as $type=>$file){ + $this->runlog->set_file(rcmail::get_instance()->config->get('log_dir').'/'.$file, $type); + } + + $start_string = ""; + $action = rcmail::get_instance()->action; + $task = rcmail::get_instance()->task; + if($action){ + $start_string .= "Action: ".$action.". "; + } + if($task){ + $start_string .= "Task: ".$task.". "; + } + $this->runlog->start($start_string); + + $this->add_hook('console', array($this, 'console')); + $this->add_hook('authenticate', array($this, 'authenticate')); + } + + function authenticate($args){ + $this->runlog->note('Authenticating '.$args['user'].'@'.$args['host']); + return $args; + } + + function console($args){ + $note = $args[0]; + $type = $args[1]; + + + if(!isset($args[1])){ + // This could be extended to detect types based on the + // file which called console. For now only rcube_imap.inc is supported + $bt = debug_backtrace(); + $file = $bt[3]['file']; + switch(basename($file)){ + case 'rcube_imap.php': + $type = 'imap'; + break; + default: + $type = FALSE; + break; + } + } + switch($note){ + case 'end': + $type = 'end'; + break; + } + + + switch($type){ + case 'start': + $this->runlog->start($note); + break; + case 'end': + $this->runlog->end(); + break; + default: + $this->runlog->note($note, $type); + break; + } + return $args; + } + + function __destruct(){ + $this->runlog->end(); + } +} +?> diff --git a/plugins/debug_logger/runlog/runlog.php b/plugins/debug_logger/runlog/runlog.php new file mode 100644 index 000000000..c9f672615 --- /dev/null +++ b/plugins/debug_logger/runlog/runlog.php @@ -0,0 +1,227 @@ +<?php + +/** + * runlog + * + * @author Ziba Scott <ziba@umich.edu> + */ +class runlog { + + private $start_time = FALSE; + + private $parent_stack = array(); + + public $print_to_console = FALSE; + + private $file_handles = array(); + + private $indent = 0; + + public $threshold = 0; + + public $tag_count = array(); + + public $timestamp = "d-M-Y H:i:s O"; + + public $max_line_size = 150; + + private $run_log = array(); + + function runlog() + { + $this->start_time = microtime( TRUE ); + } + + public function start( $name, $tag = FALSE ) + { + $this->run_log[] = array( 'type' => 'start', + 'tag' => $tag, + 'index' => count($this->run_log), + 'value' => $name, + 'time' => microtime( TRUE ), + 'parents' => $this->parent_stack, + 'ended' => false, + ); + $this->parent_stack[] = $name; + + $this->print_to_console("start: ".$name, $tag, 'start'); + $this->print_to_file("start: ".$name, $tag, 'start'); + $this->indent++; + } + + public function end() + { + $name = array_pop( $this->parent_stack ); + foreach ( $this->run_log as $k => $entry ) { + if ( $entry['value'] == $name && $entry['type'] == 'start' && $entry['ended'] == false) { + $lastk = $k; + } + } + $start = $this->run_log[$lastk]['time']; + $this->run_log[$lastk]['duration'] = microtime( TRUE ) - $start; + $this->run_log[$lastk]['ended'] = true; + + $this->run_log[] = array( 'type' => 'end', + 'tag' => $this->run_log[$lastk]['tag'], + 'index' => $lastk, + 'value' => $name, + 'time' => microtime( TRUE ), + 'duration' => microtime( TRUE ) - $start, + 'parents' => $this->parent_stack, + ); + $this->indent--; + if($this->run_log[$lastk]['duration'] >= $this->threshold){ + $tag_report = ""; + foreach($this->tag_count as $tag=>$count){ + $tag_report .= "$tag: $count, "; + } + if(!empty($tag_report)){ +// $tag_report = "\n$tag_report\n"; + } + $end_txt = sprintf("end: $name - %0.4f seconds $tag_report", $this->run_log[$lastk]['duration'] ); + $this->print_to_console($end_txt, $this->run_log[$lastk]['tag'] , 'end'); + $this->print_to_file($end_txt, $this->run_log[$lastk]['tag'], 'end'); + } + } + + public function increase_tag_count($tag){ + if(!isset($this->tag_count[$tag])){ + $this->tag_count[$tag] = 0; + } + $this->tag_count[$tag]++; + } + + public function get_text(){ + $text = ""; + foreach($this->run_log as $entry){ + $text .= str_repeat(" ",count($entry['parents'])); + if($entry['tag'] != 'text'){ + $text .= $entry['tag'].': '; + } + $text .= $entry['value']; + + if($entry['tag'] == 'end'){ + $text .= sprintf(" - %0.4f seconds", $entry['duration'] ); + } + + $text .= "\n"; + } + return $text; + } + + public function set_file($filename, $tag = 'master'){ + if(!isset($this->file_handle[$tag])){ + $this->file_handles[$tag] = fopen($filename, 'a'); + if(!$this->file_handles[$tag]){ + trigger_error('Could not open file for writing: '.$filename); + } + } + } + + public function note( $msg, $tag = FALSE ) + { + if($tag){ + $this->increase_tag_count($tag); + } + if ( is_array( $msg )) { + $msg = '<pre>' . print_r( $msg, TRUE ) . '</pre>'; + } + $this->debug_messages[] = $msg; + $this->run_log[] = array( 'type' => 'note', + 'tag' => $tag ? $tag:"text", + 'value' => htmlentities($msg), + 'time' => microtime( TRUE ), + 'parents' => $this->parent_stack, + ); + + $this->print_to_file($msg, $tag); + $this->print_to_console($msg, $tag); + + } + + public function print_to_file($msg, $tag = FALSE, $type = FALSE){ + if(!$tag){ + $file_handle_tag = 'master'; + } + else{ + $file_handle_tag = $tag; + } + if($file_handle_tag != 'master' && isset($this->file_handles[$file_handle_tag])){ + $buffer = $this->get_indent(); + $buffer .= "$msg\n"; + if(!empty($this->timestamp)){ + $buffer = sprintf("[%s] %s",date($this->timestamp, mktime()), $buffer); + } + fwrite($this->file_handles[$file_handle_tag], wordwrap($buffer, $this->max_line_size, "\n ")); + } + if(isset($this->file_handles['master']) && $this->file_handles['master']){ + $buffer = $this->get_indent(); + if($tag){ + $buffer .= "$tag: "; + } + $msg = str_replace("\n","",$msg); + $buffer .= "$msg"; + if(!empty($this->timestamp)){ + $buffer = sprintf("[%s] %s",date($this->timestamp, mktime()), $buffer); + } + if(strlen($buffer) > $this->max_line_size){ + $buffer = substr($buffer,0,$this->max_line_size - 3)."..."; + } + fwrite($this->file_handles['master'], $buffer."\n"); + } + } + + public function print_to_console($msg, $tag=FALSE){ + if($this->print_to_console){ + if(is_array($this->print_to_console)){ + if(in_array($tag, $this->print_to_console)){ + echo $this->get_indent(); + if($tag){ + echo "$tag: "; + } + echo "$msg\n"; + } + } + else{ + echo $this->get_indent(); + if($tag){ + echo "$tag: "; + } + echo "$msg\n"; + } + } + } + + public function print_totals(){ + $totals = array(); + foreach ( $this->run_log as $k => $entry ) { + if ( $entry['type'] == 'start' && $entry['ended'] == true) { + $totals[$entry['value']]['duration'] += $entry['duration']; + $totals[$entry['value']]['count'] += 1; + } + } + if($this->file_handle){ + foreach($totals as $name=>$details){ + fwrite($this->file_handle,$name.": ".number_format($details['duration'],4)."sec, ".$details['count']." calls \n"); + } + } + } + + private function get_indent(){ + $buf = ""; + for($i = 0; $i < $this->indent; $i++){ + $buf .= " "; + } + return $buf; + } + + + function __destruct(){ + foreach($this->file_handles as $handle){ + fclose($handle); + } + } + +} + +?> |