Completely disable Debug logging if it is not enabled for the current user

관리자 또는 특정 IP에서만 디버그 기능을 사용하도록 설정된 경우,
그 밖의 요청에서는 어떤 에러메시지, 쿼리, 트리거 소요시간 등의 기록도
디버그 클래스에 저장하지 않도록 변경합니다.

워닝이 많이 발생하는 PHP 8.0에서는 20~30%의 성능 개선 효과가 있습니다.

classes/display/DisplayHandler.class.php

@@ -175,7 +175,7 @@ class DisplayHandler extends Handler
 		}
 		
 		// Check if debugging is enabled for this request.
-		if (!config('debug.enabled') || !Rhymix\Framework\Debug::isEnabledForCurrentUser())
+		if (!Rhymix\Framework\Debug::isEnabledForCurrentUser())
 		{
 			return;
 		}

classes/display/HTMLDisplayHandler.php

@@ -273,10 +273,12 @@ class HTMLDisplayHandler
 		$oModuleController->replaceDefinedLangCode($output);
 		
 		// remove template path comment tag
+		/*
 		if(!Rhymix\Framework\Debug::isEnabledForCurrentUser())
 		{
 			$output = preg_replace('/\n<!-- Template (?:start|end) : .*? -->\r?\n/', "\n", $output);
 		}
+		*/
 	}
 
 	/**

classes/file/FileHandler.class.php

@@ -344,7 +344,9 @@ class FileHandler
 			$log['status'] = $response ? $response->status_code : 0;
 			$log['elapsed_time'] = $elapsed_time;
 			
-			if (config('debug.enabled') && in_array('slow_remote_requests', config('debug.display_content')))
+			if (Rhymix\Framework\Debug::isEnabledForCurrentUser())
+			{
+				if (in_array('slow_remote_requests', config('debug.display_content')))
 				{
 					$bt = debug_backtrace(\DEBUG_BACKTRACE_IGNORE_ARGS);
 					foreach($bt as $no => $call)
@@ -367,6 +369,7 @@ class FileHandler
 					$log['backtrace'] = array();
 				}
 				Rhymix\Framework\Debug::addRemoteRequest($log);
+			}
 			
 			foreach($response->cookies as $cookie)
 			{

classes/module/ModuleHandler.class.php

@@ -1229,6 +1229,8 @@ class ModuleHandler extends Handler
 			{
 				$trigger_target = $module . ($type === 'class' ? '' : $type) . '.' . $called_method;
 				
+				if (Rhymix\Framework\Debug::isEnabledForCurrentUser())
+				{
 					Rhymix\Framework\Debug::addTrigger(array(
 						'name' => $trigger_name . '.' . $called_position,
 						'target' => $trigger_target,
@@ -1236,6 +1238,7 @@ class ModuleHandler extends Handler
 						'elapsed_time' => $after_each_trigger_time - $before_each_trigger_time,
 					));
 				}
+			}
 
 			if($output instanceof BaseObject && !$output->toBool())
 			{
@@ -1280,6 +1283,8 @@ class ModuleHandler extends Handler
 					$trigger_target = 'closure';
 				}
 				
+				if (Rhymix\Framework\Debug::isEnabledForCurrentUser())
+				{
 					Rhymix\Framework\Debug::addTrigger(array(
 						'name' => $trigger_name . '.' . $called_position,
 						'target' => $trigger_target,
@@ -1287,6 +1292,7 @@ class ModuleHandler extends Handler
 						'elapsed_time' => $after_each_trigger_time - $before_each_trigger_time,
 					));
 				}
+			}
 
 			if(is_object($output) && method_exists($output, 'toBool') && !$output->toBool())
 			{

common/framework/db.php

@@ -530,8 +530,12 @@ class DB
 			{
 				$this->setError(-1, $e->getMessage());
 			}
+			
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($this->getQueryLog('START TRANSACTION', 0));
 			}
+		}
 		$this->_transaction_level++;
 		return $this->_transaction_level;
 	}
@@ -554,8 +558,12 @@ class DB
 			{
 				$this->setError(-1, $e->getMessage());
 			}
+			
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($this->getQueryLog('ROLLBACK', 0));
 			}
+		}
 		$this->_transaction_level--;
 		return $this->_transaction_level;
 	}
@@ -578,8 +586,12 @@ class DB
 			{
 				$this->setError(-1, $e->getMessage());
 			}
+			
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($this->getQueryLog('COMMIT', 0));
 			}
+		}
 		$this->_transaction_level--;
 		return $this->_transaction_level;
 	}
@@ -1060,12 +1072,7 @@ class DB
 	public function getQueryLog(string $query, float $elapsed_time): array
 	{
 		// Cache the debug status to improve performance.
-		static $debug_enabled = null;
 		static $debug_queries = null;
-		if ($debug_enabled === null)
-		{
-			$debug_enabled = Config::get('debug.enabled');
-		}
 		if ($debug_queries === null)
 		{
 			$debug_queries = in_array('queries', Config::get('debug.display_content') ?: []);
@@ -1087,7 +1094,7 @@ class DB
 		);
 		
 		// Add debug information if enabled.
-		if ($debug_enabled && ($this->_errno || $debug_queries))
+		if ($this->_errno || $debug_queries)
 		{
 			$backtrace = debug_backtrace(\DEBUG_BACKTRACE_IGNORE_ARGS);
 			foreach ($backtrace as $no => $call)

common/framework/debug.php

@@ -10,7 +10,8 @@ class Debug
 	/**
 	 * Store log entries here.
 	 */
