Index: /branches/devel-api/plugins/debug_logger/debug_logger.php =================================================================== --- /branches/devel-api/plugins/debug_logger/debug_logger.php (revision 2297) +++ /branches/devel-api/plugins/debug_logger/debug_logger.php (revision 2297) @@ -0,0 +1,146 @@ +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(true); + $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(); + } +} +?> Index: /branches/devel-api/plugins/debug_logger/runlog/runlog.php =================================================================== --- /branches/devel-api/plugins/debug_logger/runlog/runlog.php (revision 2297) +++ /branches/devel-api/plugins/debug_logger/runlog/runlog.php (revision 2297) @@ -0,0 +1,227 @@ + + */ +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 = '
' . print_r( $msg, TRUE ) . '
'; + } + $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); + } + } + +} + +?> Index: /branches/devel-api/program/include/main.inc =================================================================== --- /branches/devel-api/program/include/main.inc (revision 2296) +++ /branches/devel-api/program/include/main.inc (revision 2297) @@ -819,7 +819,13 @@ function console() { + $args = func_get_args(); + if(class_exists('rcmail')){ + $rcmail = rcmail::get_instance(); + rcmail::get_instance()->plugins->exec_hook('console',$args); + } + $msg = array(); - foreach (func_get_args() as $arg) - $msg[] = !is_string($arg) ? var_export($arg, true) : $arg; + foreach ($args as $arg) + $msg[] = !is_string($arg) ? var_export($arg, true) : $arg; if (!($GLOBALS['CONFIG']['debug_level'] & 4))