DO NOT REVIEW - chore(cypress): Try to analyze failures

apps/files_versions/lib/Storage.php

@@ -423,7 +423,30 @@
 		[$storage2, $internalPath2] = $view->resolvePath($path2);
 
 		$view->lockFile($path1, ILockingProvider::LOCK_EXCLUSIVE);
-		$view->lockFile($path2, ILockingProvider::LOCK_EXCLUSIVE);
+		try {
+			$view->lockFile($path2, ILockingProvider::LOCK_EXCLUSIVE);
+		} catch (\Throwable $e) {
+			// DIAGNOSTIC: dump all currently-held file locks to identify the
+			// concurrent holder blocking the restore (lock: -1 exclusive, >0 shared).
+			try {
+				$db = \OCP\Server::get(\OCP\IDBConnection::class);
+				$q = $db->getQueryBuilder();
+				$q->select('key', 'lock')->from('file_locks')
+					->where($q->expr()->neq('lock', $q->createNamedParameter(0, \OCP\DB\QueryBuilder\IQueryBuilder::PARAM_INT)));
+				$held = $q->executeQuery()->fetchAll();
+				\OCP\Server::get(\Psr\Log\LoggerInterface::class)->error(
+					'[restore-lock-diag] target=' . $internalPath2 . ' heldLocks=' . json_encode($held),
+					['app' => 'files_versions'],
+				);
+			} catch (\Throwable $ignore) {
+			}
+			// Acquiring the second lock can fail (e.g. the target file is
+			// transiently locked by a concurrent job under load). Release the
+			// first lock we already hold so a retry does not collide with a
+			// leaked lock.
+			$view->unlockFile($path1, ILockingProvider::LOCK_EXCLUSIVE);
+			throw $e;
+		}
 
 		try {
 			// TODO add a proper way of overwriting a file while maintaining file ids
@@ -464,7 +487,7 @@
 			}
 		} finally {
 			$view->unlockFile($path1, ILockingProvider::LOCK_EXCLUSIVE);
 			$view->unlockFile($path2, ILockingProvider::LOCK_EXCLUSIVE);
 		}
 
 		return ($result !== false);

apps/files_versions/lib/Versions/VersionManager.php

@@ -22,8 +22,10 @@
 use OCP\Files\Node;
 use OCP\Files\Storage\IStorage;
 use OCP\IUser;
+use OCP\Lock\LockedException;
 use OCP\Lock\ManuallyLockedException;
 use OCP\Server;
+use Psr\Log\LoggerInterface;
 
 class VersionManager implements IVersionManager, IDeletableVersionBackend, INeedSyncVersionBackend, IMetadataVersionBackend {
 
@@ -100,7 +102,7 @@ public function createVersion(IUser $user, FileInfo $file) {
 	#[\Override]
 	public function rollback(IVersion $version) {
 		$backend = $version->getBackend();
-		$result = self::handleAppLocks(fn (): ?bool => $backend->rollback($version));
+		$result = self::handleAppLocks(fn (): ?bool => self::retryOnLock(fn (): ?bool => $backend->rollback($version)));
 		// rollback doesn't have a return type yet and some implementations don't return anything
 		if ($result === null || $result === true) {
 			$this->dispatcher->dispatchTyped(new VersionRestoredEvent($version));
@@ -180,6 +182,45 @@ public function setMetadataValue(Node $node, int $revision, string $key, string
 		}
 	}
 
+	/**
+	 * Retry the rollback while the target file is transiently locked.
+	 *
+	 * Restoring a version needs an exclusive lock on the live file. Under load,
+	 * a concurrent operation on the same file — e.g. the versions expiration
+	 * job — can hold a lock on it, which makes the exclusive lock fail with a
+	 * LockedException and the whole restore return HTTP 500. That lock is not
+	 * held by our own request (so it is released independently of us) and is
+	 * short lived, so we keep retrying with a growing backoff until it clears
+	 * or we exceed a generous overall budget.
+	 *
+	 * @param callable $callback function performing the rollback
+	 * @return bool|null
+	 * @throws LockedException if the file stays locked for the whole budget
+	 */
+	private static function retryOnLock(callable $callback): ?bool {
+		// Total time we are willing to wait for a concurrent lock to clear.
+		$budgetMs = 15000;
+		$waitedMs = 0;
+		$backoffMs = 100;
+		for ($attempt = 1; ; $attempt++) {
+			try {
+				return $callback();
+			} catch (LockedException $e) {
+				if ($waitedMs >= $budgetMs) {
+					throw $e;
+				}
+				Server::get(LoggerInterface::class)->debug(
+					'Version rollback hit a locked file, retrying (attempt {attempt}, waited {waited}ms)',
+					['attempt' => $attempt, 'waited' => $waitedMs, 'app' => 'files_versions', 'exception' => $e],
+				);
+				usleep($backoffMs * 1000);
+				$waitedMs += $backoffMs;
+				// Grow the backoff but cap it so we keep probing regularly.
+				$backoffMs = min($backoffMs * 2, 1000);
+			}
+		}
+	}
+
 	/**
 	 * Catch ManuallyLockedException and retry in app context if possible.
 	 *

apps/files_versions/tests/VersioningTest.php

@@ -27,6 +27,8 @@
 use OCP\IConfig;
 use OCP\IUser;
 use OCP\IUserManager;
+use OCP\Lock\ILockingProvider;
+use OCP\Lock\LockedException;
 use OCP\Server;
 use OCP\Share\IShare;
 use OCP\User\Exceptions\UserNotFoundException;
@@ -763,6 +765,56 @@ function ($p) use (&$params): void {
 		);
 	}
 
+	/**
+	 * Restoring a version needs an exclusive lock on the live file. When another
+	 * request holds a shared (read) lock on that file at the same time — most
+	 * notably the versions sidebar generating a preview of the file via
+	 * OCA\Files_Versions\Controller\PreviewController — the exclusive lock cannot
+	 * be acquired and the restore throws a LockedException (surfacing as an HTTP
+	 * 500). This test reproduces that collision deterministically.
+	 */
+	public function testRestoreFailsWhileFileIsReadLocked(): void {
+		$filePath = self::TEST_VERSIONS_USER . '/files/sub/test.txt';
+		$this->rootView->mkdir(self::TEST_VERSIONS_USER . '/files/sub');
+		$this->rootView->file_put_contents($filePath, 'test file');
+		$fileInfo = $this->rootView->getFileInfo($filePath);
+
+		// Create a single older version to restore to.
+		$t2 = time() - 60 * 60 * 24 * 14;
+		$v2 = self::USERS_VERSIONS_ROOT . '/sub/test.txt.v' . $t2;
+		$this->rootView->mkdir(self::USERS_VERSIONS_ROOT . '/sub');
+		$this->rootView->file_put_contents($v2, 'version2');
+		$fileInfoV2 = $this->rootView->getFileInfo($v2);
+		$versionEntity = new VersionEntity();
+		$versionEntity->setFileId($fileInfo->getId());
+		$versionEntity->setTimestamp($t2);
+		$versionEntity->setSize($fileInfoV2->getSize());
+		$versionEntity->setMimetype($this->mimeTypeLoader->getId($fileInfoV2->getMimetype()));
+		$versionEntity->setMetadata([]);
+		$this->versionsMapper->insert($versionEntity);
+
+		// Simulate a concurrent version-preview read holding a shared lock.
+		$userView = new View('/' . self::TEST_VERSIONS_USER . '/files');
+		$userView->lockFile('/sub/test.txt', ILockingProvider::LOCK_SHARED);
+
+		// The low-level restore takes an exclusive lock on the live file, which
+		// must fail while the shared lock is held — this is the bug behind the 500.
+		$threw = false;
+		try {
+			Storage::rollback('/sub/test.txt', $t2, $this->user1);
+		} catch (LockedException $e) {
+			$threw = true;
+		}
+		$this->assertTrue($threw, 'Restore should fail with LockedException while the file is read-locked');
+		$this->assertEquals('test file', $this->rootView->file_get_contents($filePath), 'File must be unchanged after the failed restore');
+
+		// Once the read lock is released, the very same restore succeeds — proving
+		// the shared lock is the sole cause of the failure.
+		$userView->unlockFile('/sub/test.txt', ILockingProvider::LOCK_SHARED);
+		$this->assertTrue(Storage::rollback('/sub/test.txt', $t2, $this->user1));
+		$this->assertEquals('version2', $this->rootView->file_get_contents($filePath));
+	}
+
 	private function doTestRestore(): void {
 		$filePath = self::TEST_VERSIONS_USER . '/files/sub/test.txt';
 		$this->rootView->file_put_contents($filePath, 'test file');

core/Controller/CSRFTokenController.php

@@ -44,11 +44,35 @@
 	#[NoTwoFactorRequired]
 	public function index(): JSONResponse {
 		if (!$this->request->passesStrictCookieCheck()) {
+			// [login-diag] A 403 here means cy.login receives no token, so its
+			// POST /login then fails the CSRF check -> validate 401. Record it.
+			\OCP\Server::get(\Psr\Log\LoggerInterface::class)->error(
+				'[login-diag] CSRFTOKEN 403 strictCookieCheck failed remote=' . $this->request->getRemoteAddress()
+				. ' cookies=' . implode(',', array_keys($_COOKIE ?? [])),
+				['app' => 'login-diag'],
+			);
 			return new JSONResponse([], Http::STATUS_FORBIDDEN);
 		}
 
 		$requestToken = $this->tokenManager->getToken();
 
+		// [login-diag] Record the session this token was issued into, so a later
+		// csrfCheckFailed on /login can be matched against it: if the /login
+		// session/sessCookie differs from what /csrftoken issued into, the token
+		// legitimately isn't in /login's session (a session-mismatch race).
+		try {
+			$session = \OCP\Server::get(\OCP\ISession::class);
+			$raw = $this->request->getCookie(session_name());
+			\OCP\Server::get(\Psr\Log\LoggerInterface::class)->error(
+				'[login-diag] CSRFTOKEN issued remote=' . $this->request->getRemoteAddress()
+				. ' session=' . substr(md5((string)$session->getId()), 0, 8)
+				. ' sessCookie=' . ($raw !== null ? substr(md5($raw), 0, 8) : 'none'),
+				['app' => 'login-diag'],
+			);
+		} catch (\Throwable) {
+			// diagnostics must never affect the token endpoint
+		}
+
 		return new JSONResponse([
 			'token' => $requestToken->getEncryptedValue(),
 		]);

core/Controller/LoginController.php

@@ -366,12 +366,74 @@
 			);
 		}
 
+		// [login-diag] Successful login: record so we can tell a login-logic
+		// failure apart from a session/cookie propagation failure on the
+		// subsequent validate request.
+		$this->logLoginDiag('LOGIN OK', $user);
+
 		if ($result->getRedirectUrl() !== null) {
 			return new RedirectResponse($result->getRedirectUrl());
 		}
 		return $this->generateRedirect($redirect_url);
 	}
 
+	/**
+	 * [login-diag] Throwaway diagnostic logger for the e2e login flake. Emits a
+	 * single correlatable line (session id hash, remote addr, throttle delay)
+	 * so we can trace a failed `cy.login` back to its server-side cause. Must
+	 * never break the login flow, hence the broad catch.
+	 */
+	private function logLoginDiag(string $what, string $user): void {
+		try {
+			$remote = $this->request->getRemoteAddress();
+			try {
+				$session = substr(md5((string)$this->session->getId()), 0, 8);
+			} catch (\Throwable) {
+				$session = 'n/a';
+			}
+			// Break down passesCSRFCheck() so a csrfCheckFailed tells us WHICH
+			// sub-check failed: the strict same-site cookie check, or the token
+			// validation (a missing session 'requesttoken' means the /login
+			// request landed on a different session than /csrftoken issued into).
+			try {
+				$strictCookie = $this->request->passesStrictCookieCheck() ? '1' : '0';
+			} catch (\Throwable) {
+				$strictCookie = 'err';
+			}
+			try {
+				$sessHasReqToken = $this->session->exists('requesttoken') ? '1' : '0';
+			} catch (\Throwable) {
+				$sessHasReqToken = 'err';
+			}
+			// Hash of the session cookie the client actually sent, to compare the
+			// /csrftoken-issuing session against the /login session.
+			$sessCookie = 'none';
+			try {
+				$raw = $this->request->getCookie(session_name());
+				if ($raw !== null) {
+					$sessCookie = substr(md5($raw), 0, 8);
+				}
+			} catch (\Throwable) {
+				$sessCookie = 'err';
+			}
+			\OCP\Server::get(\Psr\Log\LoggerInterface::class)->error(
+				'[login-diag] ' . $what
+				. ' user=' . $user
+				. ' remote=' . $remote
+				. ' session=' . $session
+				. ' sessCookie=' . $sessCookie
+				. ' strictCookie=' . $strictCookie
+				. ' sessHasReqToken=' . $sessHasReqToken
+				. ' csrf=' . ($this->request->passesCSRFCheck() ? '1' : '0')
+				. ' origin=' . $this->request->getHeader('Origin')
+				. ' delay=' . $this->throttler->getDelay($remote, 'login'),
+				['app' => 'login-diag'],
+			);
+		} catch (\Throwable) {
+			// diagnostics must never affect the login path
+		}
+	}
+
 	/**
 	 * Creates a login failed response.
 	 *
@@ -389,6 +451,11 @@
 		string $loginMessage,
 		bool $throttle = true,
 	) {
+		// [login-diag] Every login failure path funnels through here, so this is
+		// the single point that reveals *why* a login POST did not establish a
+		// session (invalidOrigin / csrfCheckFailed / invalidpassword / ...).
+		$this->logLoginDiag('LOGIN FAILED reason=' . $loginMessage . ' throttle=' . ($throttle ? '1' : '0'), (string)$originalUser);
+
 		// Read current user and append if possible we need to
 		// return the unmodified user otherwise we will leak the login name
 		$args = $user !== null ? ['user' => $originalUser, 'direct' => 1] : [];

cypress.config.ts

@@ -26,11 +26,7 @@ export default defineConfig({
 	viewportHeight: 720,
 
 	// Tries again when in run mode (cypress run) e.g. on CI
-	retries: {
-		runMode: 5,
-		// do not retry in `cypress open`
-		openMode: 0,
-	},
+	retries: 0,
 
 	// Needed to trigger `after:run` events with cypress open
 	experimentalInteractiveRunEvents: true,
@@ -71,6 +67,13 @@ export default defineConfig({
 			// because Cypress.env() and other options are local to the current spec file.
 			const data: Record<string, unknown> = {}
 			on('task', {
+				// Print a message to the Node/terminal stdout (browser console.log
+				// is not piped to the cypress run output in headless mode).
+				log(message) {
+					// eslint-disable-next-line no-console
+					console.log(message)
+					return null
+				},
 				setVariable({ key, value }) {
 					data[key] = value
 					return null

cypress/e2e/files/FilesUtils.ts

@@ -62,6 +62,52 @@ export function getInlineActionEntryForFile(file: string, actionId: string) {
 	return cy.get(`[data-cy-files-list-row-name="${CSS.escape(file)}"] [data-cy-files-list-row-action="${CSS.escape(actionId)}"]`)
 }
 
+/**
+ * Open the actions menu of a file row and wait until it is displayed.
+ *
+ * Click exactly once, then wait: while the popover opens, the toggle
+ * already reports aria-expanded="true" although the menu is still hidden —
+ * the popover positions itself over several frames, which can take seconds
+ * on slow (CI) runners. Clicking again in that state toggles the menu
+ * closed and tangles the popover's show and hide transitions into a stuck,
+ * permanently invisible popover. Clicking is only safe while the toggle
+ * reports "closed", e.g. after an auto-close caused by a stray outside
+ * click.
+ *
+ * @param getActionButton query for the actions menu toggle of the row
+ */
+export function openActionsMenu(getActionButton: () => Cypress.Chainable<JQuery<HTMLElement>>) {
+	// The menu open has two failure modes on slow runners, needing opposite
+	// responses:
+	//   - The click is lost because the row's handler is not attached yet, so
+	//     the toggle stays collapsed (aria-expanded="false"). We must click
+	//     again.
+	//   - The menu is opening but the popover is still positioning over a few
+	//     frames (aria-expanded="true", not yet visible). Clicking again here
+	//     would toggle it closed and tangle the show/hide transitions, so we
+	//     must only wait.
+	// Poll accordingly until the menu is actually displayed.
+	const poll = (elapsed: number) => {
+		getActionButton().then(($toggle) => {
+			const menuId = $toggle.attr('aria-controls')
+			if (menuId && Cypress.$(`#${menuId}`).is(':visible')) {
+				return
+			}
+			if (elapsed >= 20000) {
+				throw new Error(`Actions menu did not open (aria-expanded=${$toggle.attr('aria-expanded')})`)
+			}
+			// Only (re)open while collapsed; never click a menu that is mid-open.
+			if ($toggle.attr('aria-expanded') !== 'true') {
+				cy.wrap($toggle).click({ force: true }) // force to avoid issues with overlaying file list header
+			}
+			// eslint-disable-next-line cypress/no-unnecessary-waiting -- give the popover a moment to open/position before re-checking
+			cy.wait(250)
+			poll(elapsed + 250)
+		})
+	}
+	poll(0)
+}
+
 /**
  *
  * @param fileid
@@ -70,8 +116,7 @@ export function getInlineActionEntryForFile(file: string, actionId: string) {
 export function triggerActionForFileId(fileid: number, actionId: string) {
 	getActionButtonForFileId(fileid)
 		.scrollIntoView()
-	getActionButtonForFileId(fileid)
-		.click({ force: true }) // force to avoid issues with overlaying file list header
+	openActionsMenu(() => getActionButtonForFileId(fileid))
 	getActionEntryForFileId(fileid, actionId)
 		.find('button')
 		.should('be.visible')
@@ -86,8 +131,7 @@ export function triggerActionForFileId(fileid: number, actionId: string) {
 export function triggerActionForFile(filename: string, actionId: string) {
 	getActionButtonForFile(filename)
 		.scrollIntoView()
-	getActionButtonForFile(filename)
-		.click({ force: true }) // force to avoid issues with overlaying file list header
+	openActionsMenu(() => getActionButtonForFile(filename))
 	getActionEntryForFile(filename, actionId)
 		.find('button')
 		.should('be.visible')