-	protected static $_enabled = true;
+	protected static $_enabled = null;
+	protected static $_config = array();
 	protected static $_aliases = array();
 	protected static $_entries = array();
 	protected static $_errors = array();
@@ -286,7 +287,7 @@ class Debug
 		self::$_entries[] = $entry;
 		
 		// Add the entry to the error log.
-		if (config('debug.write_error_log') === 'all' && self::isEnabledForCurrentUser())
+		if (self::$_config['write_error_log'] === 'all')
 		{
 			$log_entry = str_replace("\0", '', sprintf('Rhymix Debug: %s in %s on line %d',
 				var_export($message, true), $entry->file, $entry->line));
@@ -341,7 +342,7 @@ class Debug
 		);
 		
 		// Add the entry to the error log.
-		if (config('debug.write_error_log') === 'all')
+		if (self::$_config['write_error_log'] === 'all')
 		{
 			$log_entry = strtr(sprintf('PHP %s: %s in %s on line %d', $errinfo->type, $errstr, $errfile, intval($errline)), "\0\r\n\t\v\e\f", '       ');
 			error_log($log_entry . \PHP_EOL . self::formatBacktrace($backtrace));
@@ -394,7 +395,7 @@ class Debug
 			
 			self::$_errors[] = $error_object;
 			
-			if (config('debug.write_error_log') === 'all')
+			if (self::$_config['write_error_log'] === 'all')
 			{
 				$log_entry = strtr(sprintf('Query Error: %s in %s on line %d', $error_object->message, $error_object->file, intval($error_object->line)), "\0\r\n\t\v\e\f", '       ');
 				error_log($log_entry . \PHP_EOL . self::formatBacktrace($error_object->backtrace));
@@ -402,7 +403,7 @@ class Debug
 		}
 		
 		// Add the entry to the slow query log.
-		if ($query_object->query_time && $query_object->query_time >= config('debug.log_slow_queries'))
+		if ($query_object->query_time && $query_object->query_time >= self::$_config['log_slow_queries'])
 		{
 			self::$_slow_queries[] = $query_object;
 		}
@@ -436,7 +437,7 @@ class Debug
 		);
 		
 		self::$_triggers[] = $trigger_object;
