From 894258f8369c45f045dc9d0ef6ca84ce466428c1 Mon Sep 17 00:00:00 2001 From: Dillard Blom Date: Sun, 11 Oct 2026 11:45:27 +0200 Subject: [PATCH 1/3] SFTP: open the channel before the first fast read; backup step: survive a takeover by another process --- CHANGELOG.md | 14 ++++++++++ lib/Backend/SftpReadStream.php | 8 +++++- lib/Service/BackupService.php | 31 +++++++++++++++++++-- psalm-baseline.xml | 2 +- tests/Unit/Backend/SftpReadStreamTest.php | 33 +++++++++++++++++++++++ 5 files changed, 84 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 139f25a..98d8812 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,20 @@ the app store accepts a `-beta` suffix, but Nextcloud servers then only offer th beta/daily update channel, which would hide the app from most admins. The stability stage is instead carried by the app description, the git tag, the release, and this file. +## [Unreleased] + +### Fixed +- 0.9.4 could not open a repository at the root of an SFTP location (empty path): its faster + SFTP reads sent their first request before phpseclib had opened the SFTP channel, which only + happens on the first SFTP call after login. Every backup then failed with "No repository at + this location". The channel is now opened first. +- A long first backup could end as failed although its snapshot was complete: when its final + step took longer than the step's lease (150 s with `occ backup:run`), the background job took + the run over, finished it a second time and failed on the snapshot it had already recorded, + overwriting the result. The lease now lasts at least 15 minutes, a step no longer overwrites a + run that another process wrote in the meantime, and recording a snapshot that is already + recorded is no longer an error. + ## [0.9.4-beta.5] - 2026-10-09 Bugfix release: faster restores. diff --git a/lib/Backend/SftpReadStream.php b/lib/Backend/SftpReadStream.php index c982991..9fa4a5a 100644 --- a/lib/Backend/SftpReadStream.php +++ b/lib/Backend/SftpReadStream.php @@ -108,7 +108,13 @@ final class SftpReadStream { // is_callable and get_object_vars from here only see what is public: phpseclib 3 has // methods of these names neither public nor at all. if (!is_object($sftp) || !is_callable([$sftp, '_send_sftp_packet']) || !is_callable([$sftp, '_get_sftp_packet']) - || !is_callable([$sftp, '_realpath']) || !array_key_exists('packet_type', get_object_vars($sftp))) { + || !is_callable([$sftp, '_realpath']) || !is_callable([$sftp, 'pwd']) + || !array_key_exists('packet_type', get_object_vars($sftp))) { + return null; + } + // phpseclib opens the SFTP channel on its first SFTP call, not at login: on a fresh + // connection a packet sent directly would go nowhere. pwd() opens it like any call does. + if ($sftp->pwd() === false) { return null; } if (!in_array(self::PROTOCOL, stream_get_wrappers(), true)) { diff --git a/lib/Service/BackupService.php b/lib/Service/BackupService.php index 702cf78..0e7a3db 100644 --- a/lib/Service/BackupService.php +++ b/lib/Service/BackupService.php @@ -15,6 +15,7 @@ use OCA\NgBackup\Db\SnapshotMapper; use OCA\NgBackup\Db\Target; use OCA\NgBackup\Job\BackupRun; use OCA\NgBackup\Repository\RepositoryException; +use OCP\AppFramework\Db\DoesNotExistException; use OCP\App\IAppManager; use OCP\IConfig; use OCP\IDBConnection; @@ -105,7 +106,10 @@ final class BackupService { */ public function step(Run $run, float $deadline): Run { // Leases expire on their own: a step killed by a time limit or OOM blocks nothing for long. - $ttl = (int)min(3600, max(120, $deadline - microtime(true) + 120)); + // A step can run well past its deadline (the commit of a large snapshot writes its tree and + // index), so the lease holds at least 15 minutes; should it still expire and another process + // take the run over, the checks below keep the two from overwriting each other. + $ttl = (int)min(3600, max(900, $deadline - microtime(true) + 600)); try { $runLease = $this->leases->acquire('run/' . $run->getId(), LeaseService::EXCLUSIVE, $ttl); } catch (LockedException) { @@ -123,6 +127,7 @@ final class BackupService { if ($run->getStatus() !== Run::RUNNING || $run->getKind() !== self::KIND_FULL) { return $run; } + $loadedAt = $run->getUpdatedAt(); $target = $this->targets->get((string)$run->getTargetId()); $repo = $this->targets->repository($target); $state = json_decode($run->getState(), true, 512, JSON_THROW_ON_ERROR); @@ -179,8 +184,16 @@ final class BackupService { $run->setState(json_encode($state, JSON_THROW_ON_ERROR)); $run->setStats(json_encode(['db' => $state['dbStats'] ?? null, 'files' => $state['files']['stats']], JSON_THROW_ON_ERROR)); $run->setUpdatedAt(time()); - return $this->runs->update($run); + $current = $this->takenOver($run->getId(), $loadedAt); + return $current ?? $this->runs->update($run); } catch (\Throwable $e) { + // Another process that took the run over (after this step's lease expired) may have + // finished it in the meantime: its result stands, this step's error does not. + $current = isset($loadedAt) ? $this->takenOver($run->getId(), $loadedAt) : null; + if ($current !== null) { + $this->logger->warning('NG Backup run ' . $run->getId() . ': a step that another process had taken over ended with: ' . $e->getMessage()); + return $current; + } $this->logger->error('NG Backup run ' . $run->getId() . ' failed: ' . $e->getMessage(), ['exception' => $e]); $run->setStatus(Run::FAILED); $run->setError($e->getMessage()); @@ -198,6 +211,15 @@ final class BackupService { } } + /** + * The run as stored, when another process has written it since this step loaded it (updated_at + * $loadedAt); null when it is still this step's to write. + */ + private function takenOver(int $runId, int $loadedAt): ?Run { + $current = $this->runs->find($runId); + return $current->getUpdatedAt() !== $loadedAt || $current->getStatus() !== Run::RUNNING ? $current : null; + } + /** Run to completion in this process (occ, system cron), reporting progress. */ public function runToCompletion(Run $run, ?callable $progress = null, float $stepSeconds = 30): Run { while ($run->getStatus() === Run::RUNNING) { @@ -224,6 +246,11 @@ final class BackupService { } private function recordSnapshot(Run $run, array $files): void { + try { + $this->snapshots->findOne($run->getTargetId(), $files['snapshot']); + return; // already recorded, by an earlier attempt at this step + } catch (DoesNotExistException) { + } $s = new Snapshot(); $s->setTargetId($run->getTargetId()); $s->setSnapshotId($files['snapshot']); diff --git a/psalm-baseline.xml b/psalm-baseline.xml index 2718b1c..3c4f7fd 100644 --- a/psalm-baseline.xml +++ b/psalm-baseline.xml @@ -395,7 +395,7 @@ - + diff --git a/tests/Unit/Backend/SftpReadStreamTest.php b/tests/Unit/Backend/SftpReadStreamTest.php index abef338..b0a6279 100644 --- a/tests/Unit/Backend/SftpReadStreamTest.php +++ b/tests/Unit/Backend/SftpReadStreamTest.php @@ -231,6 +231,22 @@ class SftpReadStreamTest extends TestCase { $this->assertNull(SftpReadStream::open($storage, 'f')); } + public function testAFreshConnectionHasItsSftpChannelOpenedFirst(): void { + // phpseclib 2 logs in at connect time but opens the SFTP channel on the first SFTP call. + $sftp = new FakeSftpConnection(['/home/config' => 'repository config']); + $this->assertFalse($sftp->initialised); + $fh = SftpReadStream::open(new FakeSftpStorage($sftp), 'config'); + $this->assertIsResource($fh); + $this->assertSame('repository config', stream_get_contents($fh)); + fclose($fh); + } + + public function testAChannelThatCannotBeOpenedLeavesItToTheStoragesOwnStream(): void { + $sftp = new FakeSftpConnection(['/home/config' => 'x'], channelFails: true); + $this->assertNull(SftpReadStream::open(new FakeSftpStorage($sftp), 'config')); + $this->assertSame(0, $sftp->sent, 'nothing may be sent on a connection without an SFTP channel'); + } + public function testAConnectionWithoutTheNeededMethodsIsNotUsed(): void { $storage = new class { public function getRoot(): string { @@ -379,6 +395,10 @@ final class FakeSftpConnection { public array $reads = []; /** @var array */ public array $openHandles = []; + /** Whether the SFTP channel is open: phpseclib 2 opens it on the first SFTP call. */ + public bool $initialised = false; + /** Packets sent */ + public int $sent = 0; /** @var array answers by request id, in the order the server sent them */ private array $answers = []; private int $handles = 0; @@ -393,9 +413,18 @@ final class FakeSftpConnection { /** READ at or past this offset finds the connection gone (phpseclib returns false); -1: OPEN */ private ?int $loseAt = null, private bool $closeFails = false, + private bool $channelFails = false, ) { } + public function pwd(): string|false { + if ($this->channelFails) { + return false; + } + $this->initialised = true; + return '/home'; + } + public function file(string $path): ?string { return $this->files[$path] ?? null; } @@ -409,6 +438,10 @@ final class FakeSftpConnection { } public function _send_sftp_packet(int $type, string $data, int $id = 1): bool { + $this->sent++; + if (!$this->initialised) { + return false; // like phpseclib 2: no SFTP channel yet + } switch ($type) { case 3: // OPEN if ($this->throwAt === -1) { From 638592584582126c93c8db79ccbfdd45b04d2047 Mon Sep 17 00:00:00 2001 From: Dillard Blom Date: Sun, 11 Oct 2026 12:24:00 +0200 Subject: [PATCH 2/3] Backup step: write the run only if no other process wrote it since it was loaded --- CHANGELOG.md | 6 ++--- lib/Db/RunMapper.php | 30 ++++++++++++++++++++++ lib/Service/BackupService.php | 47 +++++++++++++++++++---------------- 3 files changed, 58 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 98d8812..7a1ba66 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,9 +17,9 @@ instead carried by the app description, the git tag, the release, and this file. - A long first backup could end as failed although its snapshot was complete: when its final step took longer than the step's lease (150 s with `occ backup:run`), the background job took the run over, finished it a second time and failed on the snapshot it had already recorded, - overwriting the result. The lease now lasts at least 15 minutes, a step no longer overwrites a - run that another process wrote in the meantime, and recording a snapshot that is already - recorded is no longer an error. + overwriting the result. The lease now lasts at least 15 minutes, a step writes the run only if + no other process wrote it since the step loaded it (in one database statement), and recording + a snapshot that is already recorded is no longer an error. ## [0.9.4-beta.5] - 2026-10-09 diff --git a/lib/Db/RunMapper.php b/lib/Db/RunMapper.php index 9799259..162f4d7 100644 --- a/lib/Db/RunMapper.php +++ b/lib/Db/RunMapper.php @@ -17,6 +17,36 @@ final class RunMapper extends QBMapper { parent::__construct($db, 'ngb_runs', Run::class); } + /** + * Write $run only if it is still running and unchanged since it was loaded (updated_at + * $loadedAt), in one statement: two processes that loaded the same run cannot both write it. + * The new updated_at is always later than $loadedAt, so every write is seen as a change. + * + * @return Run|null the written run, or null when another process wrote it first + */ + public function updateIfUnchanged(Run $run, int $loadedAt): ?Run { + $run->setUpdatedAt(max(time(), $loadedAt + 1)); + $types = $run->getFieldTypes(); + $qb = $this->db->getQueryBuilder(); + $qb->update($this->getTableName()); + foreach (array_keys($run->getUpdatedFields()) as $field) { + if ($field === 'id') { + continue; + } + $value = $run->{'get' . ucfirst($field)}(); + $type = ($types[$field] ?? 'string') === 'integer' ? IQueryBuilder::PARAM_INT : IQueryBuilder::PARAM_STR; + $qb->set($run->propertyToColumn($field), $qb->createNamedParameter($value, $value === null ? IQueryBuilder::PARAM_NULL : $type)); + } + $qb->where($qb->expr()->eq('id', $qb->createNamedParameter($run->getId(), IQueryBuilder::PARAM_INT))) + ->andWhere($qb->expr()->eq('status', $qb->createNamedParameter(Run::RUNNING))) + ->andWhere($qb->expr()->eq('updated_at', $qb->createNamedParameter($loadedAt, IQueryBuilder::PARAM_INT))); + if ($qb->executeStatement() !== 1) { + return null; + } + $run->resetUpdatedFields(); + return $run; + } + public function find(int $id): Run { $qb = $this->db->getQueryBuilder(); $qb->select('*')->from($this->getTableName())->where($qb->expr()->eq('id', $qb->createNamedParameter($id, IQueryBuilder::PARAM_INT))); diff --git a/lib/Service/BackupService.php b/lib/Service/BackupService.php index 0e7a3db..b2ef6ea 100644 --- a/lib/Service/BackupService.php +++ b/lib/Service/BackupService.php @@ -122,6 +122,7 @@ final class BackupService { $this->leases->release($runLease); return $run; } + $loadedAt = null; try { $run = $this->runs->find($run->getId()); // fresh state after acquiring the lock if ($run->getStatus() !== Run::RUNNING || $run->getKind() !== self::KIND_FULL) { @@ -183,23 +184,27 @@ final class BackupService { } $run->setState(json_encode($state, JSON_THROW_ON_ERROR)); $run->setStats(json_encode(['db' => $state['dbStats'] ?? null, 'files' => $state['files']['stats']], JSON_THROW_ON_ERROR)); - $run->setUpdatedAt(time()); - $current = $this->takenOver($run->getId(), $loadedAt); - return $current ?? $this->runs->update($run); + // Another process may have taken the run over after this step's lease expired: then its + // writes stand and this step's are dropped. + return $this->runs->updateIfUnchanged($run, $loadedAt) ?? $this->runs->find($run->getId()); } catch (\Throwable $e) { - // Another process that took the run over (after this step's lease expired) may have - // finished it in the meantime: its result stands, this step's error does not. - $current = isset($loadedAt) ? $this->takenOver($run->getId(), $loadedAt) : null; - if ($current !== null) { - $this->logger->warning('NG Backup run ' . $run->getId() . ': a step that another process had taken over ended with: ' . $e->getMessage()); - return $current; + if ($loadedAt === null) { + // The run could not even be loaded: there is nothing fresh to mark as failed, and + // the caller's copy may be stale. + $this->logger->error('NG Backup run ' . $run->getId() . ': step could not load the run: ' . $e->getMessage(), ['exception' => $e]); + return $run; } - $this->logger->error('NG Backup run ' . $run->getId() . ' failed: ' . $e->getMessage(), ['exception' => $e]); $run->setStatus(Run::FAILED); $run->setError($e->getMessage()); $run->setFinishedAt(time()); - $run->setUpdatedAt(time()); - $run = $this->runs->update($run); + $failed = $this->runs->updateIfUnchanged($run, $loadedAt); + if ($failed === null) { + // Another process that took the run over may have finished it: its result stands. + $this->logger->warning('NG Backup run ' . $run->getId() . ': a step that another process had taken over ended with: ' . $e->getMessage()); + return $this->runs->find($run->getId()); + } + $run = $failed; + $this->logger->error('NG Backup run ' . $run->getId() . ' failed: ' . $e->getMessage(), ['exception' => $e]); try { $this->alerts->runFailed($run, isset($target) ? $target->getName() : '#' . $run->getTargetId()); } catch (\Throwable) { @@ -211,15 +216,6 @@ final class BackupService { } } - /** - * The run as stored, when another process has written it since this step loaded it (updated_at - * $loadedAt); null when it is still this step's to write. - */ - private function takenOver(int $runId, int $loadedAt): ?Run { - $current = $this->runs->find($runId); - return $current->getUpdatedAt() !== $loadedAt || $current->getStatus() !== Run::RUNNING ? $current : null; - } - /** Run to completion in this process (occ, system cron), reporting progress. */ public function runToCompletion(Run $run, ?callable $progress = null, float $stepSeconds = 30): Run { while ($run->getStatus() === Run::RUNNING) { @@ -259,7 +255,14 @@ final class BackupService { $s->setCreatedAt(time()); $s->setFiles($files['stats']['files']); $s->setBytes($files['stats']['bytes']); - $this->snapshots->insert($s); + try { + $this->snapshots->insert($s); + } catch (\OCP\DB\Exception $e) { + // Recorded by another process between the check above and this insert. + if ($e->getReason() !== \OCP\DB\Exception::REASON_UNIQUE_CONSTRAINT_VIOLATION) { + throw $e; + } + } } /** @return list */ From 8e273ac2590fa9c2be7878babe5baf773c69dc99 Mon Sep 17 00:00:00 2001 From: Dillard Blom Date: Sun, 11 Oct 2026 12:30:05 +0200 Subject: [PATCH 3/3] Backup step: reporting on a committed snapshot cannot fail the run; check the snapshot row after a unique violation --- lib/Service/BackupService.php | 29 ++++++++++++++++++++--------- 1 file changed, 20 insertions(+), 9 deletions(-) diff --git a/lib/Service/BackupService.php b/lib/Service/BackupService.php index b2ef6ea..ec78052 100644 --- a/lib/Service/BackupService.php +++ b/lib/Service/BackupService.php @@ -168,14 +168,20 @@ final class BackupService { } if ($state['files']['phase'] === 'done') { $this->recordSnapshot($run, $state['files']); - $this->alerts->storedBytes($target, $repo->storedBytes()); - $stats = $state['files']['stats']; - if (($stats['unreadable'] ?? 0) > 0 || ($stats['changing'] ?? 0) > 0) { - $warnings = BackupRun::warnings($state['files']); - $this->logger->warning(sprintf('NG Backup run %d to %s: %d unreadable (missing from the snapshot): %s; %d changed while being read: %s', - $run->getId(), $target->getName(), $stats['unreadable'] ?? 0, implode(', ', $warnings['unreadable']), - $stats['changing'] ?? 0, implode(', ', $warnings['changing']))); - $this->alerts->runWarnings($run, $target->getName(), (int)($stats['unreadable'] ?? 0), (int)($stats['changing'] ?? 0), $warnings); + // The snapshot is committed: what follows only reports on it and must not turn + // the run into a failure. + try { + $this->alerts->storedBytes($target, $repo->storedBytes()); + $stats = $state['files']['stats']; + if (($stats['unreadable'] ?? 0) > 0 || ($stats['changing'] ?? 0) > 0) { + $warnings = BackupRun::warnings($state['files']); + $this->logger->warning(sprintf('NG Backup run %d to %s: %d unreadable (missing from the snapshot): %s; %d changed while being read: %s', + $run->getId(), $target->getName(), $stats['unreadable'] ?? 0, implode(', ', $warnings['unreadable']), + $stats['changing'] ?? 0, implode(', ', $warnings['changing']))); + $this->alerts->runWarnings($run, $target->getName(), (int)($stats['unreadable'] ?? 0), (int)($stats['changing'] ?? 0), $warnings); + } + } catch (\Throwable $e) { + $this->logger->warning('NG Backup run ' . $run->getId() . ': reporting on the finished backup failed: ' . $e->getMessage(), ['exception' => $e]); } $run->setStatus(Run::DONE); $run->setPhase('done'); @@ -258,10 +264,15 @@ final class BackupService { try { $this->snapshots->insert($s); } catch (\OCP\DB\Exception $e) { - // Recorded by another process between the check above and this insert. + // Recorded by another process between the check above and this insert? if ($e->getReason() !== \OCP\DB\Exception::REASON_UNIQUE_CONSTRAINT_VIOLATION) { throw $e; } + try { + $this->snapshots->findOne($run->getTargetId(), $files['snapshot']); + } catch (DoesNotExistException) { + throw $e; + } } }