Merge pull request #2744 from dafriend/Logger-file-line-fix

Logger {file} {line} fix

Author: MGatner

system/Log/Logger.php

@@ -467,37 +467,52 @@ protected function interpolate($message, array $context = [])
 		return strtr($message, $replace);
 	}
 
-	//--------------------------------------------------------------------
 
 	/**
-	 * Determines the current file/line that the log method was called from.
-	 * by analyzing the backtrace.
+	 * Determines the file and line that the logging call
+	 * was made from by analyzing the backtrace.
+	 * Find the earliest stack frame that is part of our logging system.
 	 *
 	 * @return array
 	 */
 	public function determineFile(): array
 	{
-		// Determine the file and line by finding the first
-		// backtrace that is not part of our logging system.
-		$trace = debug_backtrace();
-		$file  = null;
-		$line  = null;
+		$logFunctions = [
+			'log_message',
+			'log',
+			'error',
+			'debug',
+			'info',
+			'warning',
+			'critical',
+			'emergency',
+			'alert',
+			'notice',
+		];
+
+		// Generate Backtrace info
+		$trace = \debug_backtrace(false);
 
-		foreach ($trace as $row)
+		// So we search from the bottom (earliest) of the stack frames
+		$stackFrames = \array_reverse($trace);
+
+		// Find the first reference to a Logger class method
+		foreach ($stackFrames as $frame)
 		{
-			if (in_array($row['function'], ['interpolate', 'determineFile', 'log', 'log_message']))
+			if (\in_array($frame['function'], $logFunctions))
 			{
-				continue;
+				$file = isset($frame['file']) ? $this->cleanFileNames($frame['file']) : 'unknown';
+				$line = $frame['line'] ?? 'unknown';
+				return [
+					$file,
+					$line,
+				];
 			}
-
-			$file = $row['file'] ?? isset($row['object']) ? get_class($row['object']) : 'unknown';
-			$line = $row['line'] ?? $row['function'] ?? 'unknown';
-			break;
 		}
 
 		return [
-			$file,
-			$line,
+			'unknown',
+			'unknown',
 		];
 	}
 

tests/system/Log/FileHandlerTest.php

@@ -17,7 +17,8 @@ protected function setUp(): void
 
 	public function testHandle()
 	{
-		$config                                                                = new LoggerConfig();
+		$config = new LoggerConfig();
+
 		$config->handlers['Tests\Support\Log\Handlers\TestHandler']['handles'] = ['critical'];
 
 		$logger = new MockFileLogger($config->handlers['Tests\Support\Log\Handlers\TestHandler']);
@@ -32,7 +33,8 @@ public function testBasicHandle()
 		$config                                                                = new LoggerConfig();
 		$config->handlers['Tests\Support\Log\Handlers\TestHandler']['path']    = $this->start . 'charlie/';
 		$config->handlers['Tests\Support\Log\Handlers\TestHandler']['handles'] = ['critical'];
-		$logger                                                                = new MockFileLogger($config->handlers['Tests\Support\Log\Handlers\TestHandler']);
+
+		$logger = new MockFileLogger($config->handlers['Tests\Support\Log\Handlers\TestHandler']);
 		$logger->setDateFormat('Y-m-d H:i:s:u');
 		$expected = 'log-' . date('Y-m-d') . '.log';
 		vfsStream::newFile($expected)->at(vfsStream::setup('root/charlie'))->withContent('This is a test log');

tests/system/Log/LoggerTest.php

@@ -204,16 +204,13 @@ public function testLogInterpolatesFileAndLine()
 
 		$_ENV['foo'] = 'bar';
 
-		// For whatever reason, this will often be the class/function instead of file and line.
-		// Other times it actually returns the line number, so don't look for either
-		$expected = 'DEBUG - ' . date('Y-m-d') . ' --> Test message LoggerTest';
-
 		$logger->log('debug', 'Test message {file} {line}');
+		$line     = __LINE__ - 1;
+		$expected = "LoggerTest.php $line";
 
 		$logs = TestHandler::getLogs();
 
-		$this->assertCount(1, $logs);
-		$this->assertTrue(strpos($logs[0], $expected) === 0);
+		$this->assertTrue(strpos($logs[0], $expected) > 1);
 	}
 
 	//--------------------------------------------------------------------