-		if ($trigger_object->trigger_time && $trigger_object->trigger_time >= config('debug.log_slow_triggers'))
+		if ($trigger_object->trigger_time && $trigger_object->trigger_time >= self::$_config['log_slow_triggers'])
 		{
 			self::$_slow_triggers[] = $trigger_object;
 		}
@@ -468,7 +469,7 @@ class Debug
 		);
 		
 		self::$_widgets[] = $widget_object;
-		if ($widget_object->widget_time && $widget_object->widget_time >= config('debug.log_slow_widgets'))
+		if ($widget_object->widget_time && $widget_object->widget_time >= self::$_config['log_slow_widgets'])
 		{
 			self::$_slow_widgets[] = $widget_object;
 		}
@@ -502,7 +503,7 @@ class Debug
 		);
 		
 		self::$_remote_requests[] = $request_object;
-		if ($request_object->elapsed_time && $request_object->elapsed_time >= config('debug.log_slow_remote_requests'))
+		if ($request_object->elapsed_time && $request_object->elapsed_time >= self::$_config['log_slow_remote_requests'])
 		{
 			self::$_slow_remote_requests[] = $request_object;
 		}
@@ -549,7 +550,7 @@ class Debug
 			$log_entry = str_replace("\0", '', sprintf('%s #%d "%s" in %s on line %d',
 				get_class($e), $e->getCode(), $e->getMessage(), $errfile, $e->getLine()));
 		}
-		if (config('debug.write_error_log') !== 'none')
+		if (self::$_config['write_error_log'] !== 'none')
 		{
 			error_log('PHP Exception: ' . $log_entry . \PHP_EOL . self::formatBacktrace($e->getTrace()));
 		}
@@ -579,7 +580,7 @@ class Debug
 		// Add the entry to the error log.
 		$message = sprintf('%s in %s on line %d', $errinfo['message'], $errinfo['file'], intval($errinfo['line']));
 		$log_entry = str_replace("\0", '', 'PHP ' . self::getErrorType($errinfo['type']) . ': ' . $message);
-		if (config('debug.write_error_log') !== 'none')
+		if (self::$_config['write_error_log'] !== 'none')
 		{
 			error_log($log_entry);
 		}
