summaryrefslogtreecommitdiff
path: root/plugins/debug_logger
diff options
context:
space:
mode:
Diffstat (limited to 'plugins/debug_logger')
-rw-r--r--plugins/debug_logger/composer.json24
-rw-r--r--plugins/debug_logger/debug_logger.php150
-rw-r--r--plugins/debug_logger/runlog/runlog.php227
-rw-r--r--plugins/debug_logger/tests/DebugLogger.php23
4 files changed, 424 insertions, 0 deletions
diff --git a/plugins/debug_logger/composer.json b/plugins/debug_logger/composer.json
new file mode 100644
index 000000000..af7e1c1f8
--- /dev/null
+++ b/plugins/debug_logger/composer.json
@@ -0,0 +1,24 @@
+{
+ "name": "roundcube/debug_logger",
+ "type": "roundcube-plugin",
+ "description": "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.",
+ "license": "GPLv2",
+ "version": "1.0",
+ "authors": [
+ {
+ "name": "Ziba Scott",
+ "email": "ziba@umich.edu",
+ "role": "Lead"
+ }
+ ],
+ "repositories": [
+ {
+ "type": "composer",
+ "url": "http://plugins.roundcube.net"
+ }
+ ],
+ "require": {
+ "php": ">=5.3.0",
+ "roundcube/plugin-installer": ">=0.1.3"
+ }
+}
diff --git a/plugins/debug_logger/debug_logger.php b/plugins/debug_logger/debug_logger.php
new file mode 100644
index 000000000..07190e5a1
--- /dev/null
+++ b/plugins/debug_logger/debug_logger.php
@@ -0,0 +1,150 @@
+<?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.inc.php and add your desired
+ * log types and files.
+ *
+ * @version @package_version@
+ * @author Ziba Scott
+ * @website http://roundcube.net
+ *
+ * Example:
+ *
+ * config.inc.php:
+ *
+ * // $config['debug_logger'][type of logging] = name of file in log_dir
+ * // The 'master' log includes timing information
+ * $config['debug_logger']['master'] = 'master';
+ * // If you want sql messages to also go into a separate file
+ * $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(__DIR__ . '/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/rcube_storage is supported
+ $bt = debug_backtrace();
+ $file = $bt[3]['file'];
+ switch(basename($file)){
+ case 'rcube_imap.php':
+ $type = 'imap';
+ break;
+ case 'rcube_storage.php':
+ $type = 'storage';
+ 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()
+ {
+ if ($this->runlog)
+ $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..0c766a13c
--- /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 $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);
+ }
+ }
+
+}
+
+?>
diff --git a/plugins/debug_logger/tests/DebugLogger.php b/plugins/debug_logger/tests/DebugLogger.php
new file mode 100644
index 000000000..8dd0c03fe
--- /dev/null
+++ b/plugins/debug_logger/tests/DebugLogger.php
@@ -0,0 +1,23 @@
+<?php
+
+class DebugLogger_Plugin extends PHPUnit_Framework_TestCase
+{
+
+ function setUp()
+ {
+ include_once __DIR__ . '/../debug_logger.php';
+ }
+
+ /**
+ * Plugin object construction test
+ */
+ function test_constructor()
+ {
+ $rcube = rcube::get_instance();
+ $plugin = new debug_logger($rcube->api);
+
+ $this->assertInstanceOf('debug_logger', $plugin);
+ $this->assertInstanceOf('rcube_plugin', $plugin);
+ }
+}
+
generated by cgit v1.2.3 (git 2.39.1) at 2024-04-28 19:21:11 +0000