[tests-only] Log requests and responses for the failing tests (#7371)

* log request-response to a file

show logs in ci

move hooks to one place

* preserve logs between suites

* ignore logs

* Refactor and beautify logs

* fix php style

* add log step in ci pipeline

* get expected-failure file from env if available

.drone.star

@@ -791,7 +791,8 @@ def localApiTestPipeline(ctx):
                                      ocisServer(storage, params["accounts_hash_difficulty"], extra_server_environment = params["extraServerEnvironment"], with_wrapper = True, tika_enabled = params["tikaNeeded"]) +
                                      (waitForClamavService() if params["antivirusNeeded"] else []) +
                                      (waitForEmailService() if params["emailNeeded"] else []) +
-                                     localApiTests(suite, storage, params["extraEnvironment"]),
+                                     localApiTests(suite, storage, params["extraEnvironment"]) +
+                                     logRequests(),
                             "services": emailService() if params["emailNeeded"] else [] + clamavService() if params["antivirusNeeded"] else [],
                             "depends_on": getPipelineNames([buildOcisBinaryForTesting(ctx)]),
                             "trigger": {
@@ -1007,7 +1008,8 @@ def coreApiTests(ctx, part_number = 1, number_of_parts = 1, storage = "ocis", ac
                              "make -C %s test-acceptance-from-core-api" % (dirs["base"]),
                          ],
                      },
-                 ],
+                 ] +
+                 logRequests(),
         "services": redisForOCStorage(storage),
         "depends_on": getPipelineNames([buildOcisBinaryForTesting(ctx)]),
         "trigger": {
@@ -2817,3 +2819,17 @@ def tikaService():
             "wait-for -it tika:9998 -t 300",
         ],
     }]
+
+def logRequests():
+    return [{
+        "name": "api-test-failure-logs",
+        "image": OC_CI_PHP % DEFAULT_PHP_VERSION,
+        "commands": [
+            "cat %s/tests/acceptance/logs/failed.log" % dirs["base"],
+        ],
+        "when": {
+            "status": [
+                "failure",
+            ],
+        },
+    }]

tests/TestHelpers/HttpLogger.php

@@ -0,0 +1,124 @@
+<?php declare(strict_types=1);
+/**
+ * ownCloud
+ *
+ * @author Sajan Gurung <sajan@jankaritech.com>
+ * @copyright Copyright (c) 2023, ownCloud GmbH
+ *
+ * This code is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License,
+ * as published by the Free Software Foundation;
+ * either version 3 of the License, or any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program. If not, see <http://www.gnu.org/licenses/>
+ *
+ */
+
+namespace TestHelpers;
+
+use Psr\Http\Message\RequestInterface;
+use Psr\Http\Message\ResponseInterface;
+
+/**
+ * Helper for logging HTTP requests and responses
+ */
+class HttpLogger {
+	/**
+	 * @return string
+	 */
+	public static function getLogDir(): string {
+		return __DIR__ . '/../acceptance/logs';
+	}
+
+	/**
+	 * @return string
+	 */
+	public static function getFailedLogPath(): string {
+		return self::getLogDir() . "/failed.log";
+	}
+
+	/**
+	 * @return string
+	 */
+	public static function getScenarioLogPath(): string {
+		return self::getLogDir() . "/scenario.log";
+	}
+
+	/**
+	 * @param string $logFile
+	 * @param string $logMessage
+	 *
+	 * @return void
+	 */
+	public static function writeLog(string $logFile, string $logMessage): void {
+		$file = \fopen($logFile, 'a+') or die('Cannot open file:  ' . $logFile);
+		\fwrite($file, $logMessage);
+		\fclose($file);
+	}
+
+	/**
+	 * @param RequestInterface $request
+	 *
+	 * @return void
+	 */
+	public static function logRequest(RequestInterface $request): void {
+		$method = $request->getMethod();
+		$path = $request->getUri()->getPath();
+		$body = $request->getBody();
+
+		$headers = "";
+		foreach ($request->getHeaders() as $key => $value) {
+			$headers = $key . ": " . $value[0] . "\n";
+		}
+
+		$logMessage = "\t\t_______________________________________________________________________\n\n";
+		$logMessage .= "\t\t==> REQUEST\n";
+		$logMessage .= "\t\t$method $path\n";
+		$logMessage .= "\t\t$headers";
+
+		if ($body->getSize() > 0) {
+			$logMessage .= "\t\t==> REQ BODY\n";
+			$logMessage .= "\t\t$body\n";
+		}
+		$logMessage .= "\n";
+		self::writeLog(self::getScenarioLogPath(), $logMessage);
+	}
+
+	/**
+	 * @param ResponseInterface $response
+	 *
+	 * @return void
+	 */
+	public static function logResponse(ResponseInterface $response): void {
+		$statusCode = $response->getStatusCode();
+		$statusMessage = $response->getReasonPhrase();
+		$body = $response->getBody();
+		$headers = "";
+
+		foreach ($response->getHeaders() as $key => $value) {
+			$headers = $key . ": " . $value[0] . "\n";
+		}
+
+		$logMessage = "\t\t<== RESPONSE\n";
+		$logMessage .= "\t\t$statusCode $statusMessage\n";
+		$logMessage .= "\t\t$headers";
+
+		if ($body->getSize() > 0) {
+			$logMessage .= "\t\t<== RES BODY\n";
+			foreach (\explode("\n", \strval($body)) as $line) {
+				$logMessage .= "\t\t$line\n";
+			}
+		}
+		// rewind the body stream so that later code can read from the start.
+		$response->getBody()->rewind();
+
+		$logMessage = \rtrim($logMessage) . "\n\n";
+		self::writeLog(self::getScenarioLogPath(), $logMessage);
+	}
+}