@@ -633,6 +634,7 @@ class Debug
 	 */
 	public static function registerErrorHandlers($error_types)
 	{
+		self::$_config = config('debug');
 		set_error_handler('\\Rhymix\\Framework\\Debug::addError', $error_types);
 		set_exception_handler('\\Rhymix\\Framework\\Debug::exceptionHandler');
 		register_shutdown_function('\\Rhymix\\Framework\\Debug::shutdownHandler');
@@ -712,45 +714,43 @@ class Debug
 	 */
 	public static function isEnabledForCurrentUser()
 	{
-		static $cache = null;
+		if (self::$_enabled !== null)
-		if ($cache !== null)
 		{
-			return $cache;
+			return self::$_enabled;
 		}
-		if (!Config::get('debug.enabled'))
+		if (!self::$_config['enabled'])
 		{
-			return $cache = false;
+			return self::$_enabled = false;
 		}
 		
-		$display_to = Config::get('debug.display_to');
+		switch (self::$_config['display_to'])
-		switch ($display_to)
 		{
 			case 'everyone':
-				return $cache = true;
+				return self::$_enabled = true;
 			
 			case 'ip':
-				if (Filters\IpFilter::inRanges(\RX_CLIENT_IP, Config::get('debug.allow')))
+				if (Filters\IpFilter::inRanges(\RX_CLIENT_IP, self::$_config['allow']))
 				{
-					return $cache = true;
+					return self::$_enabled = true;
 				}
 				if (\RX_CLIENT_IP === '127.0.0.1' || \RX_CLIENT_IP === '::1')
 				{
-					return $cache = true;
+					return self::$_enabled = true;
 				}
 				if (\RX_CLIENT_IP === $_SERVER['SERVER_ADDR'] || \RX_CLIENT_IP === $_SERVER['LOCAL_ADDR'])
 				{
-					return $cache = true;
+					return self::$_enabled = true;
 				}
-				return $cache = false;
+				return self::$_enabled = false;
 			
 			case 'admin':
 			default:
 				$logged_info = \Context::get('logged_info');
 				if ($logged_info && $logged_info->is_admin === 'Y')
 				{
-					return $cache = true;
+					return self::$_enabled = true;
 				}
-				return $cache = false;
+				return self::$_enabled = false;
 		}
 	}
 	

common/framework/helpers/dbhelper.php

@@ -61,7 +61,10 @@ class DBHelper extends \PDO
 			$elapsed_time = microtime(true) - $start_time;
 			$db_class->addElapsedTime($elapsed_time);
 			$db_class->setError(-1, $e->getMessage());
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($db_class->getQueryLog($statement, $elapsed_time));
+			}
 			
 			/**
 			 * This is a new feature in Rhymix 2.0 so we don't have to mess
@@ -110,8 +113,11 @@ class DBHelper extends \PDO
 		{
 			$elapsed_time = microtime(true) - $start_time;
 			$db_class->addElapsedTime($elapsed_time);
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($db_class->getQueryLog($statement, $elapsed_time));
 			}
+		}
 		
 		return $stmt;
 	}
@@ -140,8 +146,11 @@ class DBHelper extends \PDO
 		{
 			$elapsed_time = microtime(true) - $start_time;
 			$db_class->addElapsedTime($elapsed_time);
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($db_class->getQueryLog($query, $elapsed_time));
 			}
+		}
 		
 		return $result;
 	}

common/framework/helpers/dbstmthelper.php

@@ -57,8 +57,11 @@ class DBStmtHelper extends \PDOStatement
 		{
 			$elapsed_time = microtime(true) - $start_time;
 			$db_class->addElapsedTime($elapsed_time);
+			if (Debug::isEnabledForCurrentUser())
+			{
 				Debug::addQuery($db_class->getQueryLog($this->queryString, $elapsed_time));
 			}
+		}
 		
 		return $result;
 	}

modules/addon/addon.controller.php

@@ -130,7 +130,7 @@ class addonController extends addon
 			$buff[] = 'if ($run && file_exists($addon_file)):';
 			$buff[] = '  include($addon_file);';
 			$buff[] = '  $after_time = microtime(true);';
-			$buff[] = '  if (class_exists("Rhymix\\\\Framework\\\\Debug")):';
+			$buff[] = '  if (class_exists("Rhymix\\\\Framework\\\\Debug") && Rhymix\\Framework\\Debug::isEnabledForCurrentUser()):';
 			$buff[] = '    Rhymix\\Framework\\Debug::addTrigger(array(';
 			$buff[] = '      "name" => "addon." . $called_position,';
 			$buff[] = '      "target" => "' . $addon . '",';

modules/widget/widget.controller.php

@@ -652,10 +652,13 @@ class widgetController extends widget
 			$GLOBALS['__widget_excute_elapsed__'] = 0;
 		}
 		$GLOBALS['__widget_excute_elapsed__'] += $elapsed_time;
+		if (Rhymix\Framework\Debug::isEnabledForCurrentUser())
+		{
 			Rhymix\Framework\Debug::addWidget(array(
 				'name' => $widget,
 				'elapsed_time' => $elapsed_time,
 			));
+		}
 		
 		// Return result
 		return $output;

tests/unit/framework/DebugTest.php

@@ -6,6 +6,7 @@ class DebugTest extends \Codeception\TestCase\Test
 	
 	public function _before()
 	{
+		Rhymix\Framework\Debug::enable();
 		$this->error_log = ini_get('error_log');
 		ini_set('error_log', '/dev/null');
 	}