From 9e179430f79f71e565e285894c1016616a357c2d Mon Sep 17 00:00:00 2001 From: arabcoders Date: Sat, 20 Jun 2026 18:13:07 +0300 Subject: [PATCH 1/9] refactor: update log messages --- FAQ.md | 2 +- src/API/Backends/PlexToken.php | 8 +- src/API/Backends/Users.php | 9 ++- src/API/History/Index.php | 45 ++++++++++- src/API/Identities/Index.php | 12 +-- src/API/Player/Playlist.php | 8 +- src/API/Player/Segments.php | 12 ++- src/API/Player/Subtitle.php | 8 +- src/Backends/Emby/Action/AddWebhook.php | 6 +- src/Backends/Emby/Action/Progress.php | 63 ++++++++++----- src/Backends/Jellyfin/Action/AddWebhook.php | 10 +-- .../Jellyfin/Action/CreatePlaylist.php | 2 +- .../Jellyfin/Action/DeletePlaylist.php | 2 +- src/Backends/Jellyfin/Action/Export.php | 2 +- .../Jellyfin/Action/GenerateAccessToken.php | 2 +- src/Backends/Jellyfin/Action/GetInfo.php | 4 +- .../Jellyfin/Action/GetLibrariesList.php | 2 +- src/Backends/Jellyfin/Action/GetLibrary.php | 4 +- src/Backends/Jellyfin/Action/GetMetaData.php | 2 +- src/Backends/Jellyfin/Action/GetPlaylist.php | 4 +- .../Jellyfin/Action/GetPlaylistsList.php | 2 +- src/Backends/Jellyfin/Action/GetSessions.php | 4 +- src/Backends/Jellyfin/Action/GetUser.php | 2 +- src/Backends/Jellyfin/Action/GetUsersList.php | 2 +- src/Backends/Jellyfin/Action/Import.php | 20 ++--- src/Backends/Jellyfin/Action/Progress.php | 67 +++++++++++----- src/Backends/Jellyfin/Action/Push.php | 38 ++++++--- src/Backends/Jellyfin/Action/SearchQuery.php | 2 +- src/Backends/Jellyfin/JellyfinGuid.php | 44 +++++++--- src/Backends/Plex/Action/AddWebhook.php | 6 +- src/Backends/Plex/Action/CreatePlaylist.php | 2 +- src/Backends/Plex/Action/DeletePlaylist.php | 2 +- src/Backends/Plex/Action/Export.php | 2 +- src/Backends/Plex/Action/GetInfo.php | 4 +- src/Backends/Plex/Action/GetLibrariesList.php | 2 +- src/Backends/Plex/Action/GetLibrary.php | 6 +- src/Backends/Plex/Action/GetMetaData.php | 2 +- src/Backends/Plex/Action/GetPlaylist.php | 4 +- src/Backends/Plex/Action/GetPlaylistsList.php | 2 +- src/Backends/Plex/Action/GetSessions.php | 4 +- src/Backends/Plex/Action/GetUserToken.php | 2 +- src/Backends/Plex/Action/GetUsersList.php | 2 +- src/Backends/Plex/Action/Import.php | 22 ++--- src/Backends/Plex/Action/Progress.php | 67 +++++++++++----- src/Backends/Plex/Action/Push.php | 44 ++++++---- src/Backends/Plex/Action/SearchQuery.php | 2 +- src/Backends/Plex/PlexClient.php | 2 +- src/Backends/Plex/PlexGuid.php | 77 +++++++++++++----- src/Commands/Backend/RestoreCommand.php | 24 +++++- src/Commands/Database/IndexCommand.php | 8 +- src/Commands/State/BackupCommand.php | 16 +++- src/Commands/State/ExportCommand.php | 20 ++++- src/Commands/State/ImportCommand.php | 19 ++++- src/Commands/State/PlaylistCommand.php | 12 ++- src/Commands/State/ValidateCommand.php | 8 +- src/Commands/System/PruneCommand.php | 5 ++ src/Commands/System/TasksCommand.php | 5 ++ src/Libs/Database/PDO/PDOAdapter.php | 12 ++- src/Libs/Guid.php | 35 +++++++- .../Identities/IdentityProvisionService.php | 71 +++++++++++++--- src/Libs/Initializer.php | 4 +- src/Libs/Mappers/Import/DirectMapper.php | 30 +++++-- src/Libs/Mappers/Import/MemoryMapper.php | 19 ++++- src/Libs/Playlists/PlaylistSyncService.php | 16 +++- src/Libs/TestCase.php | 80 +++++++++++++++++++ src/Libs/Utils.php | 10 ++- src/Libs/helpers.php | 4 + src/Listeners/ProcessProgressEvent.php | 6 +- src/Listeners/ProcessPushEvent.php | 6 +- tests/Backends/Emby/EmbyGuidTest.php | 43 +++------- tests/Backends/Jellyfin/JellyfinGuidTest.php | 43 +++------- tests/Backends/Plex/GetLibrariesListTest.php | 2 +- tests/Backends/Plex/PlexGuidTest.php | 67 +++++----------- tests/Commands/State/ExportCommandTest.php | 10 ++- tests/Commands/State/PlaylistCommandTest.php | 10 ++- tests/Commands/State/ValidateCommandTest.php | 10 ++- tests/Libs/GuidTest.php | 57 ++++--------- 77 files changed, 878 insertions(+), 416 deletions(-) diff --git a/FAQ.md b/FAQ.md index 1764f310..fed44c14 100644 --- a/FAQ.md +++ b/FAQ.md @@ -454,7 +454,7 @@ the issue. Please enable webhooks for your jellyfin backend to avoid this issue. We have added an experimental workaround for this issue in the `state:import` command. To enable it, add the env `WS_CLIENTS_JELLYFIN_FIX_PLAYED` via the `Configuration > Environment` page. It's turned off by default as it may cause some issues as it's untested in production, so please use it with caution and report any issues you find. -## CODE: DM001 - Item queued for re-processing. +## DM001 (`error: dm001_stale_date`) - Item queued for re-processing. This warning appears when the backend reports an older item state than the last recorded sync point. This usually shows up in edge cases and can often be resolved by forcing a state export to the backend. diff --git a/src/API/Backends/PlexToken.php b/src/API/Backends/PlexToken.php index 08027646..0f144f83 100644 --- a/src/API/Backends/PlexToken.php +++ b/src/API/Backends/PlexToken.php @@ -49,7 +49,7 @@ public function generate(iHttp $http): iResponse ]); if (Status::CREATED !== Status::from($req->getStatusCode())) { - $this->logger->error("Request for OAuth PIN returned with unexpected '{response.status_code}' status code.", [ + $this->logger->error('Request for OAuth PIN returned HTTP {response.status_code}.', [ 'response' => [ 'status_code' => $req->getStatusCode(), 'parsed' => $req->toArray(false), @@ -58,7 +58,7 @@ public function generate(iHttp $http): iResponse ]); return api_error( r( - text: "Request for OAuth PIN returned with unexpected '{response.status_code}' status code.", + text: 'Request for OAuth PIN returned HTTP {response.status_code}.', context: ['response' => ['status_code' => $req->getStatusCode()]], ), Status::from($req->getStatusCode()), @@ -98,7 +98,7 @@ public function check(iRequest $request, iHttp $http): iResponse ]); if (Status::OK !== Status::from($req->getStatusCode())) { - $this->logger->error("Request for OAuth PIN check returned with unexpected '{response.status_code}' status code.", [ + $this->logger->error('Request for OAuth PIN check returned HTTP {response.status_code}.', [ 'response' => [ 'status_code' => $req->getStatusCode(), 'parsed' => $req->toArray(false), @@ -108,7 +108,7 @@ public function check(iRequest $request, iHttp $http): iResponse return api_error( r( - text: "Request for OAuth PIN check returned with unexpected '{response.status_code}' status code.", + text: 'Request for OAuth PIN check returned HTTP {response.status_code}.', context: ['response' => ['status_code' => $req->getStatusCode()]], ), Status::from($req->getStatusCode()), diff --git a/src/API/Backends/Users.php b/src/API/Backends/Users.php index e51d3afb..664b1f0f 100644 --- a/src/API/Backends/Users.php +++ b/src/API/Backends/Users.php @@ -49,7 +49,14 @@ public function __invoke(iRequest $request, string $type, iLogger $logger): iRes $users[] = $user; } } catch (Throwable $e) { - $logger->error($e->getMessage(), exception_log($e)); + $logger->error( + "Failed to load users list from '{type}' backend. {exception.message}", + [ + 'operation' => 'backends.users_list', + 'backend' => ['type' => $type], + ...exception_log($e), + ], + ); return api_error($e->getMessage(), Status::INTERNAL_SERVER_ERROR); } diff --git a/src/API/History/Index.php b/src/API/History/Index.php index cd304e1e..b2ebd76b 100644 --- a/src/API/History/Index.php +++ b/src/API/History/Index.php @@ -550,7 +550,20 @@ public function list(iRequest $request): iResponse [], ); } catch (Throwable $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + "Failed to load duplicates for '#{item.id}: {item.title}'. {exception.message}", + [ + 'operation' => 'history.duplicates', + 'identity' => [ + 'user' => $userContext->name, + ], + 'item' => [ + 'id' => $entity['id'] ?? null, + 'title' => ag($entity, 'title', '??'), + ], + ...exception_log($e), + ], + ); } } @@ -673,7 +686,20 @@ public function read(iRequest $request, string $id): iResponse [], ); } catch (Throwable $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + "Failed to load duplicates for '#{item.id}: {item.title}'. {exception.message}", + [ + 'operation' => 'history.duplicates', + 'identity' => [ + 'user' => $userContext->name, + ], + 'item' => [ + 'id' => $item->id, + 'title' => $item->getName(), + ], + ...exception_log($e), + ], + ); } } @@ -711,7 +737,20 @@ public function duplicates(iRequest $request, string $id): iResponse [], ); } catch (Throwable $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + "Failed to load duplicates for '#{item.id}: {item.title}'. {exception.message}", + [ + 'operation' => 'history.duplicates', + 'identity' => [ + 'user' => $userContext->name, + ], + 'item' => [ + 'id' => $item->id, + 'title' => $item->getName(), + ], + ...exception_log($e), + ], + ); return api_error('Failed to get duplicates', Status::INTERNAL_SERVER_ERROR); } diff --git a/src/API/Identities/Index.php b/src/API/Identities/Index.php index 6c1f1d64..d6a690b5 100644 --- a/src/API/Identities/Index.php +++ b/src/API/Identities/Index.php @@ -75,10 +75,10 @@ public function identity_add(iRequest $request): iResponse per_user_config($identityName); ensure_migration(get_user_db($identityName)); } catch (Throwable $e) { - $this->logger->error(r('Failed to create identity {identity}: {exception.message}', [ - 'identity' => $identityName, + $this->logger->error("Failed to create identity '{identity.name}'. {exception.message}", [ + 'identity' => ['name' => $identityName], ...exception_log($e), - ])); + ]); return api_error( r('Failed to create identity {identity}', ['identity' => $identityName]), @@ -113,10 +113,10 @@ public function identity_delete(string $identity, iCache $cache): iResponse try { delete_user_config($identity, $cache); } catch (Throwable $e) { - $this->logger->error(r('Failed to delete identity {identity}: {exception.message}', [ - 'identity' => $identity, + $this->logger->error("Failed to delete identity '{identity.name}'. {exception.message}", [ + 'identity' => ['name' => $identity], ...exception_log($e), - ])); + ]); return api_error( r('Failed to delete identity {identity}', ['identity' => $identity]), diff --git a/src/API/Player/Playlist.php b/src/API/Player/Playlist.php index b588bcf9..f605f7a5 100644 --- a/src/API/Player/Playlist.php +++ b/src/API/Player/Playlist.php @@ -213,7 +213,13 @@ public function __invoke(iRequest $request, #[SensitiveParameter] string $token) 'Access-Control-Max-Age' => 300, ]); } catch (Throwable $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to generate playlist. {exception.message}', + [ + 'operation' => 'player.playlist', + ...exception_log($e), + ], + ); return api_error($e->getMessage(), Status::INTERNAL_SERVER_ERROR); } } diff --git a/src/API/Player/Segments.php b/src/API/Player/Segments.php index 0eb3d6d5..ff08a582 100644 --- a/src/API/Player/Segments.php +++ b/src/API/Player/Segments.php @@ -323,8 +323,9 @@ public function __invoke(iRequest $request, #[\SensitiveParameter] string $token if (!$process->isSuccessful()) { $this->logger->error( - r("Failed to generate segment. '{error}'", ['error' => $process->getErrorOutput()]), + 'Failed to generate segment.', [ + 'operation' => 'generate_segment', 'stdout' => $process->getOutput(), 'stderr' => $process->getErrorOutput(), 'Ffmpeg' => $process->getCommandLine(), @@ -380,6 +381,7 @@ public function __invoke(iRequest $request, #[\SensitiveParameter] string $token return $response; } catch (Throwable $e) { $this->logger->error('Failed to generate segment. {exception.message}', [ + 'operation' => 'generate_segment', 'stdout' => isset($process) ? $process->getOutput() : null, 'stderr' => isset($process) ? $process->getErrorOutput() : null, 'Ffmpeg' => $this->cmdLog($cmd), @@ -449,6 +451,10 @@ private function extractTextSubTitle(string $path, string $type, int $stream, st if (!$process->isSuccessful()) { $this->logger->error('Failed to extract subtitle.', [ + 'operation' => 'extract_subtitle', + 'source' => $path, + 'stream' => $stream, + 'type' => $type, 'stdout' => $process->getOutput(), 'stderr' => $process->getErrorOutput(), 'Ffmpeg' => $this->cmdLog($cmd), @@ -465,6 +471,10 @@ private function extractTextSubTitle(string $path, string $type, int $stream, st return $cacheFile; } catch (Throwable $e) { $this->logger->error('Failed to extract subtitles. {exception.message}', [ + 'operation' => 'extract_subtitle', + 'source' => $path, + 'stream' => $stream, + 'type' => $type, 'stdout' => isset($process) ? $process->getOutput() : null, 'stderr' => isset($process) ? $process->getErrorOutput() : null, 'Ffmpeg' => $this->cmdLog($cmd), diff --git a/src/API/Player/Subtitle.php b/src/API/Player/Subtitle.php index 0808eadb..d1aaca43 100644 --- a/src/API/Player/Subtitle.php +++ b/src/API/Player/Subtitle.php @@ -177,7 +177,13 @@ public function convert( 'X-Cache' => $response->getHeaderLine('X-Cache'), ]); } catch (Throwable $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to convert subtitle. {exception.message}', + [ + 'operation' => 'player.subtitle_convert', + ...exception_log($e), + ], + ); return api_error($e->getMessage(), Status::INTERNAL_SERVER_ERROR); } } diff --git a/src/Backends/Emby/Action/AddWebhook.php b/src/Backends/Emby/Action/AddWebhook.php index 45d9cfd5..03dfbd59 100644 --- a/src/Backends/Emby/Action/AddWebhook.php +++ b/src/Backends/Emby/Action/AddWebhook.php @@ -94,7 +94,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get webhooks returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' get webhooks returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ @@ -113,7 +113,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get webhooks returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' get webhooks returned an empty response.", context: [...$logContext, 'response' => ['body' => $content]], level: Levels::ERROR, ), @@ -197,7 +197,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' to {mode} webhook returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' to {mode} webhook returned HTTP {response.status_code}.", context: [ ...$logContext, 'mode' => $mode, diff --git a/src/Backends/Emby/Action/Progress.php b/src/Backends/Emby/Action/Progress.php index 58988ea1..74134c3f 100644 --- a/src/Backends/Emby/Action/Progress.php +++ b/src/Backends/Emby/Action/Progress.php @@ -128,7 +128,11 @@ private function action( if ($context->backendName === $entity->via && false === $replayProgress) { $this->logger->info( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event originated from this backend.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'event_from_this_backend', + ], ); continue; } @@ -136,7 +140,11 @@ private function action( if (null === ag($metadata, iState::COLUMN_ID, null)) { $this->logger->warning( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. No metadata was found.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'no_metadata', + ], ); continue; } @@ -145,7 +153,11 @@ private function action( if (null === $senderDate) { $this->logger->warning( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The event originator did not set a date.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'no_event_date', + ], ); continue; } @@ -155,12 +167,16 @@ private function action( $datetime = ag($entity->getExtra($context->backendName), iState::COLUMN_EXTRA_DATE, null); if (false === $ignoreDate && null !== $datetime && make_date($datetime)->getTimestamp() > $senderDate) { $this->logger->warning( - message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{event_date}' is older than backend local db item date '{local_date}'.", + message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{comparison.event_date}' is older than local database date '{comparison.local_date}'.", context: [ ...$logContext, - 'event_date' => make_date($senderDate), - 'local_date' => make_date($datetime), - 'compare' => ['remote' => make_date($datetime), 'sender' => make_date($senderDate)], + 'operation' => 'progress.skip', + 'error' => 'stale_event_date', + 'comparison' => [ + 'event_date' => make_date($senderDate), + 'local_date' => make_date($datetime), + 'delta_seconds' => make_date($datetime)->getTimestamp() - $senderDate, + ], ], ); continue; @@ -171,7 +187,11 @@ private function action( if (array_key_exists($logContext['remote']['id'], $sessions)) { $this->logger->notice( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The item is playing right now.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'currently_playing', + ], ); continue; } @@ -188,14 +208,15 @@ private function action( if (false === $ignoreDate && make_date($remoteItem->updated)->getTimestamp() > $senderDate) { $this->logger->info( - message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{event_date}' is older than backend remote item date '{remote_date}'.", + message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{comparison.event_date}' is older than backend date '{comparison.remote_date}'.", context: [ ...$logContext, - 'event_date' => make_date($senderDate), - 'remote_date' => make_date($remoteItem->updated), - 'compare' => [ - 'remote' => make_date($remoteItem->updated), - 'sender' => make_date($senderDate), + 'operation' => 'progress.skip', + 'error' => 'stale_event_date', + 'comparison' => [ + 'event_date' => make_date($senderDate), + 'remote_date' => make_date($remoteItem->updated), + 'delta_seconds' => make_date($remoteItem->updated)->getTimestamp() - $senderDate, ], ], ); @@ -211,7 +232,11 @@ private function action( if (false === ($allowUpdate >= $minThreshold && time() > ($entity->updated + $allowUpdate))) { $this->logger->info( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The backend says the item is marked as watched.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'backend_marked_watched', + ], ); continue; } @@ -220,7 +245,7 @@ private function action( } catch (\App\Libs\Exceptions\RuntimeException|RuntimeException|InvalidArgumentException $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' get {history.type} '#{history.id}: {history.title}' status. {exception.message}", + message: "Failed to get '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' status. {exception.message}", context: [ ...$logContext, ...exception_log($e), @@ -280,7 +305,7 @@ private function action( if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $this->logger->error( - message: "Request to change '{identity.user}@{identity.backend}' {history.type} '{history.title}' watch progress returned with unexpected '{response.status_code}' status code.", + message: "Request to change '{identity.user}@{identity.backend}' {history.type} '{history.title}' watch progress returned HTTP {response.status_code}.", context: [ ...$requestContext, 'response' => ['status_code' => $statusCode], @@ -340,7 +365,7 @@ private function action( $statusCode = $response->getStatusCode(); if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $this->logger->error( - message: "Request to mark '{identity.user}@{identity.backend}' {history.type} '{history.title}' as unplayed before progress update returned with unexpected '{response.status_code}' status code.", + message: "Request to mark '{identity.user}@{identity.backend}' {history.type} '{history.title}' as unplayed before progress update returned HTTP {response.status_code}.", context: [ ...$unwatchContext, 'error' => 'unexpected_status', @@ -356,7 +381,7 @@ private function action( error: function (Throwable $e) use ($unwatchContext): array { $this->logger->error( ...lw( - message: "Exception was thrown during '{identity.user}@{identity.backend}' unplayed request before progress update.", + message: "Failed to mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update. {exception.message}", context: [ ...$unwatchContext, 'error' => 'request_exception', diff --git a/src/Backends/Jellyfin/Action/AddWebhook.php b/src/Backends/Jellyfin/Action/AddWebhook.php index 1d6cff79..91abf8a9 100644 --- a/src/Backends/Jellyfin/Action/AddWebhook.php +++ b/src/Backends/Jellyfin/Action/AddWebhook.php @@ -90,7 +90,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' plugins list returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' plugins list returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ @@ -109,7 +109,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' plugins list returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' plugins list returned an empty response.", context: [...$logContext, 'response' => ['body' => $content]], level: Levels::ERROR, ), @@ -162,7 +162,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get webhooks returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' get webhooks returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ @@ -181,7 +181,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get webhooks returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' get webhooks returned an empty response.", context: [...$logContext, 'response' => ['body' => $content]], level: Levels::ERROR, ), @@ -286,7 +286,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' to {mode} webhook returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' to {mode} webhook returned HTTP {response.status_code}.", context: [ ...$logContext, 'mode' => $mode, diff --git a/src/Backends/Jellyfin/Action/CreatePlaylist.php b/src/Backends/Jellyfin/Action/CreatePlaylist.php index 6c4259c4..47a7f569 100644 --- a/src/Backends/Jellyfin/Action/CreatePlaylist.php +++ b/src/Backends/Jellyfin/Action/CreatePlaylist.php @@ -80,7 +80,7 @@ protected function action(Context $context, string $title, array $itemIds): Resp return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{title}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{title}' returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Jellyfin/Action/DeletePlaylist.php b/src/Backends/Jellyfin/Action/DeletePlaylist.php index b1564b9e..1aa7829f 100644 --- a/src/Backends/Jellyfin/Action/DeletePlaylist.php +++ b/src/Backends/Jellyfin/Action/DeletePlaylist.php @@ -72,7 +72,7 @@ protected function action(Context $context, string|int $id): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Jellyfin/Action/Export.php b/src/Backends/Jellyfin/Action/Export.php index c6913d11..e564257a 100644 --- a/src/Backends/Jellyfin/Action/Export.php +++ b/src/Backends/Jellyfin/Action/Export.php @@ -254,7 +254,7 @@ protected function process( if (Status::OK !== Status::tryFrom($statusCode)) { $this->logger->error( - message: "Request to change '{identity.user}@{identity.backend}' {item.type} '{item.title}' play state returned with unexpected '{response.status_code}' status code.", + message: "Request to change '{identity.user}@{identity.backend}' {item.type} '{item.title}' play state returned HTTP {response.status_code}.", context: [ ...$requestContext, 'response' => ['status_code' => $statusCode], diff --git a/src/Backends/Jellyfin/Action/GenerateAccessToken.php b/src/Backends/Jellyfin/Action/GenerateAccessToken.php index a6bb9e3f..44d998d5 100644 --- a/src/Backends/Jellyfin/Action/GenerateAccessToken.php +++ b/src/Backends/Jellyfin/Action/GenerateAccessToken.php @@ -128,7 +128,7 @@ private function generateToken( return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' to generate access for '{username}' token returned with unexpected '{response.status_code}' status code. {response.body}", + message: "Request for '{identity.user}@{identity.backend}' to generate access for '{username}' token returned HTTP {response.status_code}. {response.body}", context: [ ...$logContext, 'response' => [ diff --git a/src/Backends/Jellyfin/Action/GetInfo.php b/src/Backends/Jellyfin/Action/GetInfo.php index 66d17b46..54c4f01d 100644 --- a/src/Backends/Jellyfin/Action/GetInfo.php +++ b/src/Backends/Jellyfin/Action/GetInfo.php @@ -79,7 +79,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "'{identity.user}@{identity.backend}' request returned with unexpected '{response.status_code}' status code.", + message: "'{identity.user}@{identity.backend}' request returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ @@ -100,7 +100,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "'{identity.user}@{identity.backend}' request returned with empty response. Please make sure the container can communicate with the backend.", + message: "'{identity.user}@{identity.backend}' request returned an empty response. Please make sure the container can communicate with the backend.", context: [ ...$logContext, 'response' => [ diff --git a/src/Backends/Jellyfin/Action/GetLibrariesList.php b/src/Backends/Jellyfin/Action/GetLibrariesList.php index 1c9f2570..2768e891 100644 --- a/src/Backends/Jellyfin/Action/GetLibrariesList.php +++ b/src/Backends/Jellyfin/Action/GetLibrariesList.php @@ -208,7 +208,7 @@ private function real_request(Context $context): array if (Status::OK !== Status::tryFrom($response->getStatusCode())) { throw new RuntimeException( r( - text: "Request for '{identity.user}@{identity.backend}' libraries returned with unexpected '{response.status_code}' status code.", + text: "Request for '{identity.user}@{identity.backend}' libraries returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], diff --git a/src/Backends/Jellyfin/Action/GetLibrary.php b/src/Backends/Jellyfin/Action/GetLibrary.php index 79e19487..7cc055c2 100644 --- a/src/Backends/Jellyfin/Action/GetLibrary.php +++ b/src/Backends/Jellyfin/Action/GetLibrary.php @@ -129,7 +129,7 @@ private function action(Context $context, iGuid $guid, string|int $id, array $op return new Response( status: false, error: new Error( - message: "The request for '{identity.user}@{identity.backend}' library '{library.id}: {library.title}' returned with unsupported type '{library.type}'.", + message: "The request for '{identity.user}@{identity.backend}' library '{library.id}: {library.title}' returned unsupported type '{library.type}'.", context: $logContext, level: Levels::WARNING, ), @@ -170,7 +170,7 @@ private function action(Context $context, iGuid $guid, string|int $id, array $op return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' library '{library.title}' items returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' library '{library.title}' items returned HTTP {response.status_code}.", context: [ 'response' => ['status_code' => $response->getStatusCode()], ...$logContext, diff --git a/src/Backends/Jellyfin/Action/GetMetaData.php b/src/Backends/Jellyfin/Action/GetMetaData.php index 7415ceaf..44237c7d 100644 --- a/src/Backends/Jellyfin/Action/GetMetaData.php +++ b/src/Backends/Jellyfin/Action/GetMetaData.php @@ -121,7 +121,7 @@ public function __invoke(Context $context, string|int $id, array $opts = []): Re return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' - '{id}' item returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' - '{id}' item returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], diff --git a/src/Backends/Jellyfin/Action/GetPlaylist.php b/src/Backends/Jellyfin/Action/GetPlaylist.php index 250b3cc9..e65ab414 100644 --- a/src/Backends/Jellyfin/Action/GetPlaylist.php +++ b/src/Backends/Jellyfin/Action/GetPlaylist.php @@ -68,7 +68,7 @@ protected function action(Context $context, string|int $id, array $opts = []): R return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $detailResponse->getStatusCode()]], level: Levels::ERROR, ), @@ -86,7 +86,7 @@ protected function action(Context $context, string|int $id, array $opts = []): R return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' items returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' items returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $itemsResponse->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Jellyfin/Action/GetPlaylistsList.php b/src/Backends/Jellyfin/Action/GetPlaylistsList.php index 9803307c..dd8c669a 100644 --- a/src/Backends/Jellyfin/Action/GetPlaylistsList.php +++ b/src/Backends/Jellyfin/Action/GetPlaylistsList.php @@ -66,7 +66,7 @@ protected function action(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlists returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlists returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Jellyfin/Action/GetSessions.php b/src/Backends/Jellyfin/Action/GetSessions.php index 551b8113..399351c5 100644 --- a/src/Backends/Jellyfin/Action/GetSessions.php +++ b/src/Backends/Jellyfin/Action/GetSessions.php @@ -85,7 +85,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get sessions returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' get sessions returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode(), 'body' => $content], @@ -99,7 +99,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get sessions returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' get sessions returned an empty response.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode(), 'body' => $content], diff --git a/src/Backends/Jellyfin/Action/GetUser.php b/src/Backends/Jellyfin/Action/GetUser.php index 07e30e04..2c7f6bc4 100644 --- a/src/Backends/Jellyfin/Action/GetUser.php +++ b/src/Backends/Jellyfin/Action/GetUser.php @@ -112,7 +112,7 @@ private function getUser(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' user '{userId}' info returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' user '{userId}' info returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ diff --git a/src/Backends/Jellyfin/Action/GetUsersList.php b/src/Backends/Jellyfin/Action/GetUsersList.php index f3c6d60c..19abe7f5 100644 --- a/src/Backends/Jellyfin/Action/GetUsersList.php +++ b/src/Backends/Jellyfin/Action/GetUsersList.php @@ -112,7 +112,7 @@ private function getUsers(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' users list returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' users list returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ diff --git a/src/Backends/Jellyfin/Action/Import.php b/src/Backends/Jellyfin/Action/Import.php index 33889f45..496f7b21 100644 --- a/src/Backends/Jellyfin/Action/Import.php +++ b/src/Backends/Jellyfin/Action/Import.php @@ -184,7 +184,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' libraries returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' libraries returned HTTP {response.status_code}.", context: $rContext, ); @@ -202,7 +202,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro if (empty($listDirs)) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' libraries returned with empty list.", + message: "Request for '{identity.user}@{identity.backend}' libraries returned an empty list.", context: [ ...$rContext, 'response' => ['body' => $payload], @@ -214,7 +214,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (iException $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' libraries has failed. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' libraries failed. {exception.message}", context: [...$rContext, ...exception_log($e)], e: $e, ), @@ -224,7 +224,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (JsonException $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' libraries returned with invalid body. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' libraries returned invalid JSON. {exception.message}", context: [...$rContext, ...exception_log($e)], e: $e, ), @@ -347,7 +347,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro try { if (Status::OK !== Status::tryFrom($response->getStatusCode())) { $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], @@ -362,7 +362,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro if ($totalCount < 1) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned with 0 or less.", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned 0 items.", context: [ ...$logContext, 'response' => [ @@ -378,7 +378,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (iException $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' total items has failed. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' total items failed. {exception.message}", context: [...$logContext, ...exception_log($e)], e: $e, ), @@ -625,7 +625,7 @@ protected function handle(Context $context, iResponse $response, Closure $callba { if (Status::OK !== Status::tryFrom($response->getStatusCode())) { $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title} {segment.number}/{segment.of}' content returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title} {segment.number}/{segment.of}' content returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], @@ -898,9 +898,11 @@ protected function process( if (null === ag($item, $dateKey)) { $this->logger->debug( - message: "Ignoring '{identity.user}@{identity.backend}' - '{item.id}: {item.title}'. No date key '{date_key}' is set on object. '{response.body}'", + message: "Ignoring '{identity.user}@{identity.backend}' - '{item.id}: {item.title}'. No date key '{date_key}' is set on object.", context: [ 'date_key' => $dateKey, + 'operation' => 'import.item_skip', + 'error' => 'no_date_set', 'response' => ['body' => $item], ...$logContext, ], diff --git a/src/Backends/Jellyfin/Action/Progress.php b/src/Backends/Jellyfin/Action/Progress.php index e088764d..7498e079 100644 --- a/src/Backends/Jellyfin/Action/Progress.php +++ b/src/Backends/Jellyfin/Action/Progress.php @@ -155,7 +155,11 @@ private function action( if ($context->backendName === $entity->via && false === $replayProgress) { $this->logger->info( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event originated from this backend.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'event_from_this_backend', + ], ); continue; } @@ -163,7 +167,11 @@ private function action( if (null === ag($metadata, iState::COLUMN_ID, null)) { $this->logger->warning( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. No metadata was found.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'no_metadata', + ], ); continue; } @@ -172,7 +180,11 @@ private function action( if (null === $senderDate) { $this->logger->warning( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The event originator did not set a date.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'no_event_date', + ], ); continue; } @@ -182,12 +194,16 @@ private function action( $datetime = ag($entity->getExtra($context->backendName), iState::COLUMN_EXTRA_DATE, null); if (false === $ignoreDate && null !== $datetime && make_date($datetime)->getTimestamp() > $senderDate) { $this->logger->warning( - message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{event_date}' is older than backend local db item date '{local_date}'.", + message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{comparison.event_date}' is older than local database date '{comparison.local_date}'.", context: [ ...$logContext, - 'event_date' => make_date($senderDate), - 'local_date' => make_date($datetime), - 'compare' => ['remote' => make_date($datetime), 'sender' => make_date($senderDate)], + 'operation' => 'progress.skip', + 'error' => 'stale_event_date', + 'comparison' => [ + 'event_date' => make_date($senderDate), + 'local_date' => make_date($datetime), + 'delta_seconds' => make_date($datetime)->getTimestamp() - $senderDate, + ], ], ); continue; @@ -198,7 +214,11 @@ private function action( if (array_key_exists($logContext['remote']['id'], $sessions)) { $this->logger->notice( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The item is playing right now.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'currently_playing', + ], ); continue; } @@ -211,14 +231,15 @@ private function action( if (false === $ignoreDate && make_date($remoteItem->updated)->getTimestamp() > $senderDate) { $this->logger->info( - message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{event_date}' is older than backend remote item date '{remote_date}'.", + message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{comparison.event_date}' is older than backend date '{comparison.remote_date}'.", context: [ ...$logContext, - 'event_date' => make_date($senderDate), - 'remote_date' => make_date($remoteItem->updated), - 'compare' => [ - 'remote' => make_date($remoteItem->updated), - 'sender' => make_date($senderDate), + 'operation' => 'progress.skip', + 'error' => 'stale_event_date', + 'comparison' => [ + 'event_date' => make_date($senderDate), + 'remote_date' => make_date($remoteItem->updated), + 'delta_seconds' => make_date($remoteItem->updated)->getTimestamp() - $senderDate, ], ], ); @@ -234,7 +255,11 @@ private function action( if (false === ($allowUpdate >= $minThreshold && time() > ($entity->updated + $allowUpdate))) { $this->logger->info( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The backend says the item is marked as watched.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'backend_marked_watched', + ], ); continue; } @@ -243,7 +268,7 @@ private function action( } catch (\App\Libs\Exceptions\RuntimeException|RuntimeException|InvalidArgumentException $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' get {history.type} '#{history.id}: {history.title}' status. {exception.message}", + message: "Failed to get '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' status. {exception.message}", context: [ ...$logContext, ...exception_log($e), @@ -307,7 +332,7 @@ private function action( if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $this->logger->error( - message: "Request to change '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' watch progress returned with unexpected '{response.status_code}' status code.", + message: "Watch progress update for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' returned HTTP {response.status_code}.", context: [ ...$requestContext, 'response' => ['status_code' => $statusCode], @@ -330,7 +355,7 @@ private function action( error: function (Throwable $e) use ($requestContext): array { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' request to change watch progress of {history.type} '#{history.id}: {history.title}'. {exception.message}", + message: "Failed to update watch progress for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. {exception.message}", context: [ ...$requestContext, ...exception_log($e), @@ -367,7 +392,7 @@ private function action( $statusCode = $response->getStatusCode(); if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $this->logger->error( - message: "Request to mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update returned with unexpected '{response.status_code}' status code.", + message: "Mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update returned HTTP {response.status_code}.", context: [ ...$unwatchContext, 'error' => 'unexpected_status', @@ -383,7 +408,7 @@ private function action( error: function (Throwable $e) use ($unwatchContext): array { $this->logger->error( ...lw( - message: "Exception was thrown during '{identity.user}@{identity.backend}' unplayed request before progress update.", + message: "Failed to mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update. {exception.message}", context: [ ...$unwatchContext, 'error' => 'request_exception', @@ -409,7 +434,7 @@ private function action( } catch (Throwable $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' change {history.type} '#{history.id}: {history.title}' watch progress. {exception.message}", + message: "Failed to update watch progress for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. {exception.message}", context: [ ...$logContext, ...exception_log($e), diff --git a/src/Backends/Jellyfin/Action/Push.php b/src/Backends/Jellyfin/Action/Push.php index 26c93ff0..54013d9d 100644 --- a/src/Backends/Jellyfin/Action/Push.php +++ b/src/Backends/Jellyfin/Action/Push.php @@ -114,7 +114,11 @@ private function action( if (null === ag($metadata, iState::COLUMN_ID, null)) { $this->logger->warning( message: "Ignoring '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. No metadata was found.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'push.skip', + 'error' => 'no_metadata', + ], ); continue; } @@ -155,7 +159,7 @@ private function action( } catch (Throwable $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' request for {history.type} '#{history.id}: {history.title}' metadata. {exception.message}", + message: "Failed to request '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata. {exception.message}", context: [ ...$logContext, ...exception_log($e), @@ -187,12 +191,12 @@ private function action( if (Status::OK !== Status::tryFrom($response->getStatusCode())) { if (Status::NOT_FOUND === Status::tryFrom($response->getStatusCode())) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned with (404: Not Found) status code.", + message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned HTTP 404 (Not Found).", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], ); } else { $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], ); } @@ -218,7 +222,11 @@ private function action( if ($entity->watched === $isWatched) { $this->logger->info( message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. Play state is identical.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'push.skip', + 'error' => 'play_state_identical', + ], ); continue; } @@ -228,7 +236,13 @@ private function action( if (null === ($date = ag($json, $dateKey))) { $this->logger->error( message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. No {date_key} is set on backend object.", - context: ['date_key' => $dateKey, ...$logContext, 'response' => ['body' => $json]], + context: [ + 'date_key' => $dateKey, + ...$logContext, + 'operation' => 'push.skip', + 'error' => 'no_backend_date', + 'response' => ['body' => $json], + ], ); continue; } @@ -242,11 +256,13 @@ private function action( message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. Database date is older than backend date.", context: [ ...$logContext, + 'operation' => 'push.skip', + 'error' => 'stale_database_date', 'comparison' => [ - 'database' => make_date($entity->updated), - 'backend' => $date, - 'difference' => $date->getTimestamp() - $entity->updated, - 'extra_margin' => [Options::EXPORT_ALLOWED_TIME_DIFF => $timeExtra], + 'database_date' => make_date($entity->updated), + 'backend_date' => $date, + 'delta_seconds' => $date->getTimestamp() - $entity->updated, + 'margin_seconds' => $timeExtra, ], ], ); @@ -320,7 +336,7 @@ private function action( } catch (Throwable $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' push play state. {exception.message}", + message: "Failed to push play state for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. {exception.message}", context: [ ...$logContext, ...exception_log($e), diff --git a/src/Backends/Jellyfin/Action/SearchQuery.php b/src/Backends/Jellyfin/Action/SearchQuery.php index 707b8885..d1e19f7d 100644 --- a/src/Backends/Jellyfin/Action/SearchQuery.php +++ b/src/Backends/Jellyfin/Action/SearchQuery.php @@ -132,7 +132,7 @@ private function search(Context $context, string $query, int $limit = 25, array return new Response( status: false, error: new Error( - message: "Search request for '{query}' in '{identity.user}@{identity.backend}' returned with unexpected '{response.status_code}' status code.", + message: "Search request for '{query}' in '{identity.user}@{identity.backend}' returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], diff --git a/src/Backends/Jellyfin/JellyfinGuid.php b/src/Backends/Jellyfin/JellyfinGuid.php index 387b713a..6648fcd8 100644 --- a/src/Backends/Jellyfin/JellyfinGuid.php +++ b/src/Backends/Jellyfin/JellyfinGuid.php @@ -52,8 +52,9 @@ public function __construct( $this->parseGUIDFile($file); } } catch (Throwable $e) { - $this->logger->error("{class}: Failed to read or parse '{guid}' file. {exception.message}.", [ - 'class' => after_last(static::class, '\\'), + $this->logger->error("Failed to read or parse GUID file '{guid}'. {exception.message}", [ + 'operation' => 'guid.load_file', + 'error' => 'file_parse_failed', 'guid' => $file, ...exception_log($e), ]); @@ -78,7 +79,10 @@ public function parseGUIDFile(string $file): void } if (filesize($file) < 1) { - $this->logger->info("The external GUID mapping file '{file}' is empty.", ['file' => $file]); + $this->logger->info("The external GUID mapping file '{file}' is empty.", [ + 'operation' => 'guid.load_file', + 'file' => $file, + ]); return; } @@ -125,7 +129,9 @@ public function parseGUIDFile(string $file): void foreach ($mapping as $key => $map) { if (false === is_array($map)) { - $this->logger->warning("Ignoring 'links.{key}'. Value must be an object. '{given}' is given.", [ + $this->logger->warning("Ignoring link mapping '{key}'. Value must be an object. '{given}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_not_object', 'key' => $key, 'type' => $this->type, 'given' => get_debug_type($map), @@ -140,7 +146,9 @@ public function parseGUIDFile(string $file): void $mapper = ag($map, 'map', null); if (false === is_array($mapper)) { - $this->logger->warning("Ignoring 'links.{key}'. map value must be an object. '{given}' is given.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map' value must be an object. '{given}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_map_not_object', 'key' => $key, 'type' => $this->type, 'given' => get_debug_type($mapper), @@ -152,7 +160,9 @@ public function parseGUIDFile(string $file): void $to = ag($mapper, 'to', null); if (empty($from) || false === is_string($from)) { - $this->logger->warning("Ignoring 'links.{key}'. map.from field is empty or not a string.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.from' field is empty or not a string.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_from_missing', 'type' => $this->type, 'key' => $key, ]); @@ -160,7 +170,9 @@ public function parseGUIDFile(string $file): void } if (empty($to) || false === is_string($to)) { - $this->logger->warning("Ignoring 'links.{key}'. map.to field is empty or not a string.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.to' field is empty or not a string.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_missing', 'type' => $this->type, 'key' => $key, ]); @@ -168,7 +180,9 @@ public function parseGUIDFile(string $file): void } if (false === Guid::validateGUIDName($to)) { - $this->logger->warning("Ignoring 'links.{key}'. map.to '{to}' field does not starts with 'guid_'.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.to' field does not starts with 'guid_', '{to}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_not_guid', 'type' => $this->type, 'key' => $key, 'to' => $to, @@ -177,7 +191,9 @@ public function parseGUIDFile(string $file): void } if (false === in_array($to, $supported, true)) { - $this->logger->warning("Ignoring 'links.{key}'. map.to field is not a supported GUID type.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.to' field is not a supported GUID type, '{to}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_not_supported', 'type' => $this->type, 'key' => $key, 'to' => $to, @@ -244,9 +260,10 @@ protected function ListExternalIds(array $guids, array $context = [], bool $log if (true === is_ignored_id($this->context->userContext, $bName, $type, $key, $value, $id)) { if (true === $log) { $this->logger->debug( - "{class}: Ignoring '{identity.client}: {identity.user}@{identity.backend}' external id '{source}' for {item.type} '{item.id}: {item.title}' as requested.", + "Ignoring '{identity.client}: {identity.user}@{identity.backend}' external id '{source}' for {item.type} '{item.id}: {item.title}' as requested.", [ - 'class' => after_last(static::class, '\\'), + 'operation' => 'guid.parse', + 'error' => 'ignored_by_user', 'identity' => [ 'client' => $this->context->clientName, 'user' => $this->context->userContext->name, @@ -268,9 +285,10 @@ protected function ListExternalIds(array $guids, array $context = [], bool $log } catch (Throwable $e) { if (true === $log) { $this->logger->info( - message: "{class}: Ignoring '{identity.user}@{identity.backend}' invalid GUID '{agent}' for {item.type} '{item.id}: {item.title}'.", + message: "Ignoring '{identity.user}@{identity.backend}' invalid GUID '{agent}' for {item.type} '{item.id}: {item.title}'.", context: [ - 'class' => after_last(static::class, '\\'), + 'operation' => 'guid.parse', + 'error' => 'invalid_guid', 'identity' => [ 'user' => $this->context->userContext->name, 'backend' => $this->context->backendName, diff --git a/src/Backends/Plex/Action/AddWebhook.php b/src/Backends/Plex/Action/AddWebhook.php index ca731b0d..69dc0aa6 100644 --- a/src/Backends/Plex/Action/AddWebhook.php +++ b/src/Backends/Plex/Action/AddWebhook.php @@ -97,7 +97,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get webhooks returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' get webhooks returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ @@ -116,7 +116,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get webhooks returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' get webhooks returned an empty response.", context: [...$logContext, 'response' => ['body' => $content]], level: Levels::ERROR, ), @@ -176,7 +176,7 @@ private function addWebhook(Context $context, string $webhookUrl, array $opts = return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' to add webhook returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' to add webhook returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ diff --git a/src/Backends/Plex/Action/CreatePlaylist.php b/src/Backends/Plex/Action/CreatePlaylist.php index f22cc3bb..e5605952 100644 --- a/src/Backends/Plex/Action/CreatePlaylist.php +++ b/src/Backends/Plex/Action/CreatePlaylist.php @@ -103,7 +103,7 @@ private function action(Context $context, string $title, array $itemIds): Respon return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{title}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{title}' returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], diff --git a/src/Backends/Plex/Action/DeletePlaylist.php b/src/Backends/Plex/Action/DeletePlaylist.php index 78ef357f..7e44a7f4 100644 --- a/src/Backends/Plex/Action/DeletePlaylist.php +++ b/src/Backends/Plex/Action/DeletePlaylist.php @@ -72,7 +72,7 @@ private function action(Context $context, string|int $id): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Plex/Action/Export.php b/src/Backends/Plex/Action/Export.php index 2ac57730..a9426ea5 100644 --- a/src/Backends/Plex/Action/Export.php +++ b/src/Backends/Plex/Action/Export.php @@ -222,7 +222,7 @@ protected function process( if (Status::OK !== Status::tryFrom($statusCode)) { $this->logger->error( - message: "Request to change '{identity.user}@{identity.backend}' {item.type} '{item.title}' play state returned with unexpected '{response.status_code}' status code.", + message: "Request to change '{identity.user}@{identity.backend}' {item.type} '{item.title}' play state returned HTTP {response.status_code}.", context: [ ...$requestContext, 'response' => ['status_code' => $statusCode], diff --git a/src/Backends/Plex/Action/GetInfo.php b/src/Backends/Plex/Action/GetInfo.php index 7736619b..6d35c5e4 100644 --- a/src/Backends/Plex/Action/GetInfo.php +++ b/src/Backends/Plex/Action/GetInfo.php @@ -78,7 +78,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get info returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' get info returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => [ @@ -99,7 +99,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' get info returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' get info returned an empty response.", context: [...$logContext, 'response' => ['body' => $content]], level: Levels::ERROR, ), diff --git a/src/Backends/Plex/Action/GetLibrariesList.php b/src/Backends/Plex/Action/GetLibrariesList.php index ca8adf08..03f0d01d 100644 --- a/src/Backends/Plex/Action/GetLibrariesList.php +++ b/src/Backends/Plex/Action/GetLibrariesList.php @@ -195,7 +195,7 @@ private function real_request(Context $context, array $logContext = []): array if (Status::OK !== Status::tryFrom($response->getStatusCode())) { throw new RuntimeException( r( - text: "Request for '{identity.user}@{identity.backend}' libraries returned with unexpected '{response.status_code}' status code.", + text: "Request for '{identity.user}@{identity.backend}' libraries returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], ), ); diff --git a/src/Backends/Plex/Action/GetLibrary.php b/src/Backends/Plex/Action/GetLibrary.php index c8967b92..0cbd4291 100644 --- a/src/Backends/Plex/Action/GetLibrary.php +++ b/src/Backends/Plex/Action/GetLibrary.php @@ -112,7 +112,7 @@ private function action(Context $context, iGuid $guid, string|int $id, array $op return new Response( status: false, error: new Error( - message: "The requested '{identity.user}@{identity.backend}' library '{library.title}' returned with unsupported type '{library.type}'.", + message: "The requested '{identity.user}@{identity.backend}' library '{library.title}' returned unsupported type '{library.type}'.", context: $logContext, level: Levels::WARNING, ), @@ -155,7 +155,7 @@ private function action(Context $context, iGuid $guid, string|int $id, array $op return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' library '{library.title}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' library '{library.title}' returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], level: Levels::ERROR, ), @@ -232,7 +232,7 @@ private function action(Context $context, iGuid $guid, string|int $id, array $op if (Status::OK !== Status::tryFrom($response->getStatusCode())) { if (false === $noLog) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' {item.type} '{item.title}' metadata returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' {item.type} '{item.title}' metadata returned HTTP {response.status_code}.", context: [ ...$requestContext, 'response' => ['status_code' => $response->getStatusCode(), 'body' => $response->getContent(false)], diff --git a/src/Backends/Plex/Action/GetMetaData.php b/src/Backends/Plex/Action/GetMetaData.php index baee8253..24b9783e 100644 --- a/src/Backends/Plex/Action/GetMetaData.php +++ b/src/Backends/Plex/Action/GetMetaData.php @@ -93,7 +93,7 @@ public function __invoke(Context $context, string|int $id, array $opts = []): Re return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' - '{id}' item returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' - '{id}' item returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], ), ); diff --git a/src/Backends/Plex/Action/GetPlaylist.php b/src/Backends/Plex/Action/GetPlaylist.php index 37b3adc6..c2e8ded4 100644 --- a/src/Backends/Plex/Action/GetPlaylist.php +++ b/src/Backends/Plex/Action/GetPlaylist.php @@ -66,7 +66,7 @@ private function action(Context $context, string|int $id, array $opts = []): Res return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $detailResponse->getStatusCode()]], level: Levels::ERROR, ), @@ -97,7 +97,7 @@ private function action(Context $context, string|int $id, array $opts = []): Res return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' items returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlist '{id}' items returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $itemsResponse->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Plex/Action/GetPlaylistsList.php b/src/Backends/Plex/Action/GetPlaylistsList.php index 120c4ffa..8db3d740 100644 --- a/src/Backends/Plex/Action/GetPlaylistsList.php +++ b/src/Backends/Plex/Action/GetPlaylistsList.php @@ -67,7 +67,7 @@ private function action(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' playlists returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' playlists returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], level: Levels::ERROR, ), diff --git a/src/Backends/Plex/Action/GetSessions.php b/src/Backends/Plex/Action/GetSessions.php index ca6bc9f3..e8361124 100644 --- a/src/Backends/Plex/Action/GetSessions.php +++ b/src/Backends/Plex/Action/GetSessions.php @@ -77,7 +77,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' active play sessions returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' active play sessions returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode(), 'body' => $content], @@ -91,7 +91,7 @@ public function __invoke(Context $context, array $opts = []): Response return new Response( status: false, error: new Error( - message: "Request for '{identity.user}@{identity.backend}' active play sessions returned with empty response.", + message: "Request for '{identity.user}@{identity.backend}' active play sessions returned an empty response.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode(), 'body' => $content], diff --git a/src/Backends/Plex/Action/GetUserToken.php b/src/Backends/Plex/Action/GetUserToken.php index 16988a7d..5e86a6c3 100644 --- a/src/Backends/Plex/Action/GetUserToken.php +++ b/src/Backends/Plex/Action/GetUserToken.php @@ -361,7 +361,7 @@ private function request( return new Response( status: false, error: new Error( - message: "Request to '{identity.user}@{identity.backend}' to grant access token for '{user_id}' returned with unexpected '{response.status_code}' status code. {tokenType}{extra_msg}", + message: "Request to '{identity.user}@{identity.backend}' to grant access token for '{user_id}' returned HTTP {response.status_code}. {tokenType}{extra_msg}", context: [ 'identity' => [ 'user' => $context->userContext->name, diff --git a/src/Backends/Plex/Action/GetUsersList.php b/src/Backends/Plex/Action/GetUsersList.php index 15f48368..872a748b 100644 --- a/src/Backends/Plex/Action/GetUsersList.php +++ b/src/Backends/Plex/Action/GetUsersList.php @@ -621,7 +621,7 @@ private function request(iUri $url, Context $context, array $opts = []): iRespon throw new InvalidArgumentException( r( - "Request for '{identity.user}@{identity.backend}' users list returned with unexpected '{response.status_code}' status code. {tokenType}{extra_msg}", + "Request for '{identity.user}@{identity.backend}' users list returned HTTP {response.status_code}. {tokenType}{extra_msg}", [ 'identity' => [ 'user' => $context->userContext->name, diff --git a/src/Backends/Plex/Action/Import.php b/src/Backends/Plex/Action/Import.php index 247a0c63..5e6318a7 100644 --- a/src/Backends/Plex/Action/Import.php +++ b/src/Backends/Plex/Action/Import.php @@ -155,7 +155,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } $this->logger->error( - "Request for '{identity.user}@{identity.backend}' libraries returned with unexpected '{response.status_code}' status code.", + "Request for '{identity.user}@{identity.backend}' libraries returned HTTP {response.status_code}.", $logContext, ); @@ -175,7 +175,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro if (empty($listDirs)) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' libraries returned with empty list.", + message: "Request for '{identity.user}@{identity.backend}' libraries returned an empty list.", context: [ ...$rContext, 'response' => [ @@ -190,7 +190,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (ExceptionInterface $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' libraries has failed. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' libraries failed. {exception.message}", context: [...$rContext, ...exception_log($e)], e: $e, ), @@ -200,7 +200,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (JsonException $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' libraries returned with invalid body. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' libraries returned invalid JSON. {exception.message}", context: [...$rContext, ...exception_log($e)], e: $e, ), @@ -351,7 +351,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (ExceptionInterface $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count has failed. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count failed. {exception.message}", context: [...$rContext, ...exception_log($e), ...$logContext], e: $e, ), @@ -376,7 +376,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro try { if (Status::OK !== Status::tryFrom($response->getStatusCode())) { $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], @@ -389,7 +389,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro if ($totalCount < 1) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned with 0 or less.", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' items count returned 0 items.", context: [ ...$logContext, 'response' => [ @@ -408,7 +408,7 @@ protected function getLibraries(Context $context, Closure $handle, Closure $erro } catch (ExceptionInterface $e) { $this->logger->error( ...lw( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' total items has failed. {exception.message}", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title}' total items failed. {exception.message}", context: [...$logContext, ...exception_log($e)], e: $e, ), @@ -665,7 +665,7 @@ protected function handle(Context $context, iResponse $response, Closure $callba { if (Status::OK !== Status::tryFrom($response->getStatusCode())) { $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' - '{library.title} {segment.number}/{segment.of}' content returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' - '{library.title} {segment.number}/{segment.of}' content returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], @@ -881,9 +881,11 @@ protected function process( if (null === ag($item, true === (bool) ag($item, 'viewCount', false) ? 'lastViewedAt' : 'addedAt')) { $this->logger->debug( - message: "Ignoring '{identity.user}@{identity.backend}' - '{item.id}: {item.title}'. No date '{date_key}' is set on object. '{response.body}'", + message: "Ignoring '{identity.user}@{identity.backend}' - '{item.id}: {item.title}'. No date '{date_key}' is set on object.", context: [ ...$logContext, + 'operation' => 'import.item_skip', + 'error' => 'no_date_set', 'date_key' => true === (bool) ag($item, 'viewCount', false) ? 'lastViewedAt' : 'addedAt', 'response' => [ 'body' => $item, diff --git a/src/Backends/Plex/Action/Progress.php b/src/Backends/Plex/Action/Progress.php index 3acd71e3..7046a06d 100644 --- a/src/Backends/Plex/Action/Progress.php +++ b/src/Backends/Plex/Action/Progress.php @@ -137,7 +137,11 @@ private function action( if ($context->backendName === $entity->via && false === $replayProgress) { $this->logger->info( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event originated from this backend.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'event_from_this_backend', + ], ); continue; } @@ -145,7 +149,11 @@ private function action( if (null === ag($metadata, iState::COLUMN_ID, null)) { $this->logger->warning( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. No metadata was found.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'no_metadata', + ], ); continue; } @@ -154,7 +162,11 @@ private function action( if (null === $senderDate) { $this->logger->warning( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The event originator did not set a date.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'no_event_date', + ], ); continue; } @@ -165,12 +177,16 @@ private function action( if (false === $ignoreDate && null !== $datetime && make_date($datetime)->getTimestamp() > $senderDate) { $this->logger->warning( - message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{event_date}' is older than backend local db item date '{local_date}'.", + message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{comparison.event_date}' is older than local database date '{comparison.local_date}'.", context: [ ...$logContext, - 'event_date' => make_date($senderDate), - 'local_date' => make_date($datetime), - 'compare' => ['remote' => make_date($datetime), 'sender' => make_date($senderDate)], + 'operation' => 'progress.skip', + 'error' => 'stale_event_date', + 'comparison' => [ + 'event_date' => make_date($senderDate), + 'local_date' => make_date($datetime), + 'delta_seconds' => make_date($datetime)->getTimestamp() - $senderDate, + ], ], ); continue; @@ -181,7 +197,11 @@ private function action( if (array_key_exists($logContext['remote']['id'], $sessions)) { $this->logger->notice( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The item is playing right now.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'currently_playing', + ], ); continue; } @@ -199,14 +219,15 @@ private function action( if (false === $ignoreDate && make_date($remoteItem->updated)->getTimestamp() > $senderDate) { $this->logger->info( - message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{event_date}' is older than backend remote item date '{remote_date}'.", + message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. Event date '{comparison.event_date}' is older than backend date '{comparison.remote_date}'.", context: [ ...$logContext, - 'event_date' => make_date($senderDate), - 'remote_date' => make_date($remoteItem->updated), - 'compare' => [ - 'remote' => make_date($remoteItem->updated), - 'sender' => make_date($senderDate), + 'operation' => 'progress.skip', + 'error' => 'stale_event_date', + 'comparison' => [ + 'event_date' => make_date($senderDate), + 'remote_date' => make_date($remoteItem->updated), + 'delta_seconds' => make_date($remoteItem->updated)->getTimestamp() - $senderDate, ], ], ); @@ -222,7 +243,11 @@ private function action( if (false === ($allowUpdate >= $minThreshold && time() > ($entity->updated + $allowUpdate))) { $this->logger->info( message: "Not processing '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. The backend says the item is marked as watched.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'progress.skip', + 'error' => 'backend_marked_watched', + ], ); continue; } @@ -231,7 +256,7 @@ private function action( } catch (\App\Libs\Exceptions\RuntimeException|RuntimeException|InvalidArgumentException $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' get {history.type} '#{history.id}: {history.title}' status. {exception.message}", + message: "Failed to get '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' status. {exception.message}", context: [ ...$logContext, ...exception_log($e), @@ -286,7 +311,7 @@ private function action( if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $this->logger->error( - message: "Request to change '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' watch progress returned with unexpected '{response.status_code}' status code.", + message: "Watch progress update for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' returned HTTP {response.status_code}.", context: [ ...$requestContext, 'response' => ['status_code' => $statusCode], @@ -309,7 +334,7 @@ private function action( error: function (Throwable $e) use ($requestContext): array { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' request to change watch progress of {history.type} '#{history.id}: {history.title}'. {exception.message}", + message: "Failed to update watch progress for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. {exception.message}", context: [ ...$requestContext, ...exception_log($e), @@ -351,7 +376,7 @@ private function action( $statusCode = $response->getStatusCode(); if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $this->logger->error( - message: "Request to mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update returned with unexpected '{response.status_code}' status code.", + message: "Mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update returned HTTP {response.status_code}.", context: [ ...$unwatchContext, 'error' => 'unexpected_status', @@ -367,7 +392,7 @@ private function action( error: function (Throwable $e) use ($unwatchContext): array { $this->logger->error( ...lw( - message: "Exception was thrown during '{identity.user}@{identity.backend}' unplayed request before progress update.", + message: "Failed to mark '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' as unplayed before progress update. {exception.message}", context: [ ...$unwatchContext, 'error' => 'request_exception', @@ -393,7 +418,7 @@ private function action( } catch (Throwable $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' change {history.type} '#{history.id}: {history.title}' watch progress. {exception.message}", + message: "Failed to update watch progress for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. {exception.message}", context: [ ...$logContext, ...exception_log($e), diff --git a/src/Backends/Plex/Action/Push.php b/src/Backends/Plex/Action/Push.php index 9f07e0a7..a253e7f6 100644 --- a/src/Backends/Plex/Action/Push.php +++ b/src/Backends/Plex/Action/Push.php @@ -97,7 +97,11 @@ private function action( if (null === ag($metadata, iState::COLUMN_ID)) { $this->logger->warning( message: "Ignoring '#{history.id}: {history.title}' for '{identity.user}@{identity.backend}'. No metadata was found.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'push.skip', + 'error' => 'no_metadata', + ], ); continue; } @@ -124,7 +128,7 @@ private function action( } catch (Throwable $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' request for {history.type} '#{history.id}: {history.title}' metadata. {exception.message}", + message: "Failed to request '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata. {exception.message}", context: [ ...$logContext, ...exception_log($e), @@ -156,12 +160,12 @@ private function action( if (Status::OK !== Status::tryFrom($response->getStatusCode())) { if (Status::NOT_FOUND === Status::tryFrom($response->getStatusCode())) { $this->logger->warning( - message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned with (404: Not Found) status code.", + message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned HTTP 404 (Not Found).", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], ); } else { $this->logger->error( - message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned with unexpected '{response.status_code}' status code.", + message: "Request for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}' metadata returned HTTP {response.status_code}.", context: [...$logContext, 'response' => ['status_code' => $response->getStatusCode()]], ); } @@ -186,7 +190,7 @@ private function action( if (empty($json)) { $this->logger->error( - message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. Returned with unexpected body.", + message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. Backend returned unexpected body.", context: [...$logContext, 'response' => ['body' => $body]], ); continue; @@ -197,7 +201,11 @@ private function action( if ($entity->watched === $isWatched) { $this->logger->info( message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. Play state is identical.", - context: $logContext, + context: [ + ...$logContext, + 'operation' => 'push.skip', + 'error' => 'play_state_identical', + ], ); continue; } @@ -207,8 +215,14 @@ private function action( if (null === ($date = ag($json, $dateKey))) { $this->logger->error( - message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '{history.title}'. No {date_key} is set on backend object.", - context: ['date_key' => $dateKey, ...$logContext, 'response' => ['body' => $json]], + message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. No {date_key} is set on backend object.", + context: [ + 'date_key' => $dateKey, + ...$logContext, + 'operation' => 'push.skip', + 'error' => 'no_backend_date', + 'response' => ['body' => $json], + ], ); continue; } @@ -219,14 +233,16 @@ private function action( if ($date->getTimestamp() >= ($entity->updated + $timeExtra)) { $this->logger->notice( - message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '{history.title}'. Database date is older than backend date.", + message: "Ignoring '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. Database date '{comparison.database_date}' is older than backend date '{comparison.backend_date}'.", context: [ ...$logContext, + 'operation' => 'push.skip', + 'error' => 'stale_database_date', 'comparison' => [ - 'database' => make_date($entity->updated), - 'backend' => $date, - 'difference' => $date->getTimestamp() - $entity->updated, - 'extra_margin' => [Options::EXPORT_ALLOWED_TIME_DIFF => $timeExtra], + 'database_date' => make_date($entity->updated), + 'backend_date' => $date, + 'delta_seconds' => $date->getTimestamp() - $entity->updated, + 'margin_seconds' => $timeExtra, ], ], ); @@ -270,7 +286,7 @@ private function action( } catch (Throwable $e) { $this->logger->error( ...lw( - message: "Failed during '{identity.user}@{identity.backend}' push play state. {exception.message}", + message: "Failed to push play state for '{identity.user}@{identity.backend}' {history.type} '#{history.id}: {history.title}'. {exception.message}", context: [ ...$logContext, ...exception_log($e), diff --git a/src/Backends/Plex/Action/SearchQuery.php b/src/Backends/Plex/Action/SearchQuery.php index 29c1ffd8..fbf93512 100644 --- a/src/Backends/Plex/Action/SearchQuery.php +++ b/src/Backends/Plex/Action/SearchQuery.php @@ -118,7 +118,7 @@ private function search(Context $context, string $query, int $limit = 25, array return new Response( status: false, error: new Error( - message: "Search request for '{query}' in '{identity.user}@{identity.backend}' returned with unexpected '{response.status_code}' status code.", + message: "Search request for '{query}' in '{identity.user}@{identity.backend}' returned HTTP {response.status_code}.", context: [ ...$logContext, 'response' => ['status_code' => $response->getStatusCode()], diff --git a/src/Backends/Plex/PlexClient.php b/src/Backends/Plex/PlexClient.php index 61022c7d..2513e813 100644 --- a/src/Backends/Plex/PlexClient.php +++ b/src/Backends/Plex/PlexClient.php @@ -866,7 +866,7 @@ public static function discover(iHttp $http, #[\SensitiveParameter] string $toke throw new RuntimeException( r( - text: "Request for servers list returned with unexpected '{response.status_code}' status code. {context}", + text: 'Request for servers list returned HTTP {response.status_code}. {context}', context: [ 'response' => ['status_code' => $response->getStatusCode()], 'context' => array_to_string([ diff --git a/src/Backends/Plex/PlexGuid.php b/src/Backends/Plex/PlexGuid.php index 9f2f4961..881b5a1c 100644 --- a/src/Backends/Plex/PlexGuid.php +++ b/src/Backends/Plex/PlexGuid.php @@ -96,7 +96,9 @@ public function __construct( $this->parseGUIDFile($file); } } catch (Throwable $e) { - $this->logger->error("Failed to read or parse '{guid}' file. {exception.message}.", [ + $this->logger->error("Failed to read or parse GUID file '{guid}'. {exception.message}", [ + 'operation' => 'guid.load_file', + 'error' => 'file_parse_failed', 'guid' => $file, ...exception_log($e), ]); @@ -121,7 +123,10 @@ public function parseGUIDFile(string $file): void } if (filesize($file) < 1) { - $this->logger->info("The external GUID mapping file '{file}' is empty.", ['file' => $file]); + $this->logger->info("The external GUID mapping file '{file}' is empty.", [ + 'operation' => 'guid.load_file', + 'file' => $file, + ]); return; } @@ -169,7 +174,9 @@ public function parseGUIDFile(string $file): void foreach ($mapping as $key => $map) { if (false === is_array($map)) { - $this->logger->warning("Ignoring 'links.{key}'. Value must be an object. '{given}' is given.", [ + $this->logger->warning("Ignoring link mapping '{key}'. Value must be an object. '{given}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_not_object', 'key' => $key, 'given' => get_debug_type($map), ]); @@ -182,13 +189,12 @@ public function parseGUIDFile(string $file): void if (null !== ($replace = ag($map, 'options.replace', null))) { if (false === is_array($replace)) { - $this->logger->warning( - "Ignoring 'links.{key}'. options.replace value must be an object. '{given}' is given.", - [ - 'key' => $key, - 'given' => get_debug_type($replace), - ], - ); + $this->logger->warning("Ignoring link mapping '{key}'. 'options.replace' value must be an object. '{given}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_replace_not_object', + 'key' => $key, + 'given' => get_debug_type($replace), + ]); continue; } @@ -197,8 +203,10 @@ public function parseGUIDFile(string $file): void if (empty($from) || false === is_string($from)) { $this->logger->warning( - "Ignoring 'links.{key}'. options.replace.from field is empty or not a string.", + "Ignoring link mapping '{key}'. 'options.replace.from' field is empty or not a string.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_from_missing', 'key' => $key, ], ); @@ -206,7 +214,9 @@ public function parseGUIDFile(string $file): void } if (false === is_string($to)) { - $this->logger->warning("Ignoring 'links.{key}'. options.replace.to field is not a string.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'options.replace.to' field is not a string.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_not_string', 'key' => $key, ]); continue; @@ -217,7 +227,9 @@ public function parseGUIDFile(string $file): void if (null !== ($mapper = ag($map, 'map', null))) { if (false === is_array($mapper)) { - $this->logger->warning("Ignoring 'links.{key}'. map value must be an object. '{given}' is given.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map' value must be an object. '{given}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_map_not_object', 'key' => $key, 'given' => get_debug_type($mapper), ]); @@ -228,14 +240,18 @@ public function parseGUIDFile(string $file): void $to = ag($mapper, 'to', null); if (empty($from) || false === is_string($from)) { - $this->logger->warning("Ignoring 'links.{key}'. map.from field is empty or not a string.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.from' field is empty or not a string.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_from_missing', 'key' => $key, ]); continue; } if (empty($to) || false === is_string($to)) { - $this->logger->warning("Ignoring 'links.{key}'. map.to field is empty or not a string.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.to' field is empty or not a string.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_missing', 'key' => $key, ]); continue; @@ -243,8 +259,10 @@ public function parseGUIDFile(string $file): void if (false === str_starts_with($to, 'guid_')) { $this->logger->warning( - "Ignoring 'links.{key}'. map.to '{to}' field does not starts with 'guid_'.", + "Ignoring link mapping '{key}'. 'map.to' field does not starts with 'guid_', '{to}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_not_guid', 'key' => $key, 'to' => $to, ], @@ -253,7 +271,9 @@ public function parseGUIDFile(string $file): void } if (false === in_array($to, $supported, true)) { - $this->logger->warning("Ignoring 'links.{key}'. map.to field is not a supported GUID type.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.to' field is not a supported GUID type, '{to}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_to_not_supported', 'key' => $key, 'to' => $to, ]); @@ -266,7 +286,9 @@ public function parseGUIDFile(string $file): void } if (true === in_array($from, $this->guidLegacy, true)) { - $this->logger->warning("Ignoring 'links.{key}'. map.from already exists.", [ + $this->logger->warning("Ignoring link mapping '{key}'. 'map.from' already exists, '{from}' given.", [ + 'operation' => 'guid.link_map', + 'error' => 'link_from_duplicate', 'key' => $key, 'from' => $from, ]); @@ -367,6 +389,8 @@ private function ListExternalIds(array $guids, array $context = [], bool $log = if (false === str_contains($val, '://')) { if (true === $log) { $this->logger->info("Unable to parse '{identity.backend}: {agent}' identifier.", [ + 'operation' => 'guid.parse', + 'error' => 'unparseable_identifier', 'identity' => [ 'backend' => $this->context->backendName, ], @@ -389,6 +413,8 @@ private function ListExternalIds(array $guids, array $context = [], bool $log = $this->logger->debug( "Ignoring '{identity.client}: {identity.backend}' external id '{source}' for {item.type} '{item.id}: {item.title}' as requested.", [ + 'operation' => 'guid.parse', + 'error' => 'ignored_by_user', 'identity' => [ 'client' => $this->context->clientName, 'backend' => $bName, @@ -415,6 +441,8 @@ private function ListExternalIds(array $guids, array $context = [], bool $log = $this->logger->info( "'{identity.client}: {identity.backend}' reported conflicting '{key}' external ids '{existing_id}' and '{new_id}' for {item.type} '{item.id}: {item.title}'.", [ + 'operation' => 'guid.parse', + 'error' => 'conflicting_ids', 'identity' => [ 'client' => $this->context->clientName, 'backend' => $this->context->backendName, @@ -440,9 +468,10 @@ private function ListExternalIds(array $guids, array $context = [], bool $log = } catch (Throwable $e) { if (true === $log) { $this->logger->info( - message: "{class}: Ignoring '{identity.user}@{identity.backend}' invalid GUID '{agent}' for {item.type} '{item.id}: {item.title}'.", + message: "Ignoring '{identity.user}@{identity.backend}' invalid GUID '{agent}' for {item.type} '{item.id}: {item.title}'.", context: [ - 'class' => after_last(self::class, '\\'), + 'operation' => 'guid.parse', + 'error' => 'invalid_guid', 'identity' => [ 'user' => $this->context->userContext->name, 'backend' => $this->context->backendName, @@ -506,8 +535,10 @@ private function parseLegacyAgent(string $guid, array $context = [], bool $log = } catch (Throwable $e) { if (true === $log) { $this->logger->error( - message: "Failed during '{identity.client}: {identity.backend}' parsing legacy agent '{agent}' identifier. {exception.message}", + message: "Failed to parse '{identity.client}: {identity.backend}' legacy agent '{agent}' identifier. {exception.message}", context: [ + 'operation' => 'guid.parse_legacy', + 'error' => 'legacy_parse_failed', 'identity' => [ 'backend' => $this->context->backendName, 'client' => $this->context->clientName, @@ -563,8 +594,10 @@ private function parseNfoAgent(string $guid, array $context = [], bool $log = tr } catch (Throwable $e) { if (true === $log) { $this->logger->error( - message: "Failed during '{identity.client}: {identity.backend}' parsing NFO agent '{agent}' identifier. {exception.message}", + message: "Failed to parse '{identity.client}: {identity.backend}' NFO agent '{agent}' identifier. {exception.message}", context: [ + 'operation' => 'guid.parse_nfo', + 'error' => 'nfo_parse_failed', 'identity' => [ 'backend' => $this->context->backendName, 'client' => $this->context->clientName, diff --git a/src/Commands/Backend/RestoreCommand.php b/src/Commands/Backend/RestoreCommand.php index 55ac701e..685d5917 100644 --- a/src/Commands/Backend/RestoreCommand.php +++ b/src/Commands/Backend/RestoreCommand.php @@ -137,13 +137,19 @@ protected function process(iInput $input, iOutput $output): int $userName = $input->getOption('user'); if (empty($userName)) { - $this->logger->warning('User not specified. Use [-u, --user].'); + $this->logger->warning('User not specified. Use [-u, --user].', [ + 'operation' => 'restore.validate', + 'error' => 'missing_user', + ]); return self::FAILURE; } $name = $input->getOption('select-backend'); if (empty($name)) { - $this->logger->warning('Backend not specified. Use [-s, --select-backend].'); + $this->logger->warning('Backend not specified. Use [-s, --select-backend].', [ + 'operation' => 'restore.validate', + 'error' => 'missing_backend', + ]); return self::FAILURE; } @@ -154,6 +160,8 @@ protected function process(iInput $input, iOutput $output): int if (false === file_exists($newFile) || false === is_readable($newFile)) { $this->logger->warning("Unable to read backup file '{file}'.", [ + 'operation' => 'restore.validate', + 'error' => 'unreadable_backup_file', 'file' => $file, ]); return self::FAILURE; @@ -169,7 +177,14 @@ protected function process(iInput $input, iOutput $output): int try { $userContext = get_user_context(user: $userName, mapper: $mapper, logger: $this->logger); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + "Failed to load user '{user}' for restore. {exception.message}", + [ + 'operation' => 'restore.load_user', + 'user' => $userName, + ...exception_log($e), + ], + ); return self::FAILURE; } @@ -464,8 +479,9 @@ protected function process(iInput $input, iOutput $output): int return self::SUCCESS; } catch (Throwable $e) { $this->logger->error( - "Failed during '{identity.user}@{identity.backend}' restore operation. {exception.message}", + "Failed to restore '{identity.user}@{identity.backend}'. {exception.message}", [ + 'operation' => 'restore.run', 'identity' => [ 'user' => $userContext->name, 'backend' => $name, diff --git a/src/Commands/Database/IndexCommand.php b/src/Commands/Database/IndexCommand.php index d3fa021d..6110f768 100644 --- a/src/Commands/Database/IndexCommand.php +++ b/src/Commands/Database/IndexCommand.php @@ -97,7 +97,13 @@ protected function runCommand(iInput $input, iOutput $output): int try { $users = select_users($input->getOption('user')); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to resolve index users. {exception.message}', + [ + 'operation' => 'db_index.resolve_users', + ...exception_log($e), + ], + ); return self::FAILURE; } diff --git a/src/Commands/State/BackupCommand.php b/src/Commands/State/BackupCommand.php index 49341f5c..d7814a63 100644 --- a/src/Commands/State/BackupCommand.php +++ b/src/Commands/State/BackupCommand.php @@ -233,11 +233,19 @@ protected function process(iInput $input): int select_users($input->getOption('user')), ); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage()); + $this->logger->error( + 'Failed to resolve backup users. {exception.message}', + [ + 'operation' => 'backup.resolve_users', + ...exception_log($e), + ], + ); return self::FAILURE; } - $this->logger->notice('Using WatchState {full_version}', ['full_version' => get_app_version()]); + $this->logger->notice('Using WatchState {full_version}', [ + 'full_version' => get_full_version(), + ]); foreach ($users as $userContext) { try { $this->process_backup($input, $userContext); @@ -274,6 +282,8 @@ private function process_backup(iInput $input, UserContext $userContext): void if (!isset($supported[$type])) { $this->logger->error("Ignoring '{identity.user}@{identity.backend}'. Unexpected type '{type}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'unexpected_backend_type', 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, @@ -286,6 +296,8 @@ private function process_backup(iInput $input, UserContext $userContext): void if (null === ($url = ag($backend, 'url')) || false === is_valid_url($url)) { $this->logger->error("Ignoring '{identity.user}@{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'invalid_url', 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, diff --git a/src/Commands/State/ExportCommand.php b/src/Commands/State/ExportCommand.php index 725ccdc6..8eb49edb 100644 --- a/src/Commands/State/ExportCommand.php +++ b/src/Commands/State/ExportCommand.php @@ -162,7 +162,13 @@ protected function process(iInput $input, iOutput $output): int select_users($input->getOption('user')), ); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to resolve export users. {exception.message}', + [ + 'operation' => 'export.resolve_users', + ...exception_log($e), + ], + ); return self::FAILURE; } @@ -216,7 +222,7 @@ protected function process(iInput $input, iOutput $output): int if (true !== (bool) ag($backend, 'export.enabled')) { if ($isCustom) { $this->logger->warning( - "Exporting to a export disabled backend '{identity.user}@{identity.backend}' as requested.", + "Exporting to an export disabled backend '{identity.user}@{identity.backend}' as requested.", [ 'identity' => [ 'user' => $userContext->name, @@ -239,6 +245,8 @@ protected function process(iInput $input, iOutput $output): int $this->logger->error( "Ignoring '{identity.user}@{identity.backend}'. Unexpected type '{type}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'unexpected_backend_type', 'type' => $type, 'identity' => [ 'backend' => $backendName, @@ -252,6 +260,8 @@ protected function process(iInput $input, iOutput $output): int if (null === ($url = ag($backend, 'url')) || false === is_valid_url($url)) { $this->logger->error("Ignoring '{identity.user}@{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'invalid_url', 'url' => $url ?? 'None', 'identity' => [ 'backend' => $backendName, @@ -545,7 +555,7 @@ protected function process(iInput $input, iOutput $output): int if (Status::OK !== Status::tryFrom($context['response']['status_code'])) { $logger->error( - "Request to change '{identity.user}@{identity.backend}' - '#{history.id}: {history.title}' play state returned with unexpected '{response.status_code}' status code.", + "Request to change '{identity.user}@{identity.backend}' - '#{history.id}: {history.title}' play state returned HTTP {response.status_code}.", $context, ); @@ -611,8 +621,10 @@ protected function process(iInput $input, iOutput $output): int ); } else { $this->logger->warning( - "Not updating '{identity.user}@{identity.backend}' export last sync date. There was errors recorded during the operation.", + "Not updating '{identity.user}@{identity.backend}' export last sync date due to errors recorded during the operation.", [ + 'operation' => 'export.sync_date', + 'error' => 'skipped_due_to_errors', 'identity' => [ 'backend' => $name, 'user' => $userContext->name, diff --git a/src/Commands/State/ImportCommand.php b/src/Commands/State/ImportCommand.php index fbcc7f84..6c096f2b 100644 --- a/src/Commands/State/ImportCommand.php +++ b/src/Commands/State/ImportCommand.php @@ -193,7 +193,13 @@ protected function process(InputInterface $input, OutputInterface $output): int try { $selectedUsers = select_users($input->getOption('user')); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to resolve import users. {exception.message}', + [ + 'operation' => 'import.resolve_users', + ...exception_log($e), + ], + ); return self::FAILURE; } @@ -243,7 +249,7 @@ protected function process(InputInterface $input, OutputInterface $output): int $metadata = false === $importEnabled; if ($isCustom && $input->getOption('exclude') === $this->in_array($selected, $backendName)) { - $this->logger->info("Ignoring '{identity.user}@{identity.backend}'. as requested.", [ + $this->logger->info("Ignoring '{identity.user}@{identity.backend}' as requested.", [ 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, @@ -258,6 +264,8 @@ protected function process(InputInterface $input, OutputInterface $output): int if (!isset($supported[$type])) { $this->logger->error("Ignoring '{identity.user}@{identity.backend}'. Unexpected type '{type}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'unexpected_backend_type', 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, @@ -270,6 +278,8 @@ protected function process(InputInterface $input, OutputInterface $output): int if (null === ($url = ag($backend, 'url')) || false === is_valid_url($url)) { $this->logger->error("Ignoring '{identity.user}@{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'invalid_url', 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, @@ -388,8 +398,10 @@ protected function process(InputInterface $input, OutputInterface $output): int if (false === $inDryMode) { if (true === (bool) Message::get("{$name}.has_errors")) { $this->logger->warning( - message: "Not updating '{identity.user}@{identity.backend}' import last sync date. There was errors recorded during the operation.", + message: "Not updating '{identity.user}@{identity.backend}' import last sync date due to errors recorded during the operation.", context: [ + 'operation' => 'import.sync_date', + 'error' => 'skipped_due_to_errors', 'identity' => [ 'user' => $userContext->name, 'backend' => $name, @@ -494,6 +506,7 @@ protected function process(InputInterface $input, OutputInterface $output): int $this->logger->notice( "Imported '{identity.user}' play states: {movie.added} added, {movie.updated} updated, {movie.failed} failed (movies); {episode.added} added, {episode.updated} updated, {episode.failed} failed (episodes).", [ + 'operation' => 'import.summary', 'identity' => [ 'user' => $userContext->name, ], diff --git a/src/Commands/State/PlaylistCommand.php b/src/Commands/State/PlaylistCommand.php index bb07acdc..c3749399 100644 --- a/src/Commands/State/PlaylistCommand.php +++ b/src/Commands/State/PlaylistCommand.php @@ -101,7 +101,13 @@ protected function process(InputInterface $input, OutputInterface $output): int try { $selectedUsers = select_users($input->getOption('user')); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to resolve playlist sync users. {exception.message}', + [ + 'operation' => 'playlist.resolve_users', + ...exception_log($e), + ], + ); return self::FAILURE; } @@ -351,6 +357,8 @@ protected function getClients(UserContext $userContext, array $selected = [], bo $this->logger->warning( "Ignoring '{identity.user}@{identity.backend}'. Unsupported backend type '{type}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'unsupported_backend_type', 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, @@ -367,6 +375,8 @@ protected function getClients(UserContext $userContext, array $selected = [], bo $this->logger->warning( "Ignoring '{identity.user}@{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'command.backend_config', + 'error' => 'invalid_url', 'identity' => [ 'user' => $userContext->name, 'backend' => $backendName, diff --git a/src/Commands/State/ValidateCommand.php b/src/Commands/State/ValidateCommand.php index a7f0d070..1cf06115 100644 --- a/src/Commands/State/ValidateCommand.php +++ b/src/Commands/State/ValidateCommand.php @@ -133,7 +133,13 @@ protected function process(iInput $input, iOutput $output): int select_users($input->getOption('user')), ); } catch (RuntimeException $e) { - $this->logger->error($e->getMessage(), exception_log($e)); + $this->logger->error( + 'Failed to resolve validate users. {exception.message}', + [ + 'operation' => 'validate.resolve_users', + ...exception_log($e), + ], + ); return self::FAILURE; } diff --git a/src/Commands/System/PruneCommand.php b/src/Commands/System/PruneCommand.php index 32d15f4b..ddd572b1 100644 --- a/src/Commands/System/PruneCommand.php +++ b/src/Commands/System/PruneCommand.php @@ -133,6 +133,8 @@ protected function runPruners(InputInterface $input, OutputInterface $output): i if (false === ag_exists($pruners, $prunerName)) { $this->logger->warning("Unknown pruner '{pruner}'. No pruner with that name registered.", [ + 'operation' => 'prune.run', + 'error' => 'unknown_pruner', 'pruner' => $prunerName, ]); @@ -160,6 +162,7 @@ protected function runPruners(InputInterface $input, OutputInterface $output): i if (count($run) < 1) { $this->logger->debug("No pruners scheduled at '{datetime}'.", [ + 'operation' => 'prune.run', 'datetime' => make_date(), ]); } @@ -237,6 +240,8 @@ protected function stringifyCallable(mixed $callable): string protected function reportPrunerError(array $pruner, Throwable $e, OutputInterface $output): void { $this->logger->warning("Skipping pruner '{name}'. {exception.message}", [ + 'operation' => 'prune.run', + 'error' => 'pruner_failed', 'name' => ag($pruner, 'name', 'unknown'), ...exception_log($e), ]); diff --git a/src/Commands/System/TasksCommand.php b/src/Commands/System/TasksCommand.php index fa595faf..478d9ad8 100644 --- a/src/Commands/System/TasksCommand.php +++ b/src/Commands/System/TasksCommand.php @@ -304,6 +304,8 @@ private function runTasks(iInput $input, iOutput $output): int if (false === ag_exists($tasks, $task)) { $this->logger->error("Unknown task '{task}'. No task with that name registered.", [ + 'operation' => 'task.run', + 'error' => 'unknown_task', 'task' => $task, ]); return self::FAILURE; @@ -325,6 +327,7 @@ private function runTasks(iInput $input, iOutput $output): int if (count($run) < 1) { $this->logger->debug("No task scheduled at '{datetime}'.", [ + 'operation' => 'task.run', 'datetime' => make_date(), ]); @@ -519,6 +522,8 @@ private function runProcess(array $cmd, iInput $input, iOutput $output, ?array $ $stream->close(); } catch (Throwable $e) { $this->logger->error("Failed to write to logfile '{file}': {exception.message}", [ + 'operation' => 'task.logfile', + 'error' => 'write_failed', 'file' => Config::get('tasks.logfile'), ...exception_log($e), ]); diff --git a/src/Libs/Database/PDO/PDOAdapter.php b/src/Libs/Database/PDO/PDOAdapter.php index f81daef1..be17cfcf 100644 --- a/src/Libs/Database/PDO/PDOAdapter.php +++ b/src/Libs/Database/PDO/PDOAdapter.php @@ -227,9 +227,10 @@ public function insert(iState $entity, array $opts = []): iState throw $e; } $this->logger->error( - message: 'Failed. {exception.message}', + message: 'Failed to insert state record. {exception.message}', context: [ 'entity' => $entity->getAll(), + 'operation' => 'state.insert', ...exception_log($e), 'last' => $this->db->getLastStatement(), ], @@ -444,9 +445,10 @@ public function update(iState $entity, array $opts = []): iState throw $e; } $this->logger->error( - message: 'Failed. {exception.message}', + message: 'Failed to update state record. {exception.message}', context: [ 'entity' => $entity->getAll(), + 'operation' => 'state.update', ...exception_log($e), 'last' => $this->db->getLastStatement(), ], @@ -481,9 +483,10 @@ public function remove(iState $entity): bool $this->db->query('DELETE FROM state WHERE id = :id', ['id' => (int) $id]); } catch (PDOException $e) { $this->logger->error( - message: 'Failed. {exception.message}', + message: 'Failed to remove state record. {exception.message}', context: [ 'entity' => $entity->getAll(), + 'operation' => 'state.remove', ...exception_log($e), ], ); @@ -517,9 +520,10 @@ public function commit(array $entities, array $opts = []): array } catch (PDOException $e) { $actions['failed']++; $this->logger->error( - message: 'Failed. {exception.message}', + message: 'Failed to commit state record. {exception.message}', context: [ 'entity' => $entity->getAll(), + 'operation' => 'state.commit', ...exception_log($e), ], ); diff --git a/src/Libs/Guid.php b/src/Libs/Guid.php index ee08f4e0..9bcb2666 100644 --- a/src/Libs/Guid.php +++ b/src/Libs/Guid.php @@ -173,6 +173,8 @@ public function __construct(array $guids, array $context = [], ?iLogger $logger $this->getLogger()->info( "Ignoring '{identity.backend}' {item.type} '{item.title}' '{key}' external id. Unexpected value type.", [ + 'operation' => 'guid.validate', + 'error' => 'unexpected_value_type', 'key' => $key, 'condition' => [ 'expecting' => self::$supported[$key], @@ -189,6 +191,8 @@ public function __construct(array $guids, array $context = [], ?iLogger $logger $this->getLogger()->info( "Ignoring '{identity.backend}' {item.type} '{item.title}' '{key}' external id. Unexpected value '{given}'. Expecting '{expected}'.", [ + 'operation' => 'guid.validate', + 'error' => 'unexpected_value', 'key' => $key, 'expected' => self::$validateGuid[$key]['example'], 'given' => $value, @@ -235,7 +239,10 @@ public static function parseGUIDFile(string $file): void } if (filesize($file) < 1) { - self::$logger?->info(r("The external GUID mapping file '{file}' is empty.", ['file' => $file])); + self::$logger?->info("The external GUID mapping file '{file}' is empty.", [ + 'operation' => 'guid.load_file', + 'file' => $file, + ]); return; } @@ -279,6 +286,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}'. Value must be an object. '{given}' is given.", [ + 'operation' => 'guid.definition', + 'error' => 'def_not_object', 'key' => $key, 'given' => get_debug_type($def), ], @@ -291,6 +300,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}'. name must start with 'guid_'. '{given}' is given.", [ + 'operation' => 'guid.definition', + 'error' => 'def_name_invalid', 'key' => $key, 'given' => $name ?? 'null', ], @@ -303,6 +314,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}.{name}'. type must be a string. '{given}' is given.", [ + 'operation' => 'guid.definition', + 'error' => 'def_type_not_string', 'key' => $key, 'name' => $name, 'given' => get_debug_type($type), @@ -316,6 +329,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}.{name}'. validator key must be an object. '{given}' is given.", [ + 'operation' => 'guid.definition', + 'error' => 'def_validator_not_object', 'key' => $key, 'name' => $name, 'given' => get_debug_type($validator), @@ -327,6 +342,8 @@ public static function parseGUIDFile(string $file): void $pattern = ag($validator, 'pattern'); if (null === $pattern || false === @preg_match($pattern, '')) { self::$logger?->warning("Ignoring 'guids.{key}.{name}'. validator.pattern is empty or invalid.", [ + 'operation' => 'guid.definition', + 'error' => 'def_pattern_invalid', 'key' => $key, 'name' => $name, ]); @@ -337,6 +354,8 @@ public static function parseGUIDFile(string $file): void if (empty($example) || false === is_string($example)) { self::$logger?->warning("Ignoring 'guids.{key}.{name}'. validator.example is empty or not a string.", [ + 'operation' => 'guid.definition', + 'error' => 'def_example_missing', 'key' => $key, 'name' => $name, ]); @@ -346,6 +365,8 @@ public static function parseGUIDFile(string $file): void $tests = ag($validator, 'tests', []); if (empty($tests) || false === is_array($tests)) { self::$logger?->warning("Ignoring 'guids.{key}.{name}'. validator.tests key must be an object.", [ + 'operation' => 'guid.definition', + 'error' => 'def_tests_not_object', 'key' => $key, 'name' => $name, ]); @@ -355,6 +376,8 @@ public static function parseGUIDFile(string $file): void $valid = ag($tests, 'valid', []); if (empty($valid) || false === is_array($valid) || count($valid) < 1) { self::$logger?->warning("Ignoring 'guids.{key}.{name}'. validator.tests.valid key must be an array.", [ + 'operation' => 'guid.definition', + 'error' => 'def_valid_tests_not_array', 'key' => $key, 'name' => $name, ]); @@ -369,6 +392,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}.{name}'. validator.tests.valid value '{val}' does not match pattern.", [ + 'operation' => 'guid.definition', + 'error' => 'def_valid_test_no_match', 'key' => $key, 'name' => $name, 'val' => $val, @@ -382,6 +407,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}.{name}'. validator.tests.invalid key must be an array.", [ + 'operation' => 'guid.definition', + 'error' => 'def_invalid_tests_not_array', 'key' => $key, 'name' => $name, ], @@ -397,6 +424,8 @@ public static function parseGUIDFile(string $file): void self::$logger?->warning( "Ignoring 'guids.{key}.{name}'. validator.tests.invalid value '{val}' matches pattern.", [ + 'operation' => 'guid.definition', + 'error' => 'def_invalid_test_matches', 'key' => $key, 'name' => $name, 'val' => $val, @@ -576,7 +605,9 @@ private static function loadExternalGUID(): void self::parseGUIDFile($file); } } catch (Throwable $e) { - self::$logger?->error("Failed to read or parse '{guid}' file. Error '{exception.message}'.", [ + self::$logger?->error("Failed to read or parse GUID file '{guid}'. Error '{exception.message}'.", [ + 'operation' => 'guid.load_file', + 'error' => 'file_parse_failed', 'guid' => $file, ...exception_log($e), ]); diff --git a/src/Libs/Identities/IdentityProvisionService.php b/src/Libs/Identities/IdentityProvisionService.php index e8fa38fe..5a3fa5d9 100644 --- a/src/Libs/Identities/IdentityProvisionService.php +++ b/src/Libs/Identities/IdentityProvisionService.php @@ -42,6 +42,8 @@ public function loadBackends(): array if (!isset($supported[$type])) { $this->logger->error("Ignoring '{identity.backend}'. Unexpected backend type '{type}'.", [ + 'operation' => 'identity.discover', + 'error' => 'unexpected_backend_type', 'type' => $type, 'identity' => [ 'backend' => $backendName, @@ -52,7 +54,9 @@ public function loadBackends(): array } if (null === ($url = ag($backend, 'url')) || false === is_valid_url($url)) { - $this->logger->error("Ignoring '{identity.backend}'. Invalid url '{url}'.", [ + $this->logger->error("Ignoring '{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'identity.discover', + 'error' => 'invalid_url', 'url' => $url ?? 'None', 'identity' => [ 'backend' => $backendName, @@ -92,11 +96,17 @@ public function loadMappings(): array } if (false === $map->has('version')) { - $this->logger->warning('Starting with mapper.yaml v1.5, the version key is required.'); + $this->logger->warning('mapper.yaml is missing the version key. Required since v1.5.', [ + 'operation' => 'identity.mapper', + 'error' => 'missing_version_key', + ]); } if (false === $map->has('map')) { - $this->logger->warning('Please upgrade your mapper.yaml file to v1.5 format spec.'); + $this->logger->warning('mapper.yaml is missing the map key. Upgrade to v1.5 format spec.', [ + 'operation' => 'identity.mapper', + 'error' => 'missing_map_key', + ]); } $this->logger->info('Mapper file found, using it to map identities.', [ @@ -445,7 +455,13 @@ public function getBackendUsers(array $backends, array &$map, bool $noMapActions if (false === is_valid_name($user['name'])) { $this->logger->error( message: "Invalid user name '{identity.backend}: {name}'. User names must be in [a-z_0-9] format. Skipping user.", - context: ['name' => $user['name'], 'identity' => ['backend' => $backendName]], + context: [ + 'operation' => 'identity.sync', + 'error' => 'invalid_user_name', + 'constraint' => '[a-z_0-9]', + 'name' => $user['name'], + 'identity' => ['backend' => $backendName], + ], ); continue; } @@ -459,8 +475,13 @@ public function getBackendUsers(array $backends, array &$map, bool $noMapActions if (false === is_valid_name($info['backendName'])) { $this->logger->error( - message: "Invalid backend name '{name}'. Backend name must be in [a-z_0-9] format. skipping the associated users.", - context: ['name' => $info['backendName']], + message: "Invalid backend name '{name}'. Backend name must be in [a-z_0-9] format. Skipping the associated users.", + context: [ + 'operation' => 'identity.sync', + 'error' => 'invalid_backend_name', + 'constraint' => '[a-z_0-9]', + 'name' => $info['backendName'], + ], ); continue; } @@ -501,8 +522,9 @@ public function getBackendUsers(array $backends, array &$map, bool $noMapActions } } catch (Throwable $e) { $this->logger->error( - "Failed during '{identity.user}@{identity.backend}' get users list. {exception.message}", + "Failed to get users list from '{identity.user}@{identity.backend}'. {exception.message}", [ + 'operation' => 'identity.get_users', 'identity' => [ 'client' => $client->getContext()->clientName, 'backend' => $client->getContext()->backendName, @@ -533,8 +555,13 @@ public function createIdentities(IdentityProvisionRequest $request, array $ident if (false === is_valid_name($identityName)) { $this->logger->error( - message: "Invalid identity name '{identity.name}'. Identity names must be in [a-z_0-9] format. skipping identity.", - context: ['identity' => ['name' => $identityName]], + message: "Invalid identity name '{identity.name}'. Identity names must be in [a-z_0-9] format. Skipping identity.", + context: [ + 'operation' => 'identity.create', + 'error' => 'invalid_identity_name', + 'constraint' => '[a-z_0-9]', + 'identity' => ['name' => $identityName], + ], ); continue; } @@ -584,8 +611,13 @@ public function createIdentities(IdentityProvisionRequest $request, array $ident if (false === is_valid_name($name)) { $this->logger->error( - message: "Invalid backend name '{name}'. Backend name must be in [a-z_0-9] format. skipping backend.", - context: ['name' => $name], + message: "Invalid backend name '{name}'. Backend name must be in [a-z_0-9] format. Skipping backend.", + context: [ + 'operation' => 'identity.create', + 'error' => 'invalid_backend_name', + 'constraint' => '[a-z_0-9]', + 'name' => $name, + ], ); continue; } @@ -668,7 +700,11 @@ public function createIdentities(IdentityProvisionRequest $request, array $ident if (false === $token) { $this->logger->error( message: "Failed to generate access token for '{identity.name}@{identity.backend}' backend.", - context: ['identity' => ['name' => $identityName, 'backend' => $name]], + context: [ + 'operation' => 'identity.access_token', + 'error' => 'token_generation_failed', + 'identity' => ['name' => $identityName, 'backend' => $name], + ], ); } else { $perIdentity->set("{$name}.token", $token); @@ -679,6 +715,8 @@ public function createIdentities(IdentityProvisionRequest $request, array $ident $this->logger->error( message: "Failed to generate access token for '{identity.name}@{name}' backend. {exception.message}", context: [ + 'operation' => 'identity.access_token', + 'error' => 'token_generation_failed', 'name' => $name, 'identity' => ['name' => $identityName], ...exception_log($e), @@ -950,6 +988,8 @@ public function generateIdentitiesList(array $users, array $map = []): array } $this->logger->error("No partial fallback match via map for '{identity.backend}: {identity.user}'", [ + 'operation' => 'identity.match', + 'error' => 'no_partial_fallback', 'identity' => [ 'backend' => $userObj['backend'], 'user' => $userObj['name'], @@ -982,6 +1022,8 @@ public function generateIdentitiesList(array $users, array $map = []): array } $this->logger->error("No other users were found that match '{identity.backend}: {identity.user}{real_name}'.", [ + 'operation' => 'identity.match', + 'error' => 'no_user_match', 'identity' => [ 'backend' => $userObj['backend'], 'user' => $userObj['name'], @@ -1054,6 +1096,8 @@ public function mapActions(string $backend, array &$user, array &$mapping): void if (null === ($username = ag($user, 'name'))) { $this->logger->error("No username was given from one user of '{identity.backend}' backend.", [ + 'operation' => 'identity.match', + 'error' => 'missing_username', 'identity' => [ 'backend' => $backend, ], @@ -1118,6 +1162,9 @@ public function mapActions(string $backend, array &$user, array &$mapping): void $this->logger->error( message: "Failed to replace '{identity.backend}: {username}' with '{identity.backend}: {new_username}' name must be in [a-z_0-9] format.", context: [ + 'operation' => 'identity.rename', + 'error' => 'invalid_replacement_name', + 'constraint' => '[a-z_0-9]', 'identity' => [ 'backend' => $backend, ], diff --git a/src/Libs/Initializer.php b/src/Libs/Initializer.php index ca22dc1e..495c6a79 100644 --- a/src/Libs/Initializer.php +++ b/src/Libs/Initializer.php @@ -145,7 +145,7 @@ public function boot(): self set_exception_handler(static function (Throwable $e) use ($logger) { $logger->error( - message: '{exception.type}: {exception.message} ({exception.file}:{exception.line}).' . PHP_EOL, + message: 'Uncaught exception. {exception.message}', context: exception_log($e), ); exit(1); @@ -160,7 +160,7 @@ public function boot(): self $type = $error['type'] ?? 0; - $logger->error(message: "{exception.type}: {exception.message} at '{exception.file}:{exception.line}'. '{request.uri}'", context: [ + $logger->error(message: 'Fatal error. {exception.message}', context: [ 'exception' => [ 'type' => match ($type) { E_ERROR => 'E_ERROR', diff --git a/src/Libs/Mappers/Import/DirectMapper.php b/src/Libs/Mappers/Import/DirectMapper.php index 1e61b7ed..28627b2b 100644 --- a/src/Libs/Mappers/Import/DirectMapper.php +++ b/src/Libs/Mappers/Import/DirectMapper.php @@ -244,6 +244,8 @@ private function addNewItem(iState $entity, array $opts = []): self "[N] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', not found locally and backend set as metadata source only.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.new', + 'error' => 'metadata_source_only', 'metaOnly' => true, 'history' => [ 'id' => $entity->id ?? 'New', @@ -521,6 +523,8 @@ private function handleTainted(iState $local, iState $entity, array $opts = []): "[T] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', reported '{state}' vs local '{local_state}', state change ignored due to '{reasons}'.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.transition', + 'error' => 'state_change_ignored', 'history' => [ 'id' => $local->id ?? 'New', 'title' => $entity->getName(), @@ -766,15 +770,20 @@ private function handleOldEntity(iState $local, iState $entity, array $opts = [] $enable = Config::get('clients.jellyfin.fix_played', false); if ($enable && $entity->isWatched() && true === $entity->getContext('should_mark', false)) { $this->logger->notice( - "[O] '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}' date '{remote_date}' is older than last sync date '{local_date}'. Jellyfin API bug workaround applied to mark as played.", + "[O] '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}' date '{comparison.remote_date}' is older than last sync date '{comparison.local_date}'. Jellyfin API bug workaround applied to mark as played.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.old_entity', + 'error' => 'jellyfin_played_bug', 'history' => [ 'id' => $cloned->id ?? 'New', 'title' => $entity->getName(), ], - 'remote_date' => make_date($entity->updated), - 'local_date' => make_date($opts[Options::AFTER]), + 'comparison' => [ + 'remote_date' => make_date($entity->updated), + 'local_date' => make_date($opts[Options::AFTER]), + 'delta_seconds' => $opts[Options::AFTER]->getTimestamp() - $entity->updated, + ], 'identity' => [ 'user' => $this->userContext->name ?? 'main', 'backend' => $entity->via, @@ -789,15 +798,20 @@ private function handleOldEntity(iState $local, iState $entity, array $opts = [] } $this->logger->notice( - "[CODE:DM001] [O] '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}' date '{remote_date}' is older than last sync date '{local_date}'. Queueing for re-processing. Check FAQ.", + "[O] '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}' date '{comparison.remote_date}' is older than last sync date '{comparison.local_date}'. Queueing for re-processing. Check FAQ.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.old_entity', + 'error' => 'dm001_stale_date', 'history' => [ 'id' => $cloned->id ?? 'New', 'title' => $entity->getName(), ], - 'remote_date' => make_date($entity->updated), - 'local_date' => make_date($opts[Options::AFTER]), + 'comparison' => [ + 'remote_date' => make_date($entity->updated), + 'local_date' => make_date($opts[Options::AFTER]), + 'delta_seconds' => $opts[Options::AFTER]->getTimestamp() - $entity->updated, + ], 'state' => $entity->isWatched() ? 'played' : 'unplayed', 'local_state' => $local->isWatched() ? 'played' : 'unplayed', 'identity' => [ @@ -857,6 +871,8 @@ public function add(iState $entity, array $opts = []): self "[A] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', no external guids.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.add', + 'error' => 'no_external_guids', 'history' => [ 'id' => $entity->id ?? 'New', 'title' => $entity->getName(), @@ -876,6 +892,8 @@ public function add(iState $entity, array $opts = []): self "[A] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', marked as episode but no episode number.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.add', + 'error' => 'no_episode_number', 'history' => [ 'id' => $entity->id ?? ag($entity->getMetadata($entity->via), iState::COLUMN_ID, '??'), 'title' => $entity->getName(), diff --git a/src/Libs/Mappers/Import/MemoryMapper.php b/src/Libs/Mappers/Import/MemoryMapper.php index d289eeb7..0bb857cf 100644 --- a/src/Libs/Mappers/Import/MemoryMapper.php +++ b/src/Libs/Mappers/Import/MemoryMapper.php @@ -198,6 +198,8 @@ protected function addNewItem(iState $entity, array $opts = []): self "[N] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', not found locally and backend set as metadata source only.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.new', + 'error' => 'metadata_source_only', 'metaOnly' => true, 'history' => [ 'id' => $entity->id ?? 'New', @@ -320,6 +322,8 @@ protected function handleTainted(string|int $pointer, iState $cloned, iState $en "[T] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', reported '{state}' vs local '{local_state}', state change ignored due to '{reasons}'.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.transition', + 'error' => 'state_change_ignored', 'history' => [ 'id' => $this->objects[$pointer]->id ?? 'New', 'title' => $entity->getName(), @@ -473,15 +477,20 @@ protected function handleOldEntity(string|int $pointer, iState $cloned, iState $ if ($entity->isWatched() !== $this->objects[$pointer]->isWatched()) { if ($this->inTraceMode()) { $this->logger->debug( - "[O] '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}' is marked as '{state}' vs local '{local_state}', however due to the remote item date '{remote_date}' being older than the last backend sync date '{local_date}'. it was not considered as valid state.", + "[O] '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}' is marked as '{state}' vs local '{local_state}', however due to the remote item date '{comparison.remote_date}' being older than the last backend sync date '{comparison.local_date}'. it was not considered as valid state.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.old_entity', + 'error' => 'stale_remote_date', 'history' => [ 'id' => $this->objects[$pointer]->id ?? 'New', 'title' => $entity->getName(), ], - 'remote_date' => make_date($entity->updated), - 'local_date' => make_date($opts['after']), + 'comparison' => [ + 'remote_date' => make_date($entity->updated), + 'local_date' => make_date($opts['after']), + 'delta_seconds' => $opts['after']->getTimestamp() - $entity->updated, + ], 'state' => $entity->isWatched() ? 'played' : 'unplayed', 'local_state' => $this->objects[$pointer]->isWatched() ? 'played' : 'unplayed', 'identity' => [ @@ -521,6 +530,8 @@ public function add(iState $entity, array $opts = []): self "[O] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', no external guids.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.add', + 'error' => 'no_external_guids', 'history' => [ 'id' => $entity->id ?? 'New', 'title' => $entity->getName(), @@ -540,6 +551,8 @@ public function add(iState $entity, array $opts = []): self "[N] Ignoring '#{history.id}: {history.title}' by '{identity.user}@{identity.backend}', marked as episode but no episode number.", [ 'mapper' => after_last(self::class, '\\'), + 'operation' => 'mapper.add', + 'error' => 'no_episode_number', 'history' => [ 'id' => $entity->id ?? ag($entity->getMetadata($entity->via), iState::COLUMN_ID, '??'), 'title' => $entity->getName(), diff --git a/src/Libs/Playlists/PlaylistSyncService.php b/src/Libs/Playlists/PlaylistSyncService.php index 59bc5158..6206431c 100644 --- a/src/Libs/Playlists/PlaylistSyncService.php +++ b/src/Libs/Playlists/PlaylistSyncService.php @@ -43,6 +43,7 @@ public function sync(UserContext $userContext, array $clients, array $opts = []) $fetchTotals = $this->makeFetchStats(); $this->logger->notice("Starting playlist reconciliation for '{identity.user}' across '{total}' backend clients.", [ + 'operation' => 'playlist.reconcile', 'identity' => ['user' => $userContext->name], 'total' => count($clients), 'dry_run' => $dryRun, @@ -215,6 +216,7 @@ public function sync(UserContext $userContext, array $clients, array $opts = []) $summary = $this->summarizeBackends($clients, $store, $results, $syncStats, false); $this->logger->notice("Playlist reconciliation for '{identity.user}' completed in '{duration}'s.", [ + 'operation' => 'playlist.reconcile', 'identity' => ['user' => $userContext->name], 'duration' => round(microtime(true) - $syncStart, 4), 'results' => $this->summarizeResultTotals($summary), @@ -496,11 +498,13 @@ private function resolvePlaylistItem(iClient $client, UserContext $userContext, $entity = $client->toEntity($item, [Options::NO_CACHE => true]); } catch (Throwable $e) { $this->logger->warning( - "Failed to map '{identity.backend}' playlist item '{title}'. {error}", + "Failed to map '{identity.backend}' playlist item '{title}'. {exception.message}", [ + 'operation' => 'playlist.fetch', + 'error' => 'item_map_failed', 'identity' => ['backend' => $client->getName()], 'title' => ag($item, ['title', 'Name', 'OriginalTitle'], 'unknown'), - 'error' => $e->getMessage(), + ...exception_log($e), ], ); @@ -777,7 +781,11 @@ private function applySyncOperations(array $clients, PlaylistStore $store, array if ('' === $createdId) { $this->logger->warning( "Backend '{identity.backend}' create request completed without a playlist id.", - ['identity' => ['backend' => $backendName]], + [ + 'operation' => 'playlist.apply', + 'error' => 'missing_playlist_id', + 'identity' => ['backend' => $backendName], + ], ); $failedBackends[$backendName] = true; continue; @@ -1475,6 +1483,8 @@ private function logBackendThrowable(Throwable $e, string $backendName, string $ $this->logger->error( "Failed to {action} for '{identity.backend}'. {exception.message}", [ + 'operation' => 'playlist.apply', + 'error' => 'action_failed', 'action' => $action, 'identity' => ['backend' => $backendName], ...exception_log($e), diff --git a/src/Libs/TestCase.php b/src/Libs/TestCase.php index 4b210edf..24c989f8 100644 --- a/src/Libs/TestCase.php +++ b/src/Libs/TestCase.php @@ -15,6 +15,7 @@ use Closure; use Monolog\Handler\NullHandler; use Monolog\Handler\TestHandler; +use Monolog\Level; use Monolog\Logger; use PDO; use Psr\Log\LoggerInterface; @@ -64,6 +65,85 @@ protected function initTempDir(): void } } + /** + * Assert that at least one log record in the handler matches the given level and context filters. + * + * Structured context fields (e.g. 'operation', 'error') are the stable contract for log assertions. + * Prefer this over substring matching on message text, which is fragile under prose refactors. + * + * @param Level $level Expected log level. + * @param array $context Key/value pairs that must be present in the record context. + * @param bool $clear Whether to clear the handler after checking. + * + * @return bool True if a matching record was found. + */ + protected function loggedWith(Level $level, array $context = [], bool $clear = false): bool + { + if (null === $this->handler) { + return false; + } + + try { + foreach ($this->handler->getRecords() as $record) { + if ($level !== $record->level) { + continue; + } + + $match = true; + foreach ($context as $key => $value) { + if (ag($record->context, $key) === $value) { + continue; + } + $match = false; + break; + } + + if (true === $match) { + return true; + } + } + + return false; + } finally { + if (true === $clear) { + $this->handler->clear(); + } + } + } + + /** + * Static variant of loggedWith() for tests that use a local TestHandler instead of $this->handler. + * + * @param TestHandler $handler The handler to inspect. + * @param Level $level Expected log level. + * @param array $context Key/value pairs that must be present in the record context. + * + * @return bool True if a matching record was found. + */ + protected static function hasRecordWith(TestHandler $handler, Level $level, array $context = []): bool + { + foreach ($handler->getRecords() as $record) { + if ($level !== $record->level) { + continue; + } + + $match = true; + foreach ($context as $key => $value) { + if (ag($record->context, $key) === $value) { + continue; + } + $match = false; + break; + } + + if (true === $match) { + return true; + } + } + + return false; + } + protected function initTempApp(?string $path = null): string { $this->initTempDir(); diff --git a/src/Libs/Utils.php b/src/Libs/Utils.php index e1f8ca99..a95741cf 100644 --- a/src/Libs/Utils.php +++ b/src/Libs/Utils.php @@ -784,7 +784,13 @@ function register_events(bool $ignoreCache = false): void $dispatcher->addListener(ag($event, 'on'), ag($event, 'callable')); } } catch (Throwable $e) { - $logger->error($e->getMessage(), []); + $logger->error( + 'Failed to register event listener. {exception.message}', + [ + 'operation' => 'events.register_listener', + ...exception_log($e), + ], + ); } } @@ -1579,6 +1585,8 @@ function get_user_context(string $user, iImport $mapper, iLogger $logger): UserC $users = get_users(includeMain: true); if (false === in_array($user, $users, true)) { $logger->error("User '{identity.user}' not found.", [ + 'operation' => 'user_context.resolve', + 'error' => 'user_not_found', 'identity' => ['user' => $user], 'users' => $users, ]); diff --git a/src/Libs/helpers.php b/src/Libs/helpers.php index 3f2a5ebb..3332ed3e 100644 --- a/src/Libs/helpers.php +++ b/src/Libs/helpers.php @@ -572,6 +572,8 @@ function queue_push(iState $entity, bool $remove = false, ?UserContext $userCont if (!$entity->id) { $logger->error("Unable to push event '{identity.backend}: {entity}'. It has no local id yet.", [ + 'operation' => 'queue.push', + 'error' => 'no_local_id', 'identity' => ['backend' => $entity->via], 'entity' => $entity->getName(), ]); @@ -590,6 +592,8 @@ function queue_push(iState $entity, bool $remove = false, ?UserContext $userCont if (!$entity->hasGuids() && !$entity->hasRelativeGuid()) { $logger->error("Unable to push '{id}' event '{identity.backend}: {entity}'. It has no GUIDs.", [ + 'operation' => 'queue.push', + 'error' => 'no_guids', 'id' => $entity->id, 'identity' => ['backend' => $entity->via], 'entity' => $entity->getName(), diff --git a/src/Listeners/ProcessProgressEvent.php b/src/Listeners/ProcessProgressEvent.php index 74a3960c..50b274d6 100644 --- a/src/Listeners/ProcessProgressEvent.php +++ b/src/Listeners/ProcessProgressEvent.php @@ -139,6 +139,8 @@ public function __invoke(DataEvent $event): DataEvent if (!isset($supported[$type])) { $writer(Level::Error, "Ignoring '{identity.user}@{identity.backend}'. Invalid type '{type}'.", [ + 'operation' => 'webhook.backend_config', + 'error' => 'unexpected_backend_type', 'type' => $type, 'condition' => [ 'expected' => implode(', ', array_keys($supported)), @@ -154,6 +156,8 @@ public function __invoke(DataEvent $event): DataEvent if (null === ($url = ag($backend, 'url')) || false === is_valid_url($url)) { $writer(Level::Error, "Ignoring '{identity.user}@{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'webhook.backend_config', + 'error' => 'invalid_url', 'url' => $url ?? 'None', 'identity' => [ 'backend' => $backendName, @@ -285,7 +289,7 @@ public function __invoke(DataEvent $event): DataEvent if (false === in_array(Status::tryFrom($statusCode), [Status::OK, Status::NO_CONTENT], true)) { $writer( Level::Error, - "Request to change '{identity.user}@{identity.backend}' - '#{id}: {history.title}' watch progress returned with unexpected '{response.status_code}' status code.", + "Request to change '{identity.user}@{identity.backend}' - '#{id}: {history.title}' watch progress returned HTTP {response.status_code}.", [ ...$context, 'response' => ['status_code' => $statusCode], diff --git a/src/Listeners/ProcessPushEvent.php b/src/Listeners/ProcessPushEvent.php index 0b26e74b..ea523367 100644 --- a/src/Listeners/ProcessPushEvent.php +++ b/src/Listeners/ProcessPushEvent.php @@ -104,6 +104,8 @@ public function __invoke(DataEvent $e): DataEvent if (!isset($supported[$type])) { $writer(Level::Error, "Ignoring '{identity.user}@{identity.backend}'. Invalid type '{type}'.", [ + 'operation' => 'webhook.backend_config', + 'error' => 'unexpected_backend_type', 'type' => $type, 'identity' => [ 'user' => $user, @@ -119,6 +121,8 @@ public function __invoke(DataEvent $e): DataEvent if (null === ($url = ag($backend, 'url')) || false === is_valid_url($url)) { $writer(Level::Error, "Ignoring '{identity.user}@{identity.backend}'. Invalid URL '{url}'.", [ + 'operation' => 'webhook.backend_config', + 'error' => 'invalid_url', 'url' => $url ?? 'None', 'identity' => [ 'user' => $user, @@ -219,7 +223,7 @@ public function __invoke(DataEvent $e): DataEvent if (Status::OK !== Status::tryFrom($context['response']['status_code'])) { $writer( Level::Error, - "Request to change '{identity.user}@{identity.backend}' - '#{history.id}: {history.title}' play state returned with unexpected '{response.status_code}' status code.", + "Request to change '{identity.user}@{identity.backend}' - '#{history.id}: {history.title}' play state returned HTTP {response.status_code}.", $context, ); diff --git a/tests/Backends/Emby/EmbyGuidTest.php b/tests/Backends/Emby/EmbyGuidTest.php index 501bbff6..2775250a 100644 --- a/tests/Backends/Emby/EmbyGuidTest.php +++ b/tests/Backends/Emby/EmbyGuidTest.php @@ -26,31 +26,6 @@ class EmbyGuidTest extends TestCase { protected ?Logger $logger = null; - private function logged(Level $level, string $message, bool $clear = false): bool - { - try { - foreach ($this->handler->getRecords() as $record) { - if ($level !== $record->level) { - continue; - } - - if (null !== $record->formatted && true === str_contains($record->formatted, $message)) { - return true; - } - - if (true === str_contains($record->message, $message)) { - return true; - } - } - - return false; - } finally { - if (true === $clear) { - $this->handler->clear(); - } - } - } - private function getClass(): EmbyGuid { $this->handler->clear(); @@ -91,7 +66,7 @@ public function test__construct() Config::save('guid.file', $tmpFile); $this->getClass(); $this->assertTrue( - $this->logged(Level::Error, 'Failed to parse GUIDs file', true), + $this->loggedWith(Level::Error, ['operation' => 'guid.load_file', 'error' => 'file_parse_failed'], true), 'Assert message logged when the value type does not match the expected type.', ); } finally { @@ -147,7 +122,7 @@ public function test_parseGUIDFile() touch($tmpFile); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Info, 'is empty', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.load_file'], true), 'Failed to assert that the GUID file is empty.', ); @@ -172,7 +147,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump(ag_set($yaml, 'links.0', 'ff'))); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'Value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_not_object'], true), 'Assert links.0 key is an object.', ); @@ -183,7 +158,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_map_not_object'], true), 'Assert map key is an object.', ); @@ -191,7 +166,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.from field is empty or not a string.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_from_missing'], true), 'Assert to field is a string.', ); @@ -199,7 +174,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.to field is empty or not a string.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_missing'], true), 'Assert to field is a string.', ); @@ -207,7 +182,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'field does not starts with', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_guid'], true), 'Assert to field is a string.', ); @@ -215,7 +190,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.to field is not a supported', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_supported'], true), 'Assert to field is a string.', ); @@ -382,7 +357,7 @@ public function test_get_ignore() ); $this->assertTrue( - $this->logged(Level::Debug, 'EmbyGuid: Ignoring', true), + $this->loggedWith(Level::Debug, ['operation' => 'guid.parse', 'error' => 'ignored_by_user'], true), 'Assert that a log is raised when the GUID is ignored by user choice.', ); } diff --git a/tests/Backends/Jellyfin/JellyfinGuidTest.php b/tests/Backends/Jellyfin/JellyfinGuidTest.php index 6e4766af..d6d45122 100644 --- a/tests/Backends/Jellyfin/JellyfinGuidTest.php +++ b/tests/Backends/Jellyfin/JellyfinGuidTest.php @@ -26,31 +26,6 @@ class JellyfinGuidTest extends TestCase { protected ?Logger $logger = null; - private function logged(Level $level, string $message, bool $clear = false): bool - { - try { - foreach ($this->handler->getRecords() as $record) { - if ($level !== $record->level) { - continue; - } - - if (null !== $record->formatted && true === str_contains($record->formatted, $message)) { - return true; - } - - if (true === str_contains($record->message, $message)) { - return true; - } - } - - return false; - } finally { - if (true === $clear) { - $this->handler->clear(); - } - } - } - private function getClass(): JellyfinGuid { $this->handler->clear(); @@ -91,7 +66,7 @@ public function test__construct() Config::save('guid.file', $tmpFile); $this->getClass(); $this->assertTrue( - $this->logged(Level::Error, 'Failed to parse GUIDs file', true), + $this->loggedWith(Level::Error, ['operation' => 'guid.load_file', 'error' => 'file_parse_failed'], true), 'Assert message logged when the value type does not match the expected type.', ); } finally { @@ -147,7 +122,7 @@ public function test_parseGUIDFile() touch($tmpFile); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Info, 'is empty', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.load_file'], true), 'Failed to assert that the GUID file is empty.', ); @@ -172,7 +147,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump(ag_set($yaml, 'links.0', 'ff'))); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'Value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_not_object'], true), 'Assert replace key is an object.', ); @@ -183,7 +158,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_map_not_object'], true), 'Assert map key is an object.', ); @@ -191,7 +166,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.from field is empty or not a string.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_from_missing'], true), 'Assert to field is a string.', ); @@ -199,7 +174,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.to field is empty or not a string.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_missing'], true), 'Assert to field is a string.', ); @@ -207,7 +182,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'field does not starts with', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_guid'], true), 'Assert to field is a string.', ); @@ -215,7 +190,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.to field is not a supported', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_supported'], true), 'Assert to field is a string.', ); @@ -386,7 +361,7 @@ public function test_get_ignore() ); $this->assertTrue( - $this->logged(Level::Debug, 'JellyfinGuid: Ignoring', true), + $this->loggedWith(Level::Debug, ['operation' => 'guid.parse', 'error' => 'ignored_by_user'], true), 'Assert that a log is raised when the GUID is ignored by user choice.', ); } diff --git a/tests/Backends/Plex/GetLibrariesListTest.php b/tests/Backends/Plex/GetLibrariesListTest.php index 9f61885d..818a424c 100644 --- a/tests/Backends/Plex/GetLibrariesListTest.php +++ b/tests/Backends/Plex/GetLibrariesListTest.php @@ -144,7 +144,7 @@ public function test_401_invalid_token(): void $this->assertFalse($response->status); $this->assertNotNull($response->error); $this->assertStringContainsString( - "libraries returned with unexpected '401' status code", + 'libraries returned HTTP 401', (string) $response->error, ); diff --git a/tests/Backends/Plex/PlexGuidTest.php b/tests/Backends/Plex/PlexGuidTest.php index 137bbc2e..d314ba7e 100644 --- a/tests/Backends/Plex/PlexGuidTest.php +++ b/tests/Backends/Plex/PlexGuidTest.php @@ -26,31 +26,6 @@ class PlexGuidTest extends TestCase { protected ?Logger $logger = null; - private function logged(Level $level, string $message, bool $clear = false): bool - { - try { - foreach ($this->handler->getRecords() as $record) { - if ($level !== $record->level) { - continue; - } - - if (null !== $record->formatted && true === str_contains($record->formatted, $message)) { - return true; - } - - if (true === str_contains($record->message, $message)) { - return true; - } - } - - return false; - } finally { - if (true === $clear) { - $this->handler->clear(); - } - } - } - private function getClass(): PlexGuid { $this->handler->clear(); @@ -91,7 +66,7 @@ public function test__construct() Config::save('guid.file', $tmpFile); $this->getClass(); $this->assertTrue( - $this->logged(Level::Error, 'Failed to parse GUIDs file', true), + $this->loggedWith(Level::Error, ['operation' => 'guid.load_file', 'error' => 'file_parse_failed'], true), 'Assert message logged when the value type does not match the expected type.', ); } finally { @@ -147,7 +122,7 @@ public function test_parseGUIDFile() touch($tmpFile); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Info, 'is empty', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.load_file'], true), 'Failed to assert that the GUID file is empty.', ); @@ -173,7 +148,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump(ag_set($yaml, 'links.0', 'ff'))); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'Value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_not_object'], true), 'Assert link value is an object.', ); @@ -181,7 +156,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'replace value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_replace_not_object'], true), 'Assert replace key is an object.', ); @@ -189,15 +164,15 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'options.replace.from field is empty or not a string.', true), - 'Assert to field is a string.', + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_from_missing'], true), + 'Assert from field is a string.', ); $yaml = ag_set($yaml, 'links.0.options.replace.from', 'foo'); file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'options.replace.to field is not a string.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_string'], true), 'Assert to field is a string.', ); @@ -213,7 +188,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map value must be an object.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_map_not_object'], true), 'Assert map key is an object.', ); @@ -221,15 +196,15 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.from field is empty or not a string.', true), - 'Assert to field is a string.', + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_from_missing'], true), + 'Assert from field is a string.', ); $yaml = ag_set($yaml, 'links.0.map.from', 'foo'); file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.to field is empty or not a string.', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_missing'], true), 'Assert to field is a string.', ); @@ -237,16 +212,16 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'field does not starts with', true), - 'Assert to field is a string.', + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_guid'], true), + 'Assert to field starts with guid_.', ); $yaml = ag_set($yaml, 'links.0.map.to', 'guid_foobar'); file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.to field is not a supported', true), - 'Assert to field is a string.', + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_to_not_supported'], true), + 'Assert to field is a supported GUID type.', ); $yaml = ag_set($yaml, 'links.0.map', [ @@ -256,8 +231,8 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); $this->getClass()->parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'map.from already exists.', true), - 'Assert to field is a string.', + $this->loggedWith(Level::Warning, ['operation' => 'guid.link_map', 'error' => 'link_from_duplicate'], true), + 'Assert from field already exists.', ); $yaml = ag_set($yaml, 'links.0.map', [ @@ -400,7 +375,7 @@ public function test_get() ); $this->assertTrue( - $this->logged(Level::Info, 'Unable to parse', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.parse', 'error' => 'unparseable_identifier'], true), 'Assert that the invalid GUID is logged.', ); $this->assertEquals( @@ -418,7 +393,7 @@ public function test_get() ); $this->assertTrue( - $this->logged(Level::Info, 'reported conflicting', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.parse', 'error' => 'conflicting_ids'], true), 'Assert that a log is raised when multiple GUIDs for the same provider are found.', ); @@ -441,7 +416,7 @@ public function test_get() ); $this->assertFalse( - $this->logged(Level::Warning, 'reported multiple ids', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.parse', 'error' => 'conflicting_ids'], true), 'Assert identical canonical and NFO GUIDs do not raise duplicate warnings.', ); @@ -473,7 +448,7 @@ public function test_get() ); $this->assertTrue( - $this->logged(Level::Debug, 'Ignoring', true), + $this->loggedWith(Level::Debug, ['operation' => 'guid.parse', 'error' => 'ignored_by_user'], true), 'Assert that a log is raised when the GUID is ignored by user choice.', ); } diff --git a/tests/Commands/State/ExportCommandTest.php b/tests/Commands/State/ExportCommandTest.php index d59433a8..3c4a9fd2 100644 --- a/tests/Commands/State/ExportCommandTest.php +++ b/tests/Commands/State/ExportCommandTest.php @@ -13,6 +13,7 @@ use App\Libs\QueueRequests; use App\Libs\TestCase; use Monolog\Handler\TestHandler; +use Monolog\Level; use Monolog\Logger; use Symfony\Component\Console\Application; use Symfony\Component\Console\Input\InputOption; @@ -90,7 +91,14 @@ public function test_invalid_user_returns_failure(): void ]); self::assertSame(ExportCommand::FAILURE, $status); - self::assertTrue($handler->hasErrorThatContains("User 'ghost' not found.")); + self::assertTrue( + $this->hasRecordWith( + $handler, + Level::Error, + ['operation' => 'export.resolve_users'], + ), + 'Assert resolve-users error logged with operation token.', + ); } public function test_matching_backend_uses_push(): void diff --git a/tests/Commands/State/PlaylistCommandTest.php b/tests/Commands/State/PlaylistCommandTest.php index 3b5f031b..b687951a 100644 --- a/tests/Commands/State/PlaylistCommandTest.php +++ b/tests/Commands/State/PlaylistCommandTest.php @@ -12,6 +12,7 @@ use App\Libs\TestCase; use App\Libs\UserContext; use Monolog\Handler\TestHandler; +use Monolog\Level; use Monolog\Logger; use PHPUnit\Framework\MockObject\MockObject; use Symfony\Component\Cache\Adapter\ArrayAdapter; @@ -202,7 +203,14 @@ public function test_invalid_user(): void ]); self::assertSame(PlaylistCommand::FAILURE, $status); - self::assertTrue($handler->hasErrorThatContains("User 'ghost' not found.")); + self::assertTrue( + $this->hasRecordWith( + $handler, + Level::Error, + ['operation' => 'playlist.resolve_users'], + ), + 'Assert resolve-users error logged with operation token.', + ); } /** diff --git a/tests/Commands/State/ValidateCommandTest.php b/tests/Commands/State/ValidateCommandTest.php index e241e096..1c43d656 100644 --- a/tests/Commands/State/ValidateCommandTest.php +++ b/tests/Commands/State/ValidateCommandTest.php @@ -10,6 +10,7 @@ use App\Libs\Mappers\ImportInterface as iImport; use App\Libs\TestCase; use Monolog\Handler\TestHandler; +use Monolog\Level; use Monolog\Logger; use Symfony\Component\Console\Application; use Symfony\Component\Console\Tester\CommandTester; @@ -71,7 +72,14 @@ public function test_invalid_user_returns_failure(): void ]); self::assertSame(ValidateCommand::FAILURE, $status); - self::assertTrue($handler->hasErrorThatContains("User 'ghost' not found.")); + self::assertTrue( + $this->hasRecordWith( + $handler, + Level::Error, + ['operation' => 'validate.resolve_users'], + ), + 'Assert resolve-users error logged with operation token.', + ); } public function test_selected_user_db_only(): void diff --git a/tests/Libs/GuidTest.php b/tests/Libs/GuidTest.php index e985f2af..d7a5c891 100644 --- a/tests/Libs/GuidTest.php +++ b/tests/Libs/GuidTest.php @@ -20,31 +20,6 @@ class GuidTest extends TestCase { protected ?Logger $logger = null; - private function logged(Level $level, string $message, bool $clear = false): bool - { - try { - foreach ($this->handler->getRecords() as $record) { - if ($level !== $record->level) { - continue; - } - - if (null !== $record->formatted && true === str_contains($record->formatted, $message)) { - return true; - } - - if (true === str_contains($record->message, $message)) { - return true; - } - } - - return false; - } finally { - if (true === $clear) { - $this->handler->clear(); - } - } - } - protected function setUp(): void { parent::setUp(); @@ -68,13 +43,13 @@ public function test__construct() Guid::fromArray(['guid_tvdb' => INF], logger: $this->logger); $this->assertTrue( - $this->logged(Level::Info, 'external id. Unexpected value type.', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.validate', 'error' => 'unexpected_value_type'], true), 'Assert message logged when the value type does not match the expected type.', ); Guid::fromArray(['guid_tvdb' => 'tt1234567']); $this->assertTrue( - $this->logged(Level::Info, "external id. Unexpected value '", true), + $this->loggedWith(Level::Info, ['operation' => 'guid.validate', 'error' => 'unexpected_value'], true), 'Assert message logged when the value does not match the expected pattern.', ); } @@ -190,7 +165,7 @@ public function test_parseGUIDFile() touch($tmpFile); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Info, 'is empty', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.load_file'], true), 'Failed to assert that the GUID file is empty.', ); @@ -209,21 +184,21 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump(['guids' => ['guid_imdb' => 'tt1234567']])); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'Value must be an object', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_not_object'], true), 'Assert that GUID key is an array.', ); file_put_contents($tmpFile, Yaml::dump(['guids' => [['name' => 'imdb']]])); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, "name must start with 'guid_'", true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_name_invalid'], true), 'Assert that GUID name starts with guid_', ); file_put_contents($tmpFile, Yaml::dump(['guids' => [['name' => 'guid_imdb', 'type' => INF]]])); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'type must be a string', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_type_not_string'], true), 'Assert guid type is string.', ); @@ -241,7 +216,7 @@ public function test_parseGUIDFile() Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator key must be an object', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_validator_not_object'], true), 'Assert validator key is an object.', ); @@ -249,7 +224,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator.pattern is empty or invalid', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_pattern_invalid'], true), 'Assert a message is logged when the pattern is invalid.', ); @@ -257,7 +232,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator.example is empty or not a string', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_example_missing'], true), 'Assert a message is logged when the example is empty or not a string.', ); @@ -265,7 +240,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator.tests key must be an object', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_tests_not_object'], true), 'Assert a message is logged when the test key is not an object.', ); @@ -273,7 +248,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator.tests.valid key must be an array', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_valid_tests_not_array'], true), 'Assert a message is logged when the test key is not an object.', ); @@ -281,7 +256,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'does not match pattern', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_valid_test_no_match'], true), 'Assert a message is logged when valid test does not match the pattern.', ); @@ -292,7 +267,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator.tests.invalid key must be an array', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_invalid_tests_not_array'], true), 'Assert a message is logged when invalid test is not an array.', ); @@ -303,7 +278,7 @@ public function test_parseGUIDFile() file_put_contents($tmpFile, Yaml::dump($yaml)); Guid::parseGUIDFile($tmpFile); $this->assertTrue( - $this->logged(Level::Warning, 'validator.tests.invalid value', true), + $this->loggedWith(Level::Warning, ['operation' => 'guid.definition', 'error' => 'def_invalid_test_matches'], true), 'Assert a message is logged when invalid test match the pattern.', ); @@ -338,7 +313,7 @@ public function test_reparse() Guid::reparse(); Guid::getSupported(); $this->assertTrue( - $this->logged(Level::Error, 'Failed to read or parse', true), + $this->loggedWith(Level::Error, ['operation' => 'guid.load_file', 'error' => 'file_parse_failed'], true), 'Failed to assert that the GUID file is empty.', ); } finally { @@ -398,7 +373,7 @@ public function test_guid_logger_from_container() Guid::setLogger($this->logger); Guid::fromArray(['guid_tvdb' => INF]); $this->assertTrue( - $this->logged(Level::Info, 'external id. Unexpected value type.', true), + $this->loggedWith(Level::Info, ['operation' => 'guid.validate', 'error' => 'unexpected_value_type'], true), 'Assert message logged when the value type does not match the expected type.', ); } From 69b66c11fa8f448818693169259efb70c1ed7425 Mon Sep 17 00:00:00 2001 From: arabcoders Date: Sun, 21 Jun 2026 21:52:27 +0300 Subject: [PATCH 2/9] chore: packages update --- composer.lock | 65 +-- frontend/app/components/LogDetailsModal.vue | 8 +- frontend/bun.lock | 468 +++++++++++--------- frontend/package.json | 20 +- 4 files changed, 314 insertions(+), 247 deletions(-) diff --git a/composer.lock b/composer.lock index e94ae988..d1a3a90a 100644 --- a/composer.lock +++ b/composer.lock @@ -3484,16 +3484,16 @@ }, { "name": "phpunit/phpunit", - "version": "13.2.0", + "version": "13.2.1", "source": { "type": "git", "url": "https://github.com/sebastianbergmann/phpunit.git", - "reference": "3796ea973f1e7698f0d432c1c66662af9764fd9a" + "reference": "60da0ff1e10a0f72ee18a24117ec3b613a346bba" }, "dist": { "type": "zip", - "url": "https://api.github.com/repos/sebastianbergmann/phpunit/zipball/3796ea973f1e7698f0d432c1c66662af9764fd9a", - "reference": "3796ea973f1e7698f0d432c1c66662af9764fd9a", + "url": "https://api.github.com/repos/sebastianbergmann/phpunit/zipball/60da0ff1e10a0f72ee18a24117ec3b613a346bba", + "reference": "60da0ff1e10a0f72ee18a24117ec3b613a346bba", "shasum": "" }, "require": { @@ -3507,7 +3507,7 @@ "phar-io/manifest": "^2.0.4", "phar-io/version": "^3.2.1", "php": ">=8.4.1", - "phpunit/php-code-coverage": "^14.2", + "phpunit/php-code-coverage": "^14.2.2", "phpunit/php-file-iterator": "^7.0.0", "phpunit/php-invoker": "^7.0.0", "phpunit/php-text-template": "^6.0.0", @@ -3564,7 +3564,7 @@ "support": { "issues": "https://github.com/sebastianbergmann/phpunit/issues", "security": "https://github.com/sebastianbergmann/phpunit/security/policy", - "source": "https://github.com/sebastianbergmann/phpunit/tree/13.2.0" + "source": "https://github.com/sebastianbergmann/phpunit/tree/13.2.1" }, "funding": [ { @@ -3572,7 +3572,7 @@ "type": "other" } ], - "time": "2026-06-05T03:13:07+00:00" + "time": "2026-06-15T13:14:22+00:00" }, { "name": "roave/security-advisories", @@ -3580,12 +3580,12 @@ "source": { "type": "git", "url": "https://github.com/Roave/SecurityAdvisories.git", - "reference": "810e1d8cfbc718df8dacf74b62b7b9a1780b9698" + "reference": "bfdbd26a02c71b3b00586f056c8cf5efea22a27a" }, "dist": { "type": "zip", - "url": "https://api.github.com/repos/Roave/SecurityAdvisories/zipball/810e1d8cfbc718df8dacf74b62b7b9a1780b9698", - "reference": "810e1d8cfbc718df8dacf74b62b7b9a1780b9698", + "url": "https://api.github.com/repos/Roave/SecurityAdvisories/zipball/bfdbd26a02c71b3b00586f056c8cf5efea22a27a", + "reference": "bfdbd26a02c71b3b00586f056c8cf5efea22a27a", "shasum": "" }, "conflict": { @@ -3686,13 +3686,14 @@ "bytefury/crater": "<6.0.2", "cachethq/cachet": "<2.5.1", "cadmium-org/cadmium-cms": "<=0.4.9", + "cakephp/authentication": "<3.3.6|>=4,<4.1.1", "cakephp/cakephp": "<3.10.3|>=4,<4.0.10|>=4.1,<4.1.4|>=4.2,<4.2.12|>=4.3,<4.3.11|>=4.4,<4.4.10|>=5.2.10,<5.2.12|==5.3", "cakephp/database": ">=4.2,<4.2.12|>=4.3,<4.3.11|>=4.4,<4.4.10", "cardgate/magento2": "<2.0.33", "cardgate/woocommerce": "<=3.1.15", - "cart2quote/module-quotation": ">=4.1.6,<=4.4.5|>=5,<5.4.4", + "cart2quote/module-quotation": ">=4.1.6,<4.4.6|>=5,<5.4.4", "cart2quote/module-quotation-encoded": ">=4.1.6,<=4.4.5|>=5,<5.4.4", - "cartalyst/sentry": "<=2.1.6", + "cartalyst/sentry": "<2.1.7", "catfan/medoo": "<1.7.5", "causal/oidc": "<4", "cecil/cecil": "<7.47.1", @@ -3730,12 +3731,13 @@ "coreshop/core-shop": "<4.1.9|==5", "corveda/phpsandbox": "<1.3.5", "cosenary/instagram": "<=2.3", + "cotonti/cotonti": "<=1", "couleurcitron/tarteaucitron-wp": "<0.3", "cpsit/typo3-mailqueue": "<0.4.5|>=0.5,<0.5.2", "craftcms/aws-s3": ">=2.0.2,<=2.2.4", "craftcms/azure-blob": ">=2.0.0.0-beta1,<=2.1", - "craftcms/cms": "<4.17.12|>=5,<5.9.18", - "craftcms/commerce": ">=4,<4.11|>=5,<5.6", + "craftcms/cms": "<4.18|>=5,<5.10", + "craftcms/commerce": ">=4,<=4.11.1|>=5,<=5.6.4", "craftcms/composer": ">=4.0.0.0-RC1-dev,<=4.10|>=5.0.0.0-RC1-dev,<=5.5.1", "craftcms/craft": ">=3.5,<=4.16.17|>=5.0.0.0-RC1-dev,<=5.8.21", "craftcms/google-cloud": ">=2.0.0.0-beta1,<=2.2", @@ -3790,7 +3792,7 @@ "drupal/commerce_alphabank_redirect": "<1.0.3", "drupal/commerce_eurobank_redirect": "<2.1.1", "drupal/config_split": "<1.10|>=2,<2.0.2", - "drupal/core": ">=6,<6.38|>=7,<7.103|>=8,<10.5.9|>=10.6,<10.6.7|>=11,<11.2.11|>=11.3,<11.3.7", + "drupal/core": ">=6,<6.38|>=7,<7.103|>=8,<10.5.10|>=10.6,<10.6.9|>=11,<11.2.12|>=11.3,<11.3.10", "drupal/core-recommended": ">=7,<7.102|>=8,<10.2.11|>=10.3,<10.3.9|>=11,<11.0.8", "drupal/currency": "<3.5", "drupal/drupal": ">=5,<5.11|>=6,<6.38|>=7,<7.102|>=8,<10.2.11|>=10.3,<10.3.9|>=11,<11.0.8", @@ -3863,6 +3865,7 @@ "fenom/fenom": "<=2.12.1", "filament/actions": ">=3.2,<3.2.123|>=4,<=4.11.3|>=5,<=5.6.3", "filament/filament": ">=4,<4.3.1", + "filament/forms": ">=3,<=3.3.52", "filament/infolists": ">=3,<3.2.115", "filament/tables": ">=3,<=3.3.50|>=4,<4.8.5|>=5,<5.3.5", "filegator/filegator": "<7.8", @@ -3910,10 +3913,10 @@ "georgringer/news": "<10.0.4|>=11,<11.4.4|>=12,<12.3.2|>=13,<13.0.2|>=14,<14.0.3", "geshi/geshi": "<=1.0.9.1", "getformwork/formwork": "<=2.3.3", - "getgrav/grav": "<=2.0.0.0-RC1", + "getgrav/grav": "<=2.0.0.0-RC8", "getgrav/grav-plugin-api": "<1.0.0.0-beta15", "getgrav/grav-plugin-form": "<9.1", - "getkirby/cms": "<=4.9|>=5,<=5.4", + "getkirby/cms": "<=4.9.3|>=5,<=5.4.3", "getkirby/kirby": "<3.9.8.3-dev|>=3.10,<3.10.1.2-dev|>=4,<4.7.1", "getkirby/panel": "<2.5.14", "getkirby/starterkit": "<=3.7.0.2", @@ -3930,10 +3933,10 @@ "gregwar/rst": "<1.0.3", "grumpydictator/firefly-iii": "<=6.6.2", "gugoan/economizzer": "<=0.9.0.0-beta1", - "guzzlehttp/guzzle": "<6.5.8|>=7,<7.4.5", + "guzzlehttp/guzzle": "<7.12.1", "guzzlehttp/guzzle-services": "<1.5.4", "guzzlehttp/oauth-subscriber": "<0.8.1", - "guzzlehttp/psr7": "<2.10.2", + "guzzlehttp/psr7": "<2.12.1", "haffner/jh_captcha": "<=2.1.3|>=3,<=3.0.2", "handcraftedinthealps/goodby-csv": "<1.4.3", "harvesthq/chosen": "<1.8.7", @@ -3988,6 +3991,7 @@ "jasig/phpcas": "<1.3.3", "jbartels/wec-map": "<3.0.3", "jcbrand/converse.js": "<3.3.3", + "jleehr/canto-saas-api": "<=2", "joedolson/my-calendar": "<3.7.7", "joelbutcher/socialstream": "<5.6|>=6,<6.2", "johnbillion/query-monitor": "<3.20.4", @@ -4031,7 +4035,7 @@ "lara-zeus/artemis": ">=1,<=1.0.6", "lara-zeus/dynamic-dashboard": ">=3,<=3.0.1", "laravel/fortify": "<1.11.1", - "laravel/framework": "<12.60|>=13,<13.10", + "laravel/framework": "<12.61.1|>=13,<13.12", "laravel/laravel": ">=5.4,<5.4.22", "laravel/passport": ">=13,<13.7.1", "laravel/pulse": "<1.3.1", @@ -4122,6 +4126,7 @@ "movim/moxl": ">=0.8,<=0.10", "movingbytes/social-network": "<=1.2.1", "mpdf/mpdf": "<=7.1.7", + "mtdowling/jmespath.php": "<2.9.1", "munkireport/comment": "<4", "munkireport/managedinstalls": "<2.6", "munkireport/munki_facts": "<1.5", @@ -4208,7 +4213,7 @@ "phenx/php-svg-lib": "<0.5.2", "php-censor/php-censor": "<2.0.13|>=2.1,<2.1.5", "php-mod/curl": "<2.3.2", - "phpbb/phpbb": "<3.3.11", + "phpbb/phpbb": "<3.3.16|==4.0.0.0-alpha1", "phpems/phpems": ">=6,<=6.1.3", "phpfastcache/phpfastcache": "<6.1.5|>=7,<7.1.2|>=8,<8.0.7", "phpmailer/phpmailer": "<6.5", @@ -4220,7 +4225,7 @@ "phpoffice/phpexcel": "<=1.8.2", "phpoffice/phpspreadsheet": "<=1.30.4|>=2,<=2.1.15|>=2.2,<=2.4.4|>=3,<=3.10.4|>=4,<=5.6", "phppgadmin/phppgadmin": "<=7.13", - "phpseclib/phpseclib": "<=2.0.53|>=3,<=3.0.51", + "phpseclib/phpseclib": "<=2.0.54|>=3,<=3.0.53", "phpservermon/phpservermon": "<3.6", "phpsysinfo/phpsysinfo": "<3.4.3", "phpunit/phpunit": "<8.5.52|>=9,<9.6.33|>=10,<10.5.62|>=11,<11.5.50|>=12,<12.5.8|>=12.5.21,<12.5.22|>=13.1.5,<13.1.6", @@ -4236,7 +4241,7 @@ "pimcore/demo": "<10.3", "pimcore/ecommerce-framework-bundle": "<1.0.10", "pimcore/perspective-editor": "<1.5.1", - "pimcore/pimcore": "<=12.3.6", + "pimcore/pimcore": "<=12.3.8", "pimcore/web2print-tools-bundle": "<=5.2.1|>=6.0.0.0-RC1-dev,<=6.1", "piwik/piwik": "<1.11", "pixelfed/pixelfed": "<0.12.5", @@ -4260,8 +4265,8 @@ "prestashop/ps_linklist": "<3.1", "privatebin/privatebin": "<1.4|>=1.5,<1.7.4|>=1.7.7,<2.0.3", "processwire/processwire": "<=3.0.255", - "propel/propel": ">=2.0.0.0-alpha1,<=2.0.0.0-alpha7", - "propel/propel1": ">=1,<=1.7.1", + "propel/propel": ">=2.0.0.0-alpha1,<2.0.0.0-alpha8", + "propel/propel1": ">=1,<1.7.2", "psy/psysh": "<=0.11.22|>=0.12,<=0.12.18", "pterodactyl/panel": "<1.12.3", "ptheofan/yii2-statemachine": ">=2.0.0.0-RC1-dev,<=2", @@ -4324,7 +4329,7 @@ "silverstripe/assets": "<2.4.5|>=3,<3.1.3", "silverstripe/cms": "<4.11.3", "silverstripe/comments": ">=1.3,<3.1.1", - "silverstripe/forum": "<=0.6.1|>=0.7,<=0.7.3", + "silverstripe/forum": "<0.6.2|>=0.7,<0.7.4", "silverstripe/framework": "<5.3.23", "silverstripe/graphql": ">=2,<2.0.5|>=3,<3.8.2|>=4,<4.3.7|>=5,<5.1.3", "silverstripe/hybridsessions": ">=1,<2.4.1|>=2.5,<2.5.1", @@ -4368,6 +4373,7 @@ "spencer14420/sp-php-email-handler": "<1", "spipu/html2pdf": "<5.2.8", "spiral/roadrunner": "<2025.1", + "spomky-labs/otphp": "<11.4.3", "spoon/library": "<1.4.1", "spoonity/tcpdf": "<6.2.22", "squizlabs/php_codesniffer": ">=1,<2.8.1|>=3,<3.0.1", @@ -4441,7 +4447,9 @@ "symfony/twig-bridge": ">=2,<4.4.51|>=5,<5.4.31|>=6,<6.3.8|>=6.4.24,<6.4.40", "symfony/twilio-notifier": ">=6.4,<6.4.40|>=7,<7.4.12|>=8,<8.0.12", "symfony/ux-autocomplete": "<2.36|>=3,<3.1", + "symfony/ux-icons": ">=2.17,<2.36.1|>=3,<3.2", "symfony/ux-live-component": "<2.36|>=3,<3.1", + "symfony/ux-toolkit": ">=2.32,<2.36.1|>=3,<3.2", "symfony/ux-twig-component": "<2.25.1", "symfony/validator": "<5.4.43|>=6,<6.4.11|>=7,<7.1.4", "symfony/var-exporter": ">=4.2,<4.2.12|>=4.3,<4.3.8", @@ -4543,6 +4551,9 @@ "web-auth/webauthn-lib": ">=4.5,<4.9|>=5.2,<5.2.4", "web-auth/webauthn-symfony-bundle": ">=5.2,<5.2.4", "web-feet/coastercms": "==5.5", + "web-token/jwt-experimental": "<=4.1.6", + "web-token/jwt-framework": "<=4.2.99", + "web-token/jwt-library": "<3.4.10|>=4,<4.0.7|>=4.1,<4.1.7", "web-tp3/wec_map": "<3.0.3", "webbuilders-group/silverstripe-kapost-bridge": "<0.4", "webcoast/deferred-image-processing": "<1.0.2", @@ -4668,7 +4679,7 @@ "type": "tidelift" } ], - "time": "2026-06-12T20:48:39+00:00" + "time": "2026-06-19T21:28:22+00:00" }, { "name": "sebastian/cli-parser", diff --git a/frontend/app/components/LogDetailsModal.vue b/frontend/app/components/LogDetailsModal.vue index 6c6de86e..c78dd723 100644 --- a/frontend/app/components/LogDetailsModal.vue +++ b/frontend/app/components/LogDetailsModal.vue @@ -225,14 +225,14 @@ >