diff --git a/app/Services/FileSystem/AbstractFileDownloadStrategy.php b/app/Services/FileSystem/AbstractFileDownloadStrategy.php index 9e1ca4170..52dc6dc08 100644 --- a/app/Services/FileSystem/AbstractFileDownloadStrategy.php +++ b/app/Services/FileSystem/AbstractFileDownloadStrategy.php @@ -85,7 +85,7 @@ public function getUrl(string $relativeFileName, bool $useTemporaryUrl = false, $key = sprintf("%s/%s_%b_%s", $this->getDriver(), $relativeFileName, $useTemporaryUrl, $ttl); $res = Cache::get($key); - if(!empty($res) && $res != '#' && !$avoidCache) { + if(!empty($res) && !$avoidCache) { Log::debug ( sprintf @@ -100,12 +100,12 @@ public function getUrl(string $relativeFileName, bool $useTemporaryUrl = false, // @see https://laravel.com/docs/8.x/filesystem#temporary-urls $res = $useTemporaryUrl ? Storage::disk($this->getDriver())->temporaryUrl($relativeFileName, now()->addMinutes($ttl)) : Storage::disk($this->getDriver())->url($relativeFileName); - if(!empty($res) && $res != '#') { + if(!empty($res)) { $ttl = $useTemporaryUrl ? ($ttl - 1) : intval(Config::get('cache_api_response.file_url_lifetime', 3600)); Log::debug(sprintf("AbstractFileDownloadStrategy::getUrl adding key %s res %s ttl %s to cache", $key, $res, $ttl)); Cache::add($key, $res, $ttl); } - return $res; + return empty($res) ? null : $res; } /** diff --git a/app/Services/FileSystem/Dropbox/DropboxAdapter.php b/app/Services/FileSystem/Dropbox/DropboxAdapter.php index 97087c56b..d2e7b212c 100644 --- a/app/Services/FileSystem/Dropbox/DropboxAdapter.php +++ b/app/Services/FileSystem/Dropbox/DropboxAdapter.php @@ -24,6 +24,10 @@ final class DropboxAdapter extends BaseDropboxAdapter /* * This method returns a public URL for the given path in Dropbox. * this is overloaded to retrieve a URL with the preview mode enabled. + * Returns an empty string when no shared link can be produced (e.g. the file is not in Dropbox); + * the parent declares getUrl(): string, so null is not allowed here by PHP return-type covariance. + * AbstractFileDownloadStrategy::getUrl() normalizes it to null, so serializers expose + * private_url = null and clients fall back to public_url. */ public function getUrl(string $path): string { @@ -65,6 +69,6 @@ public function getUrl(string $path): string catch (Exception $ex){ Log::error($ex); } - return '#'; + return ''; } } diff --git a/app/Services/Model/ISummitService.php b/app/Services/Model/ISummitService.php index c7c9b1684..e11aa3aa3 100644 --- a/app/Services/Model/ISummitService.php +++ b/app/Services/Model/ISummitService.php @@ -552,10 +552,13 @@ public function regenerateTemporalUrlsForMediaUploads(int $summit_id):void; * Process pending media uploads from the PendingMediaUpload table. * 429 rate-limit handling is now transparently handled by RetryAfterDropboxClient. * - * @param int $max_retries Maximum retry attempts per upload across cron runs (default 3) + * Attempts are spaced with exponential backoff (5, 10, 20, 40 ... minutes since the last + * failed attempt); when the budget is exhausted the row is marked Error and logged at error level. + * + * @param int $max_retries Maximum retry attempts per upload across cron runs (default 5) * @return array Stats array: ['processed' => int, 'errors' => int] */ - public function processPendingMediaUploads(int $max_retries = 3): array; + public function processPendingMediaUploads(int $max_retries = 5): array; /** * @param Summit $summit diff --git a/app/Services/Model/Imp/SummitService.php b/app/Services/Model/Imp/SummitService.php index 7b8d94075..8f22a33be 100644 --- a/app/Services/Model/Imp/SummitService.php +++ b/app/Services/Model/Imp/SummitService.php @@ -128,6 +128,11 @@ final class SummitService extends AbstractPublishService implements ISummitService { + /** + * Base wait (minutes) between attempts of a pending media upload; doubles per attempt: 5, 10, 20, 40 ... + */ + const PendingMediaUploadRetryBaseMinutes = 5; + /** * @var ISummitEventRepository */ @@ -4389,7 +4394,7 @@ public function validateBadge(Summit $summit, string $badge_qr_code): SummitAtte * @param int $max_retries * @return array */ - public function processPendingMediaUploads(int $max_retries = 3): array + public function processPendingMediaUploads(int $max_retries = 5): array { Log::debug(sprintf( "SummitService::processPendingMediaUploads max_retries %s", @@ -4422,14 +4427,28 @@ public function processPendingMediaUploads(int $max_retries = 3): array $upload_id = $pending_upload->getId(); Log::debug(sprintf("SummitService::processPendingMediaUploads processing upload ID %s", $upload_id)); + $attempts = $pending_upload->getAttempts(); + // Check retry limit - if ($pending_upload->getAttempts() >= $max_retries) { + if ($attempts >= $max_retries) { $this->tx_service->transaction(function () use ($pending_upload) { $pending_upload->setStatus(PendingMediaUpload::STATUS_ERROR); $pending_upload->setErrorMessage('Max retries exceeded'); }); $stats['errors']++; - Log::warning(sprintf("SummitService::processPendingMediaUploads upload ID %s exceeded max retries", $upload_id)); + // Permanent Error transition: error level so it survives LOG_LEVEL=error in production + Log::error(sprintf("SummitService::processPendingMediaUploads upload ID %s exceeded max retries (%s), marked as Error", $upload_id, $max_retries)); + continue; + } + + // Exponential backoff between attempts (5, 10, 20, 40 ... minutes since the last failed attempt) + if ($attempts > 0 && !self::isPendingMediaUploadRetryDue($pending_upload, $attempts)) { + Log::debug(sprintf( + "SummitService::processPendingMediaUploads upload ID %s skipped, backoff not elapsed (attempts %s, retry %s minutes after the last attempt)", + $upload_id, + $attempts, + self::getPendingMediaUploadRetryDelayMinutes($attempts) + )); continue; } @@ -4529,22 +4548,30 @@ public function processPendingMediaUploads(int $max_retries = 3): array } catch (\Exception $ex) { // On failure, status remains at whatever partial state was reached // Set error message and mark as ERROR only if max retries exhausted - $this->tx_service->transaction(function () use ($pending_upload, $ex, $max_retries) { + $attempts = $pending_upload->getAttempts(); + $exhausted = $attempts >= $max_retries; + $this->tx_service->transaction(function () use ($pending_upload, $ex, $exhausted) { $pending_upload->setErrorMessage($ex->getMessage()); - if ($pending_upload->getAttempts() >= $max_retries) { + if ($exhausted) { $pending_upload->setStatus(PendingMediaUpload::STATUS_ERROR); } // else: leave at current status (Pending, PublicStorageUploaded, or PrivateStorageUploaded) for retry }); $stats['errors']++; - Log::warning(sprintf( + $message = sprintf( "SummitService::processPendingMediaUploads upload ID %s failed (attempt %s/%s): %s", $upload_id, - $pending_upload->getAttempts(), + $attempts, $max_retries, $ex->getMessage() - )); + ); + // Permanent Error transition: error level so it survives LOG_LEVEL=error in production + if ($exhausted) { + Log::error($message . ' - max retries exhausted, marked as Error'); + } else { + Log::warning($message); + } } } @@ -4573,4 +4600,33 @@ public function processPendingMediaUploads(int $max_retries = 3): array return $stats; } + + /** + * Exponential backoff between attempts of a pending media upload: a row that already failed + * $attempts times is due again PendingMediaUploadRetryBaseMinutes * 2^(attempts - 1) minutes + * after its LastEdited (the time of the last failed attempt): 5, 10, 20, 40 ... + * @param PendingMediaUpload $pending_upload + * @param int $attempts + * @return bool + */ + private static function isPendingMediaUploadRetryDue(PendingMediaUpload $pending_upload, int $attempts): bool + { + // LastEdited is stored as DefaultTimeZone wall-clock and hydrated by Doctrine in the app + // timezone (UTC), so the raw getLastEdited() is off by the zone offset; getLastEditedUTC() + // re-interprets it correctly. Compare instants in UTC. + $last_edited = $pending_upload->getLastEditedUTC(); + if (is_null($last_edited)) return true; + $next_retry_at = (clone $last_edited)->modify(sprintf('+%d minutes', self::getPendingMediaUploadRetryDelayMinutes($attempts))); + $now = new \DateTime('now', new \DateTimeZone('UTC')); + return $next_retry_at <= $now; + } + + /** + * @param int $attempts failed attempts so far (>= 1) + * @return int minutes to wait after the last attempt: 5, 10, 20, 40 ... + */ + private static function getPendingMediaUploadRetryDelayMinutes(int $attempts): int + { + return self::PendingMediaUploadRetryBaseMinutes * (2 ** max($attempts - 1, 0)); + } } diff --git a/tests/Unit/Services/DropboxAdapterGetUrlTest.php b/tests/Unit/Services/DropboxAdapterGetUrlTest.php new file mode 100644 index 000000000..6e73c6a0c --- /dev/null +++ b/tests/Unit/Services/DropboxAdapterGetUrlTest.php @@ -0,0 +1,100 @@ +singleton('log', fn() => new NullLogger()); + Container::setInstance($app); + Facade::setFacadeApplication($app); + } + + protected function tearDown(): void + { + Facade::setFacadeApplication(null); + Facade::clearResolvedInstances(); + Container::setInstance(null); + Mockery::close(); + parent::tearDown(); + } + + /** + * The file never reached Dropbox (e.g. the pending upload failed), so + * sharing/create_shared_link_with_settings answers path/not_found. + * The adapter must report "no link" as an empty string (the parent declares getUrl(): string, + * so null is not allowed), never as a placeholder like "#" + * that clients would treat as a real URL. AbstractFileDownloadStrategy turns it into null. + */ + public function testGetUrlReturnsEmptyStringWhenSharedLinkCannotBeCreated(): void + { + $path = 'PresentationMediaUploads/Private/73/9121/missing.pptx'; + + $client = Mockery::mock(DropboxClient::class); + $client->shouldReceive('createSharedLinkWithSettings') + ->once() + ->with($path) + ->andThrow(new BadRequest(new Response(409, [], json_encode([ + 'error_summary' => 'path/not_found/', + 'error' => ['.tag' => 'path', 'path' => ['.tag' => 'not_found']], + ])))); + $client->shouldNotReceive('listSharedLinks'); + + $adapter = new DropboxAdapter($client); + + $this->assertSame('', $adapter->getUrl($path)); + } + + /** + * Anti-regression: when Dropbox creates the shared link, its URL is returned as-is. + */ + public function testGetUrlReturnsSharedLinkUrlOnSuccess(): void + { + $path = 'PresentationMediaUploads/Private/73/9082/deck.pptx'; + $url = 'https://www.dropbox.com/scl/fi/abc123/deck.pptx?dl=0'; + + $client = Mockery::mock(DropboxClient::class); + $client->shouldReceive('createSharedLinkWithSettings') + ->once() + ->with($path) + ->andReturn(['url' => $url]); + + $adapter = new DropboxAdapter($client); + + $this->assertSame($url, $adapter->getUrl($path)); + } +} diff --git a/tests/Unit/Services/FileDownloadStrategyGetUrlTest.php b/tests/Unit/Services/FileDownloadStrategyGetUrlTest.php new file mode 100644 index 000000000..e474b6ab6 --- /dev/null +++ b/tests/Unit/Services/FileDownloadStrategyGetUrlTest.php @@ -0,0 +1,106 @@ + NullLogger, Cache / Storage / Config -> mocks. + Facade::clearResolvedInstances(); + $app = new Container(); + $app->singleton('log', fn() => new NullLogger()); + $this->cache = Mockery::mock(); + $this->filesystem = Mockery::mock(); + $this->config = Mockery::mock(); + $app->instance('cache', $this->cache); + $app->instance('filesystem', $this->filesystem); + $app->instance('config', $this->config); + Container::setInstance($app); + Facade::setFacadeApplication($app); + } + + protected function tearDown(): void + { + Facade::setFacadeApplication(null); + Facade::clearResolvedInstances(); + Container::setInstance(null); + Mockery::close(); + parent::tearDown(); + } + + /** + * The Dropbox adapter reports "no link" as an empty string (its parent forbids null). + * The strategy must hand serializers null, and must not cache the miss. + */ + public function testGetUrlReturnsNullAndDoesNotCacheWhenDiskHasNoUrl(): void + { + $path = 'PresentationMediaUploads/Private/73/9121/missing.pptx'; + + $disk = Mockery::mock(); + $disk->shouldReceive('url')->once()->with($path)->andReturn(''); + $this->filesystem->shouldReceive('disk')->with('dropbox')->andReturn($disk); + $this->cache->shouldReceive('get')->once()->andReturn(null); + $this->cache->shouldNotReceive('add'); + + $strategy = new DropboxStorageFileDownloadStrategy(); + + $this->assertNull($strategy->getUrl($path)); + } + + /** + * Anti-regression: a real URL is returned and cached for the configured lifetime. + */ + public function testGetUrlReturnsAndCachesDiskUrl(): void + { + $path = 'PresentationMediaUploads/Private/73/9082/deck.pptx'; + $url = 'https://www.dropbox.com/scl/fi/abc123/deck.pptx?dl=0'; + + $disk = Mockery::mock(); + $disk->shouldReceive('url')->once()->with($path)->andReturn($url); + $this->filesystem->shouldReceive('disk')->with('dropbox')->andReturn($disk); + $this->cache->shouldReceive('get')->once()->andReturn(null); + $this->config->shouldReceive('get')->with('cache_api_response.file_url_lifetime', 3600)->andReturn(3600); + $this->cache->shouldReceive('add')->once()->with(Mockery::type('string'), $url, 3600); + + $strategy = new DropboxStorageFileDownloadStrategy(); + + $this->assertSame($url, $strategy->getUrl($path)); + } +} diff --git a/tests/Unit/Services/ProcessPendingMediaUploadsTest.php b/tests/Unit/Services/ProcessPendingMediaUploadsTest.php index 436bf97e2..62e62e998 100644 --- a/tests/Unit/Services/ProcessPendingMediaUploadsTest.php +++ b/tests/Unit/Services/ProcessPendingMediaUploadsTest.php @@ -23,7 +23,7 @@ use models\summit\Summit; use models\summit\SummitMediaUploadType; use PHPUnit\Framework\TestCase; -use Psr\Log\NullLogger; +use Psr\Log\AbstractLogger; /** * Class ProcessPendingMediaUploadsTest @@ -36,8 +36,38 @@ * * @package Tests\Unit\Services */ +/** + * PSR-3 logger that records (level, message) pairs so tests can assert on the level + * a transition was logged at (e.g. Error transitions must be visible at LOG_LEVEL=error). + */ +final class RecordingLogger extends AbstractLogger +{ + /** @var array */ + public array $records = []; + + public function log($level, string|\Stringable $message, array $context = []): void + { + $this->records[] = ['level' => (string) $level, 'message' => (string) $message]; + } + + /** + * @param string $level + * @param string $pattern regex + * @return bool + */ + public function has(string $level, string $pattern): bool + { + foreach ($this->records as $record) { + if ($record['level'] === $level && preg_match($pattern, $record['message'])) return true; + } + return false; + } +} + class ProcessPendingMediaUploadsTest extends TestCase { + /** @var RecordingLogger */ + private $logger; protected function setUp(): void { parent::setUp(); @@ -47,7 +77,8 @@ protected function setUp(): void // prior test that booted a full Laravel app (e.g., AbstractOAuth2ApiScopesTest). Facade::clearResolvedInstances(); $app = new Container(); - $app->singleton('log', fn() => new NullLogger()); + $this->logger = new RecordingLogger(); + $app->singleton('log', fn() => $this->logger); Container::setInstance($app); Facade::setFacadeApplication($app); } @@ -100,6 +131,19 @@ private function createServiceWithDeps( return $service; } + /** + * What PendingMediaUpload::getLastEditedUTC() returns for a row last edited $minutes ago. + * The service must use the UTC accessor: the raw getLastEdited() is hydrated in the app + * timezone from a DefaultTimeZone wall-clock value and is off by the zone offset. + * @param int $minutes + * @return \DateTime + */ + private function minutesAgo(int $minutes): \DateTime + { + $dt = new \DateTime('now', new \DateTimeZone('UTC')); + return $dt->modify(sprintf('-%d minutes', $minutes)); + } + /** * Test max retries exceeded marks upload as Error. * When attempts >= max_retries, the upload should be permanently marked as Error. @@ -129,6 +173,8 @@ public function testMaxRetriesExceededMarksUploadAsError(): void $this->assertEquals(0, $stats['processed']); $this->assertEquals(1, $stats['errors']); + // The permanent Error transition must be visible in production logs (LOG_LEVEL=error) + $this->assertTrue($this->logger->has('error', '/upload ID 1 exceeded max retries/'), 'Error transition not logged at error level'); } /** @@ -321,6 +367,8 @@ public function testPartialStatusPreservedOnFailure(): void // First call: retry guard (1 < 3, passes) // Second call: in catch block (2 < 3, leave at partial status) $pendingUpload->shouldReceive('getAttempts')->andReturnValues([1, 2]); + // Backoff for attempt 1 is 5 minutes; last attempt long ago -> due for retry + $pendingUpload->shouldReceive('getLastEditedUTC')->andReturn($this->minutesAgo(60)); // Verify setErrorMessage is called but setStatus is NOT called in catch block // (status stays at whatever partial state was reached) @@ -342,4 +390,84 @@ public function testPartialStatusPreservedOnFailure(): void $this->assertEquals(0, $stats['processed']); $this->assertEquals(1, $stats['errors']); } + + /** + * A row that already failed must wait before being retried: 5 * 2^(attempts-1) minutes + * since LastEdited (5, 10, 20, 40 ...). With 2 attempts and a failure 6 minutes ago the + * row is due at 10 minutes, so this run must leave it untouched (no status change, + * no attempt increment, not counted as processed or error). + */ + public function testProcessPendingMediaUploadsSkipsRowWhileBackoffNotElapsed(): void + { + $pendingRepo = Mockery::mock(IPendingMediaUploadRepository::class); + $txService = Mockery::mock(ITransactionService::class); + + $pendingUpload = Mockery::mock(PendingMediaUpload::class); + $pendingUpload->shouldReceive('getId')->andReturn(1); + $pendingUpload->shouldReceive('getAttempts')->andReturn(2); + $pendingUpload->shouldReceive('getLastEditedUTC')->andReturn($this->minutesAgo(6)); + $pendingUpload->shouldNotReceive('setStatus'); + $pendingUpload->shouldNotReceive('incrementAttempts'); + $pendingUpload->shouldNotReceive('setErrorMessage'); + + $pendingRepo->shouldReceive('resetStuckProcessingRows')->once()->with(10)->andReturn(0); + $pendingRepo->shouldReceive('getPendingUploads')->once()->andReturn([$pendingUpload]); + $pendingRepo->shouldReceive('deleteCompletedOlderThan')->once()->with(7, 1000)->andReturn(0); + + // Only reset stuck + cleanup transactions: the row is skipped without touching it + $txService->shouldReceive('transaction')->twice()->andReturnUsing(function ($callback) { + return $callback(); + }); + + $service = $this->createServiceWithDeps($pendingRepo, $txService); + + $stats = $service->processPendingMediaUploads(); + + $this->assertEquals(0, $stats['processed']); + $this->assertEquals(0, $stats['errors']); + } + + /** + * Default retry budget is 5 attempts. A row with 4 failed attempts whose backoff + * (40 minutes) has elapsed is attempted again; when that 5th attempt fails the row + * transitions to Error and the transition is logged at error level. + */ + public function testProcessPendingMediaUploadsMarksErrorAndLogsErrorOnFinalFailedAttempt(): void + { + $pendingRepo = Mockery::mock(IPendingMediaUploadRepository::class); + $txService = Mockery::mock(ITransactionService::class); + $summitRepository = Mockery::mock(ISummitRepository::class); + + $pendingUpload = Mockery::mock(PendingMediaUpload::class); + $pendingUpload->shouldReceive('getId')->andReturn(1); + // First getAttempts() call: retry guard + backoff (4 < 5, 45 min > 40 min backoff) + // Second getAttempts() call: in catch block after incrementAttempts (5 >= 5 -> Error) + $pendingUpload->shouldReceive('getAttempts')->andReturnValues([4, 5]); + $pendingUpload->shouldReceive('getLastEditedUTC')->andReturn($this->minutesAgo(45)); + $pendingUpload->shouldReceive('setStatus')->with(PendingMediaUpload::STATUS_PROCESSING)->once(); + $pendingUpload->shouldReceive('incrementAttempts')->once(); + $pendingUpload->shouldReceive('getSummitId')->andReturn(999); + // Summit not found -> EntityNotFoundException -> caught, attempts exhausted + $summitRepository->shouldReceive('getById')->with(999)->andReturn(null); + $pendingUpload->shouldReceive('setErrorMessage')->once()->with(Mockery::pattern('/Summit 999 not found/')); + $pendingUpload->shouldReceive('setStatus')->with(PendingMediaUpload::STATUS_ERROR)->once(); + + $pendingRepo->shouldReceive('resetStuckProcessingRows')->once()->with(10)->andReturn(0); + $pendingRepo->shouldReceive('getPendingUploads')->once()->andReturn([$pendingUpload]); + $pendingRepo->shouldReceive('deleteCompletedOlderThan')->once()->with(7, 1000)->andReturn(0); + + // 4 transactions: reset stuck, mark processing, catch (error message + Error status), cleanup + $txService->shouldReceive('transaction')->times(4)->andReturnUsing(function ($callback) { + return $callback(); + }); + + $service = $this->createServiceWithDeps($pendingRepo, $txService, $summitRepository); + + // default max_retries + $stats = $service->processPendingMediaUploads(); + + $this->assertEquals(0, $stats['processed']); + $this->assertEquals(1, $stats['errors']); + $this->assertTrue($this->logger->has('error', '/upload ID 1 failed \(attempt 5\/5\)/'), 'Final failed attempt not logged at error level'); + } }