From 11de4f99157d808623791213f1d7499e3b8b3e25 Mon Sep 17 00:00:00 2001 From: Clemens Schwaighofer Date: Tue, 22 Aug 2023 13:34:43 +0900 Subject: [PATCH] Logging update for class/method trace --- src/Admin/Backend.php | 2 +- src/DB/IO.php | 7 +- src/Debug/LoggingLegacy.php | 6 +- src/Debug/Support.php | 85 +++++++++++++------ src/Logging/Logging.php | 43 +++++++--- .../Debug/CoreLibsDebugSupportTest.php | 38 ++++++++- .../Logging/CoreLibsLoggingLoggingTest.php | 2 +- 7 files changed, 135 insertions(+), 48 deletions(-) diff --git a/src/Admin/Backend.php b/src/Admin/Backend.php index 2a8a1dc..f06b786 100644 --- a/src/Admin/Backend.php +++ b/src/Admin/Backend.php @@ -556,7 +556,7 @@ class Backend string $suffix = '', int $min_steps = 1, bool $name_pos_back = false - ) { + ): string { // get the build layout $html_time = \CoreLibs\Output\Form\Elements::printDateTime( $year, diff --git a/src/DB/IO.php b/src/DB/IO.php index c92f80f..d3117d2 100644 --- a/src/DB/IO.php +++ b/src/DB/IO.php @@ -805,7 +805,10 @@ class IO $call_stack[] = ($call_trace['file'] ?? 'n/f') . ':' . ($call_trace['line'] ?? '-') . ':' - . (!empty($call_trace['class']) ? $call_trace['class'] . '->' : '') + . (!empty($call_trace['class']) ? + $call_trace['class'] . ($call_trace['type'] ?? '') : + '' + ) . $call_trace['function']; } $context = [ @@ -825,7 +828,7 @@ class IO ); break; default: - // used named arguments so we can easy change the order of debug + // used named arguments so we can easy change the order of debug $this->log->debug( group_id: $debug_id, message: $error_string, diff --git a/src/Debug/LoggingLegacy.php b/src/Debug/LoggingLegacy.php index 6d3a602..0b5f6fd 100644 --- a/src/Debug/LoggingLegacy.php +++ b/src/Debug/LoggingLegacy.php @@ -405,7 +405,7 @@ class LoggingLegacy // set per class, but don't use get_class as we will only get self $rpl_string = !$this->log_per_class ? '' : '_' // set sub class settings - . str_replace('\\', '-', Support::getCallerClass()); + . str_replace('\\', '-', Support::getCallerTopLevelClass()); $fn = str_replace('{CLASS}', $rpl_string, $fn); // create output filename // if request to write to one file @@ -756,7 +756,7 @@ class LoggingLegacy return $status; } // get the last class entry and wrie that - $class = Support::getCallerClass(); + $class = Support::getCallerTopLevelClass(); // get timestamp $timestamp = Support::printTime(); // same string put for print (no html data inside) @@ -855,7 +855,7 @@ class LoggingLegacy . 'border-bottom: 1px solid black; margin: 10px 0 10px 0; ' . 'background-color: white; color: black;">' . '
{' - . Support::getCallerClass() . '}
'; + . Support::getCallerTopLevelClass() . '}'; $string_output = $string_prefix . $string_output . '
Script Run Time: ' . $script_end . '
' diff --git a/src/Debug/Support.php b/src/Debug/Support.php index cc1333d..456be11 100644 --- a/src/Debug/Support.php +++ b/src/Debug/Support.php @@ -79,10 +79,10 @@ class Support * default true: true, false: false * * @param bool $bool Variable to convert - * @param string $name [default: ''] Prefix name - * @param string $true [default: 'true'] True string - * @param string $false [default: 'false'] False string - * @param bool $no_html [default: false] if true do not print html + * @param string $name [=''] Prefix name + * @param string $true [='true'] True string + * @param string $false [='false'] False string + * @param bool $no_html [=false] if true do not print html * @return string String with converted bool text for debug */ public static function printBool( @@ -104,8 +104,8 @@ class Support * Convert bool value to string value. Short name alias for printBool * * @param bool $bool Bool value to be transformed - * @param string $true [default: 'true'] Override default string 'true' - * @param string $false [default: 'false'] Override default string 'false' + * @param string $true [='true'] Override default string 'true' + * @param string $false [=false'] Override default string 'false' * @return string $true or $false string for true/false bool */ public static function prBl( @@ -159,7 +159,7 @@ class Support * Recommended debug output * * @param mixed $data Anything - * @param bool $no_html [default=false] If true strip all html tags + * @param bool $no_html [=false] If true strip all html tags * (for text print) * @return string A text string */ @@ -203,7 +203,7 @@ class Support * exports (dumps) var, in more printable design, but without detail info * * @param mixed $data Anything - * @param bool $no_html If true true do not add 
 tags
+	 * @param  bool   $no_html [=false] If true true do not add 
 tags
 	 * @return string          A text string
 	 */
 	public static function exportVar(mixed $data, bool $no_html = false): string
@@ -217,7 +217,7 @@ class Support
 	 * Return file name and line number where this was called
 	 * One level up
 	 *
-	 * @param  int         $level trace level, default 1
+	 * @param  int         $level [=1] trace level
 	 * @return string|null        null or file name:line number
 	 */
 	public static function getCallerFileLine(int $level = 1): ?string
@@ -238,14 +238,14 @@ class Support
 	 * eg for debugging, this function does this
 	 *
 	 * call this method in the child method and you get the parent function that called
-	 * @param  int    $level trace level, default 1
-	 * @return ?string       null or the function that called the function
-	 *                       where this method is called
+	 * @param  int         $level [=1] trace level
+	 * @return string|null        null or the function that called the function
+	 *                            where this method is called
 	 */
 	public static function getCallerMethod(int $level = 1): ?string
 	{
 		$traces = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
-		// print \CoreLibs\Debug\Support::printAr($traces);
+		// print "getCallerMethod:
" . \CoreLibs\Debug\Support::printAr($traces);
 		// We should check from top down if unset?
 		// sets the start point here, and in level two (the sub call) we find this
 		if (isset($traces[$level])) {
@@ -254,6 +254,41 @@ class Support
 		return null;
 	}
 
+	/**
+	 * get the class that first called it and skip the base class
+	 * Companion method to getCallerMethod
+	 *
+	 * @param  int    $level [=1] trace level
+	 * @return ?string       null if class not found
+	 */
+	public static function getCallerClass(int $level = 1): ?string
+	{
+		$traces = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
+		// print "getCallerClass:
" . \CoreLibs\Debug\Support::printAr($traces);
+		if (isset($traces[$level])) {
+			return $traces[$level]['class'] ?? null;
+		}
+		return null;
+	}
+
+	/**
+	 * Returns class and method together
+	 *
+	 * @param  int         $level [=1] travel level
+	 * @return string|null        null if trace level not found, else namespace class and method
+	 */
+	public static function getCallerClassMethod(int $level = 1): ?string
+	{
+		$traces = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
+		// print "getCallerClass:
" . \CoreLibs\Debug\Support::printAr($traces);
+		if (isset($traces[$level])) {
+			return ($traces[$level]['class'] ?? '-')
+				. ($traces[$level]['type'] ?? '')
+				. $traces[$level]['function'];
+		}
+		return null;
+	}
+
 	/**
 	 * Returns array with all methods in the call stack in the order so that last
 	 * called is last in order
@@ -283,25 +318,21 @@ class Support
 	 * Is mostly used in debug log statements to get the class where the debug
 	 * was called
 	 * gets top level class
-	 *　loops over the debug backtrace until if finds the first class (from the end)
+	 * loops over the debug backtrace until if finds the first class (from the end)
 	 *
 	 * @return string Class name with namespace
 	 */
-	public static function getCallerClass(): string
+	public static function getCallerTopLevelClass(): string
 	{
-		$backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
-		// ?? [['class' => get_called_class()]];
-		// TODO make sure that this doesn't loop forver
+		$traces = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
+		// print "getCallerClass:
" . \CoreLibs\Debug\Support::printAr($traces);
 		$class = null;
-		while ($class === null && count($backtrace) > 0) {
-			// if current is
-			// [function] => debug
-			// [class] => CoreLibs\Debug\Logging
-			// then return
-			// (OUTSIDE) because it was not called from a class method
-			// or return file name
-			$get_class = array_pop($backtrace);
-			$class = $get_class['class'] ?? null;
+		// reverse and stop at first set class, this is the top level one
+		foreach (array_reverse($traces) as $trace) {
+			$class = $trace['class'] ?? null;
+			if (!empty($class)) {
+				break;
+			}
 		}
 		// on null or empty return empty string
 		return empty($class) ? '' : $class;
diff --git a/src/Logging/Logging.php b/src/Logging/Logging.php
index 6c74845..d672d9a 100644
--- a/src/Logging/Logging.php
+++ b/src/Logging/Logging.php
@@ -381,7 +381,7 @@ class Logging
 			// auto set (should be deprecated in future)
 			$this->setLogFileId(
 				str_replace(':', '-', $this->host_name) . '_'
-					. str_replace('\\', '-', Support::getCallerClass())
+					. str_replace('\\', '-', Support::getCallerTopLevelClass())
 			);
 		}
 		if (empty($this->getLogFileId())) {
@@ -460,7 +460,7 @@ class Logging
 		// set per class, but don't use get_class as we will only get self
 		$rpl_string = !$this->getLogFlag(Flag::per_class) ? '' : '_'
 			// set sub class settings
-			. str_replace('\\', '-', Support::getCallerClass());
+			. str_replace('\\', '-', Support::getCallerTopLevelClass());
 		$fn = str_replace('{CLASS}', $rpl_string, $fn); // create output filename
 
 		// if request to write to one file
@@ -526,7 +526,10 @@ class Logging
 
 	/**
 	 * Prepare the log message with all needed info blocks:
-	 * [timestamp] [host name] [file path + file] [running uid] {class}  - message
+	 * [timestamp] [host name] [file path + file::row number] [running uid] {class::/->method}
+	 *  - message
+	 * Note: group id is only for debug level
+	 * if no method can be found or no class is found a - will be wirtten
 	 *
 	 * @param  Level $level    Log level we will write to
 	 * @param  string|Stringable $message  The message to write
@@ -545,16 +548,32 @@ class Logging
 		if (!$this->checkLogLevel($level)) {
 			return '';
 		}
+		$file_line = '';
+		$caller_class_method = '-';
+		$traces = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
+		// print "[" . $level->getName() . "] [$message] prepareLog:
" . Support::printAr($traces);
 		// file + line: call not this but one before (the one that calls this)
-		$file_line = Support::getCallerFileLine(2) ??
-			System::getPageName(System::FULL_PATH);
-		// get the last class entry and wrie that
-		$class = Support::getCallerClass();
-		// method/function: prepareLog->(debug|info|...)->[THIS]
-		$method = Support::getCallerMethod(3);
-		if ($method !== null) {
-			$class .= '::' . $method;
+		// start from this level, if unset fall down until we are at null
+		$start_trace_level = 2;
+		for ($trace_level = $start_trace_level; $trace_level >= 0; $trace_level--) {
+			if (isset($traces[$trace_level])) {
+				$file_line = ($traces[$trace_level]['file'] ?? $traces[$trace_level]['function'])
+					. ':' . ($traces[$trace_level]['line'] ?? '-');
+				// as namespace\class->method
+				$caller_class_method =
+					// get the last call before we are in the Logging class
+					($traces[$trace_level]['class'] ?? '')
+					// connector, if unkown use ==
+					. ($traces[$trace_level]['type'] ?? '')
+					// method/function: prepareLog->(debug|info|...)->[THIS]
+					. $traces[$trace_level]['function'];
+				break;
+			}
 		}
+		if (empty($file_line)) {
+			$file_line = System::getPageName(System::FULL_PATH);
+		}
+		// print "CLASS: " . $class . "
";
 		// get timestamp
 		$timestamp = Support::printTime();
 
@@ -574,7 +593,7 @@ class Logging
 			. '[' . $this->host_name . '] '
 			. '[' . $file_line . '] '
 			. '[' . $this->running_uid . '] '
-			. '{' . $class . '} '
+			. '{' . $caller_class_method . '} '
 			. '<' . strtoupper($group_str) . '> '
 			. $message
 			. $context_str;
diff --git a/test/phpunit/Debug/CoreLibsDebugSupportTest.php b/test/phpunit/Debug/CoreLibsDebugSupportTest.php
index 15e0e9c..2420d5a 100644
--- a/test/phpunit/Debug/CoreLibsDebugSupportTest.php
+++ b/test/phpunit/Debug/CoreLibsDebugSupportTest.php
@@ -562,10 +562,10 @@ final class CoreLibsDebugSupportTest extends TestCase
 	}
 
 	/**
-	 * Undocumented function
+	 * test the lowest one (one above base)
 	 *
 	 * @cover ::getCallerClass
-	 * @testWith ["PHPUnit\\TextUI\\Command"]
+	 * @testWith ["tests\\CoreLibsDebugSupportTest"]
 	 * @testdox getCallerClass check if it returns $expected [$_dataName]
 	 *
 	 * @return void
@@ -578,6 +578,40 @@ final class CoreLibsDebugSupportTest extends TestCase
 		);
 	}
 
+	/**
+	 * test highest return (top level)
+	 *
+	 * @cover ::getCallerTopLevelClass
+	 * @testWith ["PHPUnit\\TextUI\\Command"]
+	 * @testdox getCallerTopLevelClass check if it returns $expected [$_dataName]
+	 *
+	 * @return void
+	 */
+	public function testGetCallerTopLevelClass(string $expected): void
+	{
+		$this->assertEquals(
+			$expected,
+			Support::getCallerTopLevelClass()
+		);
+	}
+
+	/**
+	 * test highest return (top level)
+	 *
+	 * @cover ::getCallerClassMethod
+	 * @testWith ["tests\\CoreLibsDebugSupportTest->testGetCallerClassMethod"]
+	 * @testdox getCallerClassMethod check if it returns $expected [$_dataName]
+	 *
+	 * @return void
+	 */
+	public function testGetCallerClassMethod(string $expected): void
+	{
+		$this->assertEquals(
+			$expected,
+			Support::getCallerClassMethod()
+		);
+	}
+
 	/**
 	 * Undocumented function
 	 *
diff --git a/test/phpunit/Logging/CoreLibsLoggingLoggingTest.php b/test/phpunit/Logging/CoreLibsLoggingLoggingTest.php
index e60efc5..bf9a189 100644
--- a/test/phpunit/Logging/CoreLibsLoggingLoggingTest.php
+++ b/test/phpunit/Logging/CoreLibsLoggingLoggingTest.php
@@ -22,7 +22,7 @@ final class CoreLibsLoggingLoggingTest extends TestCase
 		. "\[[\w\.]+(:\d+)?\]\s{1}" // host:port
 		. "\[[\w\-\.\/]+:\d+\]\s{1}" // folder/file
 		. "\[\w+\]\s{1}" // run id
-		. "{[\w\\\\]+(::\w+)?}\s{1}"; // class
+		. "{[\w\\\\]+((::|->)\w+)?}\s{1}"; // class
 
 	public static function tearDownAfterClass(): void
 	{