tests/TestHelpers/HttpRequestHelper.php

@@ -155,6 +155,7 @@ class HttpRequestHelper {
 			}
 		}
 
+		HttpLogger::logResponse($response);
 		return $response;
 	}
 
@@ -428,6 +429,7 @@ class HttpRequestHelper {
 			$headers,
 			$body
 		);
+		HttpLogger::logRequest($request);
 		return $request;
 	}
 

tests/acceptance/.gitignore

@@ -1 +1,2 @@
 output
+logs

tests/acceptance/features/apiDownloads/download.feature

@@ -60,4 +60,3 @@ Feature: Download file in project space
     Given user "Alice" has uploaded a file inside space "download file" with content "new content" to "file.txt"
     When user "Bob" tries to get version of the file "file.txt" with the index "1" of the space "download file" using the WebDAV API
     Then the HTTP status code should be "403"
-

tests/acceptance/features/bootstrap/FeatureContext.php

@@ -27,9 +27,11 @@ use GuzzleHttp\Exception\GuzzleException;
 use Helmich\JsonAssert\JsonAssertions;
 use rdx\behatvars\BehatVariablesContext;
 use Behat\Behat\Hook\Scope\BeforeScenarioScope;
+use Behat\Behat\Hook\Scope\AfterScenarioScope;
 use Behat\Gherkin\Node\PyStringNode;
 use Behat\Gherkin\Node\TableNode;
 use Behat\Testwork\Hook\Scope\BeforeSuiteScope;
+use Behat\Testwork\Hook\Scope\AfterSuiteScope;
 use GuzzleHttp\Cookie\CookieJar;
 use Psr\Http\Message\ResponseInterface;
 use PHPUnit\Framework\Assert;
@@ -37,6 +39,7 @@ use TestHelpers\AppConfigHelper;
 use TestHelpers\OcsApiHelper;
 use TestHelpers\SetupHelper;
 use TestHelpers\HttpRequestHelper;
+use TestHelpers\HttpLogger;
 use TestHelpers\UploadHelper;
 use TestHelpers\OcisHelper;
 use Laminas\Ldap\Ldap;
@@ -572,6 +575,66 @@ class FeatureContext extends BehatVariablesContext {
 		$this->originalAdminPassword = $this->adminPassword;
 	}
 
+	/**
+	 * Create log directory if it doesn't exist
+	 *
+	 * @BeforeSuite
+	 *
+	 * @param BeforeSuiteScope $scope
+	 *
+	 * @return void
+	 * @throws Exception
+	 */
+	public static function setupLogDir(BeforeSuiteScope $scope): void {
+		if (!\file_exists(HttpLogger::getLogDir())) {
+			\mkdir(HttpLogger::getLogDir(), 0777, true);
+		}
+	}
+
+	/**
+	 *
+	 * @BeforeScenario
+	 *
+	 * @param BeforeScenarioScope $scope
+	 *
+	 * @return void
+	 * @throws Exception
+	 */
+	public static function logScenario(BeforeScenarioScope $scope): void {
+		$scenarioLine = self::getScenarioLine($scope);
+
+		if ($scope->getScenario()->getNodeType() === "Example") {
+			$scenario = "Scenario Outline: " . $scope->getScenario()->getOutlineTitle();
+		} else {
+			$scenario = $scope->getScenario()->getNodeType() . ": " . $scope->getScenario()->getTitle();
+		}
+
+		$logMessage = "## $scenario ($scenarioLine)\n";
+	
+		// Delete previous scenario's log file
+		if (\file_exists(HttpLogger::getScenarioLogPath())) {
+			\unlink(HttpLogger::getScenarioLogPath());
+		}
+
+		// Write the scenario log
+		HttpLogger::writeLog(HttpLogger::getScenarioLogPath(), $logMessage);
+	}
+
+	/**
+	 *
+	 * @BeforeStep
+	 *
+	 * @param BeforeStepScope $scope
+	 *
+	 * @return void
+	 * @throws Exception
+	 */
+	public static function logStep(BeforeStepScope $scope): void {
+		$step = $scope->getStep()->getType() . " " . $scope->getStep()->getText();
+		$logMessage = "\t### $step\n";
+		HttpLogger::writeLog(HttpLogger::getScenarioLogPath(), $logMessage);
+	}
+
 	/**
 	 * @param string $appTestCodeFullPath
 	 *
@@ -3578,4 +3641,80 @@ class FeatureContext extends BehatVariablesContext {
 			throw new Exception(__METHOD__ . " accounts-list is empty");
 		}
 	}
+
+	/**
+	 *
+	 * @AfterSuite
+	 *
+	 * @return void
+	 * @throws Exception
+	 */
+	public static function clearScenarioLog(): void {
+		if (\file_exists(HttpLogger::getScenarioLogPath())) {
+			\unlink(HttpLogger::getScenarioLogPath());
+		}
+	}
+
+	/**
+	 * Log request and response logs if scenario fails
+	 *
+	 * @AfterScenario
+	 *
+	 * @param AfterScenarioScope $scope
+	 *
+	 * @return void
+	 * @throws Exception
+	 */
+	public static function checkScenario(AfterScenarioScope $scope): void {
+		if (($scope->getTestResult()->getResultCode() !== 0)
+			&& (!self::isExpectedToFail(self::getScenarioLine($scope)))
+		) {
+			$logs = \file_get_contents(HttpLogger::getScenarioLogPath());
+			// add new lines
+			$logs = \rtrim($logs, "\n") . "\n\n\n";
+			HttpLogger::writeLog(HttpLogger::getFailedLogPath(), $logs);
+		}
+	}
+
+	/**
+	 * @param BeforeScenarioScope|AfterScenarioScope $scope
+	 *
+	 * @return string
+	 */
+	public static function getScenarioLine($scope): string {
+		$feature = $scope->getFeature()->getFile();
+		$feature = \explode('/', $feature);
+		$feature = \array_slice($feature, -2);
+		$feature = \implode('/', $feature);
+		$scenarioLine = $scope->getScenario()->getLine();
+		// Example: apiGraph/createUser.feature:24
+		return $feature . ':' . $scenarioLine;
+	}
+
+	/**
+	 * @param string $scenarioLine
+	 *
+	 * @return bool
+	 */
+	public static function isExpectedToFail(string $scenarioLine): bool {
+		$expectedFailFile = \getenv('EXPECTED_FAILURES_FILE');
+		if (!$expectedFailFile) {
+			$expectedFailFile = __DIR__ . '/../../expected-failures-localAPI-on-OCIS-storage.md';
+			if (\strpos($scenarioLine, "coreApi") === 0) {
+				$expectedFailFile = __DIR__ . '/../../expected-failures-API-on-OCIS-storage.md';
+			}
+		}
+
+		$reader = \fopen($expectedFailFile, 'r');
+		if ($reader) {
+			while (($line = \fgets($reader)) !== false) {
+				if (\strpos($line, $scenarioLine) !== false) {
+					\fclose($reader);
+					return true;
+				}
+			}
+			\fclose($reader);
+		}
+		return false;
+	}
 }