Log order of logic execution

src/Debug/OutputBuffer.php

@@ -15,6 +15,7 @@ class OutputBuffer {
 	private Closure $obStartHandler;
 	private Closure $obGetCleanHandler;
 	private string $buffer = "";
+	private bool $bufferOpen = false;
 
 	public function __construct(
 		private bool $debugToJavaScript,
@@ -33,11 +34,19 @@ private function fillBuffer(string $buffer):string {
 	public function start():void {
 		$this->cleanBuffer();
 		($this->obStartHandler)();
+		$this->bufferOpen = true;
 	}
 
 	public function cleanBuffer():void {
+		if(!$this->bufferOpen) {
+			return;
+		}
+
+		$buffer = ($this->obGetCleanHandler)();
+		$this->bufferOpen = false;
+
 		// ob_get_clean can return false; normalise to empty string.
-		$this->fillBuffer(($this->obGetCleanHandler)() ?? "");
+		$this->fillBuffer($buffer ?: "");
 	}
 
 	public function debugOutput():?string {

src/Dispatch/Dispatcher.php

@@ -54,6 +54,8 @@
  * @SuppressWarnings("PHPMD.ExcessiveClassComplexity")
  */
 class Dispatcher {
+	private const LOGIC_EXECUTION_HEADER = "X-Logic-Execution";
+
 	private Config $config;
 	private Request $request;
 	/** @var array<string, array<string, string|array<string, string>>> */
@@ -80,6 +82,8 @@ class Dispatcher {
 	private HeaderManager $headerManager;
 	private Closure $viewInitCb;
 	private bool $redirectPrepared = false;
+	/** @var array<int, string> */
+	private array $logicExecutionOrder = [];
 
 	/**
 	 * @param array<string, array<string, string|array<string, string>>> $globals
@@ -369,9 +373,8 @@ private function handleLogicExecution(
 			$extraArgs[$legacyElementClass] = $component;
 		}
 
-		foreach($this->logicExecutor->invoke($logicAssembly, "go_before", $extraArgs) as $file) {
-			// Force generator execution even when debug output is disabled.
-			continue;
+		foreach($this->logicExecutor->invoke($logicAssembly, "go_before", $extraArgs) as $functionReference) {
+			$this->recordLogicExecution($functionReference);
 		}
 
 // TODO: No need to have the whole Input class. Just pass a nullable string in called $doMethod, from $input->getString("do")
@@ -383,21 +386,18 @@ function(InputData $data)use($logicAssembly, $extraArgs) {
 						$data->getString("do"),
 					);
 
-				foreach($this->logicExecutor->invoke($logicAssembly, $doName, $extraArgs) as $file) {
-					// Force generator execution even when debug output is disabled.
-					continue;
+				foreach($this->logicExecutor->invoke($logicAssembly, $doName, $extraArgs) as $functionReference) {
+					$this->recordLogicExecution($functionReference);
 				}
 			}
 		);
 
-		foreach($this->logicExecutor->invoke($logicAssembly, "go", $extraArgs) as $file) {
-			// Force generator execution even when debug output is disabled.
-			continue;
+		foreach($this->logicExecutor->invoke($logicAssembly, "go", $extraArgs) as $functionReference) {
+			$this->recordLogicExecution($functionReference);
 		}
 
-		foreach($this->logicExecutor->invoke($logicAssembly, "go_after", $extraArgs) as $file) {
-			// Force generator execution even when debug output is disabled.
-			continue;
+		foreach($this->logicExecutor->invoke($logicAssembly, "go_after", $extraArgs) as $functionReference) {
+			$this->recordLogicExecution($functionReference);
 		}
 	}
 
@@ -408,6 +408,7 @@ function(InputData $data)use($logicAssembly, $extraArgs) {
 	public function processResponse(
 		?Throwable $errorThrowable = null,
 	):void {
+		$this->logicExecutionOrder = [];
 		$dynamicPath = $this->serviceContainer->get(DynamicPath::class);
 
 		$this->viewModelProcessor?->processDynamicPath(
@@ -460,6 +461,13 @@ public function processResponse(
 			}
 		}
 
+		if($this->logicExecutionOrder) {
+			$this->response = $this->response->withHeader(
+				self::LOGIC_EXECUTION_HEADER,
+				implode(";", $this->logicExecutionOrder),
+			);
+		}
+
 		if($responseWithHeader = $this->headerManager->applyWithHeader(
 			$this->response->getResponseHeaders(),
 			$this->response->withHeader(...)
@@ -476,6 +484,40 @@ public function processResponse(
 	}
 	// phpcs:enable Generic.Metrics.CyclomaticComplexity.TooHigh
 
+	private function recordLogicExecution(string $functionReference):void {
+		$refWithoutAttributes = explode("#", $functionReference, 2)[0];
+		$separatorPosition = strrpos($refWithoutAttributes, "::");
+		if($separatorPosition === false) {
+			return;
+		}
+
+		$file = substr($refWithoutAttributes, 0, $separatorPosition);
+		$function = substr($refWithoutAttributes, $separatorPosition + 2);
+		$function = preg_replace('/\(\)$/', '', $function);
+		if($function === null || $function === "") {
+			return;
+		}
+
+		$this->logicExecutionOrder[] = sprintf(
+			"%s:%s",
+			$this->normaliseLogicExecutionFile($file),
+			$function,
+		);
+	}
+
+	private function normaliseLogicExecutionFile(string $file):string {
+		$cwd = getcwd();
+		if($cwd && str_starts_with($file, $cwd . DIRECTORY_SEPARATOR)) {
+			$file = substr($file, strlen($cwd) + 1);
+		}
+
+		if(str_ends_with($file, ".php")) {
+			$file = substr($file, 0, -4);
+		}
+
+		return $file;
+	}
+
 	private function verifyCsrfRequest(string $method, InputData $inputData):void {
 		if($method !== "POST" || $this->isIgnoredCsrfPath()) {
 			return;

test/phpunit/ApplicationTest.php

@@ -40,29 +40,29 @@ public function testStart_callsRedirectExecute():void {
 			->method("execute")
 			->willReturn(null);
 
-			$globalProtection = self::createStub(Protection::class);
-			$serverRequest = self::createStub(ServerRequest::class);
-			$serverRequest->method("getUri")
-				->willReturn(self::createStub(Uri::class));
-			$serverRequest->method("getHeaderLine")
-				->willReturnCallback(
-					fn(string $name):string => strtolower($name) === "accept" ? "*/*" : ""
-				);
+		$globalProtection = self::createStub(Protection::class);
+		$serverRequest = self::createStub(ServerRequest::class);
+		$serverRequest->method("getUri")
+			->willReturn(self::createStub(Uri::class));
+		$serverRequest->method("getHeaderLine")
+			->willReturnCallback(
+				fn(string $name):string => strtolower($name) === "accept" ? "*/*" : ""
+			);
 		$serverRequest->method("getMethod")
 			->willReturn("GET");
-			$requestFactory = self::createStub(RequestFactory::class);
-			$requestFactory->method("createServerRequestFromGlobalState")
-				->willReturn($serverRequest);
-			$dispatcher = self::createStub(Dispatcher::class);
+		$requestFactory = self::createStub(RequestFactory::class);
+		$requestFactory->method("createServerRequestFromGlobalState")
+			->willReturn($serverRequest);
+		$dispatcher = self::createStub(Dispatcher::class);
 
-			$response = self::createStub(Response::class);
+		$response = self::createStub(Response::class);
 		$response->method('getStatusCode')->willReturn(200);
 		$response->method('getHeaders')->willReturn(['Content-Type' => ['text/html']]);
 		$response->method('getBody')->willReturn(new \GT\Http\Stream());
 		$dispatcher->method('generateResponse')->willReturn($response);
 
-			$dispatcherFactory = self::createStub(DispatcherFactory::class);
-			$dispatcherFactory->method('create')->willReturn($dispatcher);
+		$dispatcherFactory = self::createStub(DispatcherFactory::class);
+		$dispatcherFactory->method('create')->willReturn($dispatcher);
 
 		// Avoid warnings by ensuring server params contain REMOTE_ADDR
 		$serverRequest->method('getServerParams')->willReturn(['REMOTE_ADDR' => '127.0.0.1']);
@@ -85,23 +85,23 @@ public function testStart_callsTimerFunctions():void {
 		$timer->expects(self::once())
 			->method("logDelta");
 
-			$dispatcher = self::createStub(Dispatcher::class);
-			$response = self::createStub(Response::class);
+		$dispatcher = self::createStub(Dispatcher::class);
+		$response = self::createStub(Response::class);
 		$response->method('getStatusCode')->willReturn(200);
 		$response->method('getHeaders')->willReturn(['Content-Type' => ['text/html']]);
 		$response->method('getBody')->willReturn(new \GT\Http\Stream());
 		$dispatcher->method('generateResponse')->willReturn($response);
-			$dispatcherFactory = self::createStub(DispatcherFactory::class);
-			$dispatcherFactory->method('create')->willReturn($dispatcher);
-
-			$requestFactory = self::createStub(RequestFactory::class);
-			$serverRequest = self::createStub(ServerRequest::class);
-			$serverRequest->method('getServerParams')->willReturn(['REMOTE_ADDR' => '127.0.0.1']);
-				$serverRequest->method('getUri')->willReturn(self::createStub(Uri::class));
-			$serverRequest->method('getHeaderLine')
-				->willReturnCallback(
-					fn(string $name):string => strtolower($name) === "accept" ? "*/*" : ""
-				);
+		$dispatcherFactory = self::createStub(DispatcherFactory::class);
+		$dispatcherFactory->method('create')->willReturn($dispatcher);
+
+		$requestFactory = self::createStub(RequestFactory::class);
+		$serverRequest = self::createStub(ServerRequest::class);
+		$serverRequest->method('getServerParams')->willReturn(['REMOTE_ADDR' => '127.0.0.1']);
+		$serverRequest->method('getUri')->willReturn(self::createStub(Uri::class));
+		$serverRequest->method('getHeaderLine')
+			->willReturnCallback(
+				fn(string $name):string => strtolower($name) === "accept" ? "*/*" : ""
+			);
 		$serverRequest->method('getMethod')->willReturn('GET');
 		$requestFactory->method('createServerRequestFromGlobalState')->willReturn($serverRequest);
 
@@ -250,7 +250,7 @@ public function testStart_callErrorScriptOnThrowable():void {
 		$output = ob_get_clean();
 		ob_end_clean();
 
-			self::assertStringContainsString("exception message is testing", $output);
+		self::assertStringContainsString("exception message is testing", $output);
 	}
 
 	public function testStart_protectsGlobalsUsingConfiguredWhitelists():void {
@@ -363,7 +363,7 @@ public function testStart_rebuildsDispatcherWithErrorStatusAndSessionInit():void
 				Closure $finishCallback,
 				?int $errorStatus = null,
 				?SessionInit $passedSessionInit = null,
-			)use($config, $request, $sessionInit, &$createCalls, $firstDispatcher, $secondDispatcher) {
+			) use ($config, $request, $sessionInit, &$createCalls, $firstDispatcher, $secondDispatcher) {
 				$createCalls[] = [
 					"config" => $passedConfig,
 					"request" => $passedRequest,
@@ -1080,22 +1080,22 @@ private function createTestConfig(array $mockedValues):Config {
 		$configContents = parse_ini_file($configFile, true);
 
 		$map = [];
-		foreach ($configContents as $section => $kvp) {
-			foreach ($kvp as $key => $value) {
+		foreach($configContents as $section => $kvp) {
+			foreach($kvp as $key => $value) {
 				$map["$section.$key"] = $value;
 			}
 		}
 
 		$map = array_merge($map, $mockedValues);
 
-		$config->method(self::anything())->willReturnCallback(function ($key) use ($map) {
+		$config->method(self::anything())->willReturnCallback(function($key) use ($map) {
 			$type = null;
 			$bt = debug_backtrace();
 			if(isset($bt[1]) && ($bt[1]["args"][0] ?? null) instanceof Invocation) {
 				$type = strtolower(substr($bt[1]["args"][0]->methodName(), 3));
 			}
 
-			return match($type) {
+			return match ($type) {
 				"bool" => (bool)$map[$key],
 				"int" => (int)$map[$key],
 				"float" => (float)$map[$key],

test/phpunit/Debug/OutputBufferTest.php

@@ -52,9 +52,10 @@ public function testCleanBuffer_accumulatesAndNormalisesNull(): void {
 		$obGetClean = function() use (&$sequence) { return array_shift($sequence); };
 		$sut = new OutputBuffer(true, $obStart, $obGetClean);
 		$sut->start();
-		// Manually accumulate twice, then let debugOutput() call a final clean
 		$sut->cleanBuffer(); // "one"
+		$sut->start();
 		$sut->cleanBuffer(); // null -> ""
+		$sut->start();
 		$html = $sut->debugOutput(); // "two" + emit script
 		self::assertNotNull($html);
 		self::assertStringContainsString('onetwo', $html);

test/phpunit/Dispatch/DispatcherTest.php

@@ -174,9 +174,7 @@ public function testGenerateResponse_executesComponentAndPageLogicAndAppliesHead
 					"name" => $name,
 					"extraArgs" => $extraArgs,
 				];
-				if(false) {
-					yield "never";
-				}
+				yield ($assembly === $componentAssembly ? "/tmp/component.php" : "/tmp/page.php") . "::$name()";
 			});
 
 		$headerManager = $this->createMock(HeaderManager::class);
@@ -210,6 +208,17 @@ public function testGenerateResponse_executesComponentAndPageLogicAndAppliesHead
 
 		self::assertSame(StatusCode::OK, $response->getStatusCode());
 		self::assertSame("applied", $response->getHeaderLine("X-Test"));
+		self::assertSame(
+			"/tmp/component:go_before;"
+			. "/tmp/component:do_save_item;"
+			. "/tmp/component:go;"
+			. "/tmp/component:go_after;"
+			. "/tmp/page:go_before;"
+			. "/tmp/page:do_save_item;"
+			. "/tmp/page:go;"
+			. "/tmp/page:go_after",
+			$response->getHeaderLine("X-Logic-Execution"),
+		);
 		self::assertSame([
 			["assembly" => "component", "name" => "go_before"],
 			["assembly" => "component", "name" => "do_save_item"],