diff --git a/FAQ.md b/FAQ.md index bda14eec..d0f7db9f 100644 --- a/FAQ.md +++ b/FAQ.md @@ -308,26 +308,25 @@ it's slower than `MemoryMapper`. ### Q: What environment variables supported? -| Key | Type | Description | Default | -|-----------------------|--------|---------------------------------------------------------------------------------|------------------------------------| -| WS_DATA_PATH | string | Where key data stored (config, db). | `${BASE_PATH}/var` | -| WS_TMP_DIR | string | Where temp data stored. (logs, cache). | `${WS_DATA_PATH}` | -| WS_TZ | string | Set timezone. | `UTC` | -| WS_CRON_IMPORT | bool | Enable import scheduled task. Value casted to bool. | `false` | -| WS_CRON_IMPORT_AT | string | When to run import scheduled task. Valid Cron Expression Expected. | `0 */1 * * *` (Every 1h) | -| WS_CRON_IMPORT_ARGS | string | Flags to pass to the import command. | `-v` | -| WS_CRON_EXPORT | bool | Enable export scheduled task. Value casted to bool. | `false` | -| WS_CRON_EXPORT_AT | string | When to run export scheduled task. Valid Cron Expression Expected. | `30 */1 * * *` (Every 1h 30m) | -| WS_CRON_EXPORT_ARGS | string | Flags to pass to the export command. | `-v` | -| WS_CRON_PUSH | bool | Enable push scheduled task. Value casted to bool. | `false` | -| WS_CRON_PUSH_AT | string | When to run push scheduled task. Valid Cron Expression Expected. | `*/10 * * * *` (Every 10m) | -| WS_CRON_PUSH_ARGS | string | Flags to pass to the push command. | `-v` | -| WS_LOGS_PRUNE_AFTER | string | Delete logs older than specified time. Set to `disable` to disable the pruning. | `-3 DAYS` | -| WS_LOGS_CONTEXT | bool | Add context to console output messages. | `false` | -| WS_LOGGER_FILE_ENABLE | bool | Save logs to file. | `true` | -| WS_LOGGER_FILE | string | Full path to log file. | `${WS_TMP_DIR}/logs/app.(Ymd).log` | -| WS_LOGGER_FILE_LEVEL | string | File Logger Level. | `ERROR` | -| WS_WEBHOOK_DEBUG | bool | If enabled, allow dumping request/webhook using `rdump` & `wdump` parameters. | `false` | +| Key | Type | Description | Default | +|-----------------------|--------|---------------------------------------------------------------------------------|-------------------------------| +| WS_DATA_PATH | string | Where to store main data. (config, db). | `${BASE_PATH}/var` | +| WS_TMP_DIR | string | Where to store temp data. (logs, cache) | `${WS_DATA_PATH}` | +| WS_TZ | string | Set timezone. | `UTC` | +| WS_CRON_IMPORT | bool | Enable import scheduled task. Value casted to bool. | `false` | +| WS_CRON_IMPORT_AT | string | When to run import scheduled task. Valid Cron Expression Expected. | `0 */1 * * *` (Every 1h) | +| WS_CRON_IMPORT_ARGS | string | Flags to pass to the import command. | `-v` | +| WS_CRON_EXPORT | bool | Enable export scheduled task. Value casted to bool. | `false` | +| WS_CRON_EXPORT_AT | string | When to run export scheduled task. Valid Cron Expression Expected. | `30 */1 * * *` (Every 1h 30m) | +| WS_CRON_EXPORT_ARGS | string | Flags to pass to the export command. | `-v` | +| WS_CRON_PUSH | bool | Enable push scheduled task. Value casted to bool. | `false` | +| WS_CRON_PUSH_AT | string | When to run push scheduled task. Valid Cron Expression Expected. | `*/10 * * * *` (Every 10m) | +| WS_CRON_PUSH_ARGS | string | Flags to pass to the push command. | `-v` | +| WS_LOGS_PRUNE_AFTER | string | Delete logs older than specified time. Set to `disable` to disable the pruning. | `-3 DAYS` | +| WS_LOGS_CONTEXT | bool | Add context to console output messages. | `false` | +| WS_LOGGER_FILE_ENABLE | bool | Save logs to file. | `true` | +| WS_LOGGER_FILE_LEVEL | string | File Logger Level. | `ERROR` | +| WS_WEBHOOK_DEBUG | bool | If enabled, allow dumping request/webhook using `rdump` & `wdump` parameters. | `false` | #### Container specific environment variables. diff --git a/config/commands.php b/config/commands.php index a9806e47..2d43ba53 100644 --- a/config/commands.php +++ b/config/commands.php @@ -16,6 +16,11 @@ return [ 'state:import' => App\Commands\State\ImportCommand::class, 'state:export' => App\Commands\State\ExportCommand::class, 'state:push' => App\Commands\State\PushCommand::class, + 'pull' => App\Commands\State\ImportCommand::class, + 'import' => App\Commands\State\ImportCommand::class, + 'export' => App\Commands\State\ExportCommand::class, + 'push' => App\Commands\State\PushCommand::class, + // -- storage: 'storage:maintenance' => App\Commands\Storage\MaintenanceCommand::class, 'storage:migrations' => App\Commands\Storage\MigrationsCommand::class, diff --git a/config/config.php b/config/config.php index 4236fe76..f5735ccd 100644 --- a/config/config.php +++ b/config/config.php @@ -34,7 +34,7 @@ return (function () { ], ]; - $config['logs']['affix'] = makeDate()->format('Ymd'); + $logDateFormat = makeDate()->format('Ymd'); $config['tmpDir'] = fixPath(env('WS_TMP_DIR', ag($config, 'path'))); @@ -55,8 +55,9 @@ return (function () { ]; $config['webhook'] = [ + 'logfile' => ag($config, 'tmpDir') . '/logs/access.' . $logDateFormat . '.log', 'debug' => (bool)env('WS_WEBHOOK_DEBUG', false), - 'tokenLength' => (int)env('WS_WEBHOOK_TOKEN_LENGTH', 16), + 'tokenLength' => 16, ]; $config['mapper'] = [ @@ -83,7 +84,6 @@ return (function () { ]; $config['debug'] = [ - 'import' => (bool)env('WS_DEBUG_IMPORT', false), 'profiler' => [ 'options' => [ 'save.handler' => 'file', @@ -106,10 +106,7 @@ return (function () { 'type' => 'stream', 'enabled' => (bool)env('WS_LOGGER_FILE_ENABLE', true), 'level' => env('WS_LOGGER_FILE_LEVEL', Logger::ERROR), - 'filename' => env( - 'WS_LOGGER_FILE', - fn() => ag($config, 'tmpDir') . '/logs/app.' . ag($config, 'logs.affix') . '.log' - ), + 'filename' => ag($config, 'tmpDir') . '/logs/app.' . $logDateFormat . '.log', ], 'stderr' => [ 'type' => 'stream', @@ -129,7 +126,7 @@ return (function () { 'facility' => env('WS_LOGGER_SYSLOG_FACILITY', LOG_USER), 'enabled' => (bool)env('WS_LOGGER_SYSLOG_ENABLED', !env('IN_DOCKER')), 'level' => env('WS_LOGGER_SYSLOG_LEVEL', Logger::ERROR), - 'name' => env('WS_LOGGER_SYSLOG_NAME', ag($config, 'name')), + 'name' => ag($config, 'name'), ], ]; @@ -177,7 +174,7 @@ return (function () { ]; $config['tasks'] = [ - 'logfile' => ag($config, 'tmpDir') . '/logs/tasks/task.' . ag($config, 'logs.affix') . '.log', + 'logfile' => ag($config, 'tmpDir') . '/logs/task.' . $logDateFormat . '.log', 'commands' => [ ImportCommand::TASK_NAME => [ Task::NAME => ImportCommand::TASK_NAME, diff --git a/config/directories.php b/config/directories.php index 405aa943..3122e433 100644 --- a/config/directories.php +++ b/config/directories.php @@ -5,7 +5,7 @@ declare(strict_types=1); return [ '%(path)/db/archive', '%(path)/config', - '%(tmpDir)/logs/tasks', + '%(tmpDir)/logs', '%(tmpDir)/cache', '%(tmpDir)/profiler', '%(tmpDir)/webhooks', diff --git a/docker/files/nginx.conf b/docker/files/nginx.conf index 0d065e4e..58310fff 100644 --- a/docker/files/nginx.conf +++ b/docker/files/nginx.conf @@ -23,21 +23,9 @@ http { '' close; } - log_format traceable '[$time_iso8601] ' - ' status: $status ' - '- message: "$upstream_http_x_status" ' - '- event: "$upstream_http_x_wh_event" ' - '- type: "$upstream_http_x_wh_type" ' - '- id: "$upstream_http_x_wh_id" ' - '- item: "$upstream_http_x_wh_item" ' - '- backend: "$upstream_http_x_wh_backend" ' - '- version: "$upstream_http_x_wh_version" ' - '- apikey: "$http_x_apikey" ' - '- request_id: "$request_id" ' - '- request: "$request":$body_bytes_sent ' - '- host: $http_host ' - '- ip: $remote_addr ' - '- agent: "$http_user_agent"'; + log_format traceable '$remote_addr - $remote_user [$time_local] ' + '"$request" $status $body_bytes_sent ' + '"$http_referer" "$http_user_agent" "$request_id"'; server { listen 80 default_server; @@ -74,7 +62,7 @@ http { set $path_info $fastcgi_path_info; fastcgi_param PATH_INFO $path_info; - # For better request traking. + # For better request tracking. fastcgi_param X_REQUEST_ID $request_id; fastcgi_index index.php; diff --git a/src/Backends/Emby/Action/InspectRequest.php b/src/Backends/Emby/Action/InspectRequest.php index 6d1d1f26..e043e239 100644 --- a/src/Backends/Emby/Action/InspectRequest.php +++ b/src/Backends/Emby/Action/InspectRequest.php @@ -5,8 +5,8 @@ declare(strict_types=1); namespace App\Backends\Emby\Action; use App\Backends\Common\CommonTrait; -use App\Backends\Common\Response; use App\Backends\Common\Context; +use App\Backends\Common\Response; use Psr\Http\Message\ServerRequestInterface; class InspectRequest @@ -27,9 +27,9 @@ class InspectRequest $payload = (string)ag($request->getParsedBody() ?? [], 'data', null); $json = json_decode( - json: $payload, + json: $payload, associative: true, - flags: JSON_INVALID_UTF8_IGNORE | JSON_THROW_ON_ERROR + flags: JSON_INVALID_UTF8_IGNORE | JSON_THROW_ON_ERROR ); $alteredRequest = $request->withParsedBody($json); @@ -38,7 +38,8 @@ class InspectRequest 'ITEM_ID' => ag($json, 'Item.Id', ''), 'SERVER_ID' => ag($json, 'Server.Id', ''), 'SERVER_NAME' => ag($json, 'Server.Name', ''), - 'SERVER_VERSION' => afterLast($userAgent, '/'), + 'SERVER_CLIENT' => before($userAgent, '/'), + 'SERVER_VERSION' => ag($json, 'Server.Version', fn() => afterLast($userAgent, '/')), 'USER_ID' => ag($json, 'User.Id', ''), 'USER_NAME' => ag($json, 'User.Name', ''), 'WH_EVENT' => ag($json, 'Event', 'not_set'), diff --git a/src/Backends/Jellyfin/Action/Import.php b/src/Backends/Jellyfin/Action/Import.php index 940060ae..fd39f52b 100644 --- a/src/Backends/Jellyfin/Action/Import.php +++ b/src/Backends/Jellyfin/Action/Import.php @@ -10,7 +10,6 @@ use App\Backends\Common\GuidInterface as iGuid; use App\Backends\Common\Response; use App\Backends\Jellyfin\JellyfinActionTrait; use App\Backends\Jellyfin\JellyfinClient as JFC; -use App\Libs\Config; use App\Libs\Data; use App\Libs\Entity\StateInterface as iFace; use App\Libs\Guid; @@ -528,24 +527,6 @@ class Import ); if (false === $entity->hasGuids() && false === $entity->hasRelativeGuid()) { - if (true === (bool)Config::get('debug.import')) { - $name = sprintf( - Config::get('tmpDir') . '/debug/%s.%s.json', - $context->backendName, - ag($item, 'Id') - ); - - if (!file_exists($name)) { - file_put_contents( - $name, - json_encode( - $item, - JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES | JSON_INVALID_UTF8_IGNORE - ) - ); - } - } - $providerIds = (array)ag($item, 'ProviderIds', []); $message = 'Ignoring [%(backend)] [%(item.title)]. No valid/supported external ids.'; diff --git a/src/Backends/Jellyfin/Action/InspectRequest.php b/src/Backends/Jellyfin/Action/InspectRequest.php index e1ebc561..994c05f8 100644 --- a/src/Backends/Jellyfin/Action/InspectRequest.php +++ b/src/Backends/Jellyfin/Action/InspectRequest.php @@ -5,8 +5,8 @@ declare(strict_types=1); namespace App\Backends\Jellyfin\Action; use App\Backends\Common\CommonTrait; -use App\Backends\Common\Response; use App\Backends\Common\Context; +use App\Backends\Common\Response; use Psr\Http\Message\ServerRequestInterface; final class InspectRequest @@ -38,6 +38,7 @@ final class InspectRequest 'ITEM_ID' => ag($json, 'ItemId', ''), 'SERVER_ID' => ag($json, 'ServerId', ''), 'SERVER_NAME' => ag($json, 'ServerName', ''), + 'SERVER_CLIENT' => before($userAgent, '/'), 'SERVER_VERSION' => ag($json, 'ServerVersion', fn() => afterLast($userAgent, '/')), 'USER_ID' => ag($json, 'UserId', ''), 'USER_NAME' => ag($json, 'NotificationUsername', ''), diff --git a/src/Backends/Plex/Action/Import.php b/src/Backends/Plex/Action/Import.php index 01f43cf1..6849e573 100644 --- a/src/Backends/Plex/Action/Import.php +++ b/src/Backends/Plex/Action/Import.php @@ -10,7 +10,6 @@ use App\Backends\Common\GuidInterface as iGuid; use App\Backends\Common\Response; use App\Backends\Plex\PlexActionTrait; use App\Backends\Plex\PlexClient; -use App\Libs\Config; use App\Libs\Data; use App\Libs\Entity\StateInterface as iFace; use App\Libs\Guid; @@ -574,22 +573,6 @@ class Import ); if (!$entity->hasGuids() && !$entity->hasRelativeGuid()) { - if (true === (bool)Config::get('debug.import')) { - $name = Config::get( - 'tmpDir' - ) . '/debug/' . $context->backendName . '.' . $item['ratingKey'] . '.json'; - - if (!file_exists($name)) { - file_put_contents( - $name, - json_encode( - $item, - JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES | JSON_INVALID_UTF8_IGNORE - ) - ); - } - } - $message = 'Ignoring [%(backend)] [%(item.title)]. No valid/supported external ids.'; if (null === ($item['Guid'] ?? null)) { diff --git a/src/Backends/Plex/Action/InspectRequest.php b/src/Backends/Plex/Action/InspectRequest.php index 3a2dd619..1fd0cbad 100644 --- a/src/Backends/Plex/Action/InspectRequest.php +++ b/src/Backends/Plex/Action/InspectRequest.php @@ -5,8 +5,8 @@ declare(strict_types=1); namespace App\Backends\Plex\Action; use App\Backends\Common\CommonTrait; -use App\Backends\Common\Response; use App\Backends\Common\Context; +use App\Backends\Common\Response; use Psr\Http\Message\ServerRequestInterface; final class InspectRequest @@ -27,9 +27,9 @@ final class InspectRequest $payload = ag($request->getParsedBody() ?? [], 'payload', null); $json = json_decode( - json: $payload, + json: $payload, associative: true, - flags: JSON_INVALID_UTF8_IGNORE | JSON_THROW_ON_ERROR + flags: JSON_INVALID_UTF8_IGNORE | JSON_THROW_ON_ERROR ); $alteredRequest = $request->withParsedBody($json); @@ -38,7 +38,8 @@ final class InspectRequest 'ITEM_ID' => ag($json, 'Metadata.ratingKey', ''), 'SERVER_ID' => ag($json, 'Server.uuid', ''), 'SERVER_NAME' => ag($json, 'Server.title', ''), - 'SERVER_VERSION' => afterLast($userAgent, '/'), + 'SERVER_CLIENT' => before($userAgent, '/'), + 'SERVER_VERSION' => ag($json, 'Server.version', fn() => afterLast($userAgent, '/')), 'USER_ID' => ag($json, 'Account.id', ''), 'USER_NAME' => ag($json, 'Account.title', ''), 'WH_EVENT' => ag($json, 'event', 'not_set'), diff --git a/src/Commands/State/ExportCommand.php b/src/Commands/State/ExportCommand.php index eb0698ce..aee24e73 100644 --- a/src/Commands/State/ExportCommand.php +++ b/src/Commands/State/ExportCommand.php @@ -52,6 +52,7 @@ class ExportCommand extends Command 'Always update the locally stored metadata from backend.' ) ->addOption('config', 'c', InputOption::VALUE_REQUIRED, 'Use Alternative config file.') + ->setAliases(['export']) // -- @RELEASE remove force-* options ->addOption('force-export-mode', null, InputOption::VALUE_NONE, 'Force export mode. [NO LONGER USED].') ->addOption('force-push-mode', null, InputOption::VALUE_NONE, 'Force push mode. [NO LONGER USED].'); diff --git a/src/Commands/State/ImportCommand.php b/src/Commands/State/ImportCommand.php index 50547a2b..d57d2f98 100644 --- a/src/Commands/State/ImportCommand.php +++ b/src/Commands/State/ImportCommand.php @@ -65,7 +65,8 @@ class ImportCommand extends Command InputOption::VALUE_NONE, 'import metadata changes only. Works when there are records in storage.' ) - ->addOption('config', 'c', InputOption::VALUE_REQUIRED, 'Use Alternative config file.'); + ->addOption('config', 'c', InputOption::VALUE_REQUIRED, 'Use Alternative config file.') + ->setAliases(['import', 'pull']); } protected function runCommand(InputInterface $input, OutputInterface $output): int diff --git a/src/Commands/State/PushCommand.php b/src/Commands/State/PushCommand.php index 6e21d160..74f79405 100644 --- a/src/Commands/State/PushCommand.php +++ b/src/Commands/State/PushCommand.php @@ -47,7 +47,8 @@ class PushCommand extends Command null, InputOption::VALUE_NONE, 'Ignore date comparison. Push storage state to the backends regardless of date.' - ); + ) + ->setAliases(['push']); } /** diff --git a/src/Commands/System/LogsCommand.php b/src/Commands/System/LogsCommand.php index 32ddec8b..287498a0 100644 --- a/src/Commands/System/LogsCommand.php +++ b/src/Commands/System/LogsCommand.php @@ -9,6 +9,8 @@ use App\Libs\Config; use Exception; use LimitIterator; use SplFileObject; +use Symfony\Component\Console\Completion\CompletionInput; +use Symfony\Component\Console\Completion\CompletionSuggestions; use Symfony\Component\Console\Input\InputInterface; use Symfony\Component\Console\Input\InputOption; use Symfony\Component\Console\Output\OutputInterface; @@ -16,23 +18,43 @@ use Symfony\Component\Console\Question\ConfirmationQuestion; final class LogsCommand extends Command { + private const LOG_FILES = [ + 'app', + 'access', + 'task' + ]; + public const DEFAULT_LIMIT = 50; protected function configure(): void { $this->setName('system:logs') ->addOption( - 'filename', - 'f', - InputOption::VALUE_OPTIONAL, - 'Read contents of given file.', - after(Config::get('logger.file.filename'), Config::get('tmpDir') . '/') + 'type', + null, + InputOption::VALUE_REQUIRED, + sprintf('Log type, can be [%s].', implode(', ', self::LOG_FILES)), + self::LOG_FILES[0] + ) + ->addOption( + 'date', + null, + InputOption::VALUE_REQUIRED, + 'Which log date to open. Format is [YYYYMMDD].', + makeDate()->format('Ymd'), + ) + ->addOption('list', null, InputOption::VALUE_NONE, 'List All log files.') + ->addOption( + 'limit', + 'l', + InputOption::VALUE_OPTIONAL, + 'Show last X number of log lines.', + self::DEFAULT_LIMIT ) - ->addOption('limit', 'l', InputOption::VALUE_OPTIONAL, 'Show last X number messages.', self::DEFAULT_LIMIT) ->addOption('tail', 't', InputOption::VALUE_NONE, 'Tail logfile.') ->addOption('clear', null, InputOption::VALUE_NONE, 'Clear log file') ->setAliases(['logs']) - ->setDescription('View current log file content.'); + ->setDescription('View current logs.'); } /** @@ -40,21 +62,36 @@ final class LogsCommand extends Command */ protected function runCommand(InputInterface $input, OutputInterface $output): int { - $file = $input->getOption('filename'); - $limit = (int)$input->getOption('limit'); - - if (false === file_exists($file) && false === str_starts_with($file, '/')) { - $file = Config::get('tmpDir') . '/' . $file; + if ($input->getOption('list')) { + return $this->listLogs($input, $output); } - if (empty($file) || false === file_exists($file) || false === is_file($file) || false === is_readable($file)) { - if ($file === Config::get('logger.file.filename')) { - $output->writeln('Log file is empty. No records were found for today.'); - return self::SUCCESS; - } + $type = $input->getOption('type'); - $output->writeln(sprintf('Unable to read logfile \'%s\'.', $file)); - return self::FAILURE; + if (false === in_array($type, self::LOG_FILES)) { + throw new \RuntimeException( + sprintf('Log type has to be one of the supported log files [%s].', implode(', ', self::LOG_FILES)) + ); + } + + $date = $input->getOption('date'); + + if (1 !== preg_match('/^\d{8}$/', $date)) { + throw new \RuntimeException('Log date must be in [YYYYMMDD] format. For example [20220622].'); + } + + $limit = (int)$input->getOption('limit'); + + $file = sprintf(Config::get('tmpDir') . '/logs/%s.%s.log', $type, $date); + + if (false === file_exists($file) || filesize($file) < 1) { + $output->writeln( + sprintf( + 'Log file [%s] does not exist or is empty. This means it has been pruned, the date is incorrect or nothing has written to that file yet.', + after($file, dirname(Config::get('tmpDir'))) + ) + ); + return self::SUCCESS; } $file = new SplFileObject($file, 'r'); @@ -126,6 +163,38 @@ final class LogsCommand extends Command return self::SUCCESS; } + private function listLogs(InputInterface $input, OutputInterface $output): int + { + $path = fixPath(Config::get('tmpDir') . '/logs'); + + $list = []; + + $isTable = $input->getOption('output') === 'table'; + + foreach (glob($path . '/*.*.log') as $file) { + preg_match('/(\w+)\.(\d+)\.log/i', basename($file), $matches); + + $size = filesize($file); + + $builder = [ + 'type' => $matches[1], + 'date' => $matches[2], + 'size' => $isTable ? fsize($size) : $size, + 'modified' => makeDate(filemtime($file))->format('Y-m-d H:i:s T'), + ]; + + if (!$isTable) { + $builder['file'] = $file; + } + + $list[] = $builder; + } + + $this->displayContent($list, $output, $input->getOption('output')); + + return self::SUCCESS; + } + private function handleClearLog(SplFileObject $file, InputInterface $input, OutputInterface $output): int { $logfile = after($file->getRealPath(), Config::get('tmpDir') . '/'); @@ -176,4 +245,23 @@ final class LogsCommand extends Command return self::SUCCESS; } + + public function complete(CompletionInput $input, CompletionSuggestions $suggestions): void + { + parent::complete($input, $suggestions); + + if ($input->mustSuggestOptionValuesFor('type')) { + $currentValue = $input->getCompletionValue(); + + $suggest = []; + + foreach (self::LOG_FILES as $name) { + if (empty($currentValue) || str_starts_with($name, $currentValue)) { + $suggest[] = $name; + } + } + + $suggestions->suggestValues($suggest); + } + } } diff --git a/src/Commands/System/PruneCommand.php b/src/Commands/System/PruneCommand.php index a1dbd7fe..87fdd946 100644 --- a/src/Commands/System/PruneCommand.php +++ b/src/Commands/System/PruneCommand.php @@ -57,8 +57,10 @@ final class PruneCommand extends Command 'filter' => '*.log', ], [ + // -- @RELEASE - remove path. 'path' => Config::get('tmpDir') . '/logs/tasks', 'filter' => '*.log', + 'report' => false, ], [ 'path' => Config::get('tmpDir') . '/webhooks', @@ -80,9 +82,11 @@ final class PruneCommand extends Command $path = ag($item, 'path'); if (null === $path || !is_dir($path)) { - $this->logger->warning('Path [%(path)] not found or inaccessible.', [ - 'path' => $path - ]); + if (true === (bool)ag($item, 'report', true)) { + $this->logger->warning('Path [%(path)] not found or inaccessible.', [ + 'path' => $path + ]); + } continue; } diff --git a/src/Libs/Initializer.php b/src/Libs/Initializer.php index 9c5a50d8..cc41646d 100644 --- a/src/Libs/Initializer.php +++ b/src/Libs/Initializer.php @@ -32,6 +32,7 @@ final class Initializer { private Cli $cli; private ConsoleOutput $cliOutput; + private LoggerInterface|null $accessLog = null; public function __construct() { @@ -160,319 +161,354 @@ final class Initializer private function defaultHttpServer(ServerRequestInterface $realRequest): ResponseInterface { - $log = $responseHeaders = $server = []; + $log = $server = []; $class = null; - $logger = Container::get(LoggerInterface::class); $request = $realRequest; - try { - // -- Save request payload. - if (true === Config::get('webhook.debug') && true === (bool)ag($realRequest->getQueryParams(), 'rdump')) { - saveRequestPayload($realRequest); + // -- Save request payload. + if (true === Config::get('webhook.debug') && true === (bool)ag($realRequest->getQueryParams(), 'rdump')) { + saveRequestPayload($realRequest); + } + + $apikey = ag($realRequest->getQueryParams(), 'apikey', $realRequest->getHeaderLine('x-apikey')); + + if (empty($apikey)) { + $this->write($request, Logger::INFO, 'No webhook token was found in header or query.'); + return new Response(401); + } + + $validUser = $validUUid = null; + + // -- Find Relevant backend. + foreach (Config::get('servers', []) as $name => $info) { + if (null === ag($info, 'webhook.token')) { + continue; } - $apikey = ag($realRequest->getQueryParams(), 'apikey', $realRequest->getHeaderLine('x-apikey')); - if (empty($apikey)) { - $log[] = 'No webhook token found in headers or query'; - throw new HttpException('No Webhook token was found.', 400); + if (true !== hash_equals((string)ag($info, 'webhook.token'), (string)$apikey)) { + continue; } - $validUser = $validUUid = null; + try { + $class = makeServer($info, $name); + } catch (RuntimeException $e) { + $this->write($request, Logger::ERROR, 'An exception was thrown in [%(backend)] instance creation.', [ + 'backend' => $name, + 'exception' => [ + 'file' => $e->getFile(), + 'line' => $e->getLine(), + 'kind' => get_class($e), + 'message' => $e->getMessage(), + ] + ]); + continue; + } - // -- Find Relevant backend. - foreach (Config::get('servers', []) as $name => $info) { - if (null === ag($info, 'webhook.token')) { + $request = $class->processRequest(clone $realRequest); + + if (null !== ($userId = ag($info, 'user', null)) && true === (bool)ag($info, 'webhook.match.user')) { + if (null === ($requestUser = $request->getAttribute('USER_ID', null))) { + $validUser = false; + $server = $class = null; + $log[] = 'Request user is not set'; continue; } - if (true !== hash_equals((string)ag($info, 'webhook.token'), (string)$apikey)) { + if (false === hash_equals((string)$userId, (string)$requestUser)) { + $validUser = false; + $server = $class = null; + $log[] = sprintf( + 'Request user id [%s] does not match configured value [%s]', + $requestUser ?? 'NOT SET', + $userId + ); continue; } - try { - $class = makeServer($info, $name); - } catch (RuntimeException $e) { - $log[] = sprintf('%s: Creating Instance of the server backend has failed.', $name); - throw new HttpException($e->getMessage(), 500); + $validUser = true; + } + + if (null !== ($uuid = ag($info, 'uuid', null)) && true === (bool)ag($info, 'webhook.match.uuid')) { + if (null === ($requestBackendId = $request->getAttribute('SERVER_ID', null))) { + $validUUid = false; + $server = $class = null; + $log[] = 'backend unique id is not set'; + continue; } - $request = $class->processRequest(clone $realRequest); - - $userId = ag($info, 'user', null); - - if (null !== $userId && true === (bool)ag($info, 'webhook.match.user')) { - if (null === ($requestUser = $request->getAttribute('USER_ID', null))) { - $validUser = false; - $server = $class = null; - $log[] = 'Request user is not set'; - continue; - } - - if (false === hash_equals((string)$userId, (string)$requestUser)) { - $validUser = false; - $server = $class = null; - $log[] = sprintf( - 'Request user id [%s] does not match configured value [%s]', - $requestUser ?? 'NOT SET', - $userId - ); - continue; - } - - $validUser = true; - } - - $uuid = ag($info, 'uuid', null); - - if (null !== $uuid && true === (bool)ag($info, 'webhook.match.uuid')) { - if (null === ($requestBackendId = $request->getAttribute('SERVER_ID', null))) { - $validUUid = false; - $server = $class = null; - $log[] = 'backend unique id is not set'; - continue; - } - - if (false === hash_equals((string)$uuid, (string)$requestBackendId)) { - $validUUid = false; - $server = $class = null; - $log[] = sprintf( - 'Request backend unique id [%s] does not match configured value [%s]', - $requestBackendId ?? 'NOT SET', - $uuid - ); - continue; - } - - $validUUid = true; - } - - $server = array_replace_recursive(['name' => $name], $info); - break; - } - - if (empty($server) || null === $class) { - if (false === $validUser) { - $message = 'token is valid, User matching failed.'; - } elseif (false === $validUUid) { - $message = 'token and user are valid. Backend unique id matching failed.'; - } else { - $message = 'Invalid token was given.'; - } - throw new HttpException($message, 401); - } - - // -- sanity check in case user has both import.enabled and options.IMPORT_METADATA_ONLY enabled. - // -- @RELEASE remove 'webhook.import' - if (true === (bool)ag($server, ['import.enabled', 'webhook.import'])) { - if (true === ag_exists($server, 'options.' . Options::IMPORT_METADATA_ONLY)) { - $server = ag_delete($server, 'options.' . Options::IMPORT_METADATA_ONLY); - } - } - - $metadataOnly = true === (bool)ag($server, 'options.' . Options::IMPORT_METADATA_ONLY); - - // -- @RELEASE remove 'webhook.import' - if (true !== $metadataOnly && true !== (bool)ag($server, ['import.enabled', 'webhook.import'])) { - $log[] = 'Import disabled for this backend.'; - throw new HttpException( - sprintf( - '%s: Import is disabled for this backend.', - $class->getName() - ), - 500 - ); - } - - $entity = $class->parseWebhook($request); - - // -- Dump Webhook context. - if (true === Config::get('webhook.debug') && true === (bool)ag($request->getQueryParams(), 'wdump')) { - saveWebhookPayload($entity, $request); - } - - $responseHeaders = [ - 'X-WH-Id' => '?', - 'X-WH-Backend' => $class->getName(), - 'X-WH-Item' => $entity->getName(), - 'X-WH-Type' => $request->getAttribute('WH_TYPE', 'not_set'), - 'X-WH-Event' => $request->getAttribute('WH_EVENT', 'not_set'), - 'X-WH-Version' => getAppVersion(), - ]; - - if (!$entity->hasGuids() && !$entity->hasRelativeGuid()) { - $message = sprintf('%s does not have valid/supported external ids.', ucfirst($entity->type)); - return new Response( - status: 204, - headers: $responseHeaders + ['X-Status' => $message] - ); - } - - $storage = Container::get(StorageInterface::class); - - if (null === ($local = $storage->get($entity))) { - if (true === $metadataOnly) { - $message = 'Unable to add new item. This backend is flagged for metadata only.'; - return new Response( - status: 204, - headers: $responseHeaders + ['X-Status' => $message] + if (false === hash_equals((string)$uuid, (string)$requestBackendId)) { + $validUUid = false; + $server = $class = null; + $log[] = sprintf( + 'Request backend unique id [%s] does not match configured value [%s]', + $requestBackendId ?? 'NOT SET', + $uuid ); + continue; } - $entity = $storage->insert($entity); - - if (true === $entity->isWatched()) { - queuePush($entity); - } - - $responseHeaders['X-WH-Id'] = $entity->id; - - return jsonResponse( - status: 200, - body: $entity->getAll(), - headers: $responseHeaders + ['X-Status' => sprintf('Added %s as new item.', $entity->type)] - ); + $validUUid = true; } - $responseHeaders['X-WH-Id'] = $local->id; + $server = array_replace_recursive(['name' => $name], $info); + break; + } - $cloned = clone $local; - - if (true === $metadataOnly || true === $entity->isTainted()) { - $flag = true === $metadataOnly ? '[M]' : '[T]'; - $keys = true === $metadataOnly ? [iFace::COLUMN_META_DATA] : iFace::ENTITY_FORCE_UPDATE_FIELDS; - - if ((clone $cloned)->apply(entity: $entity, fields: $keys)->isChanged(fields: $keys)) { - if (true === $metadataOnly) { - $entity->guids = Guid::makeVirtualGuid( - $entity->via, - ag($entity->getMetadata($entity->via), iFace::COLUMN_ID) - ); - $keys = array_merge($keys, [iFace::COLUMN_GUIDS, iFace::COLUMN_EXTRA]); - } - - $local = $storage->update( - $local->apply( - entity: $entity, - fields: array_merge($keys, [iFace::COLUMN_EXTRA]) - ) - ); - - return jsonResponse( - status: 200, - body: $local->getAll(), - headers: $responseHeaders + ['X-Status' => $flag . ' Updated metadata.'] - ); - } - - return new Response( - status: 200, - headers: $responseHeaders + ['X-Status' => $flag . ' This event is irrelevant.'] - ); + if (empty($server) || null === $class) { + if (false === $validUser) { + $message = 'token is valid, User matching failed.'; + } elseif (false === $validUUid) { + $message = 'token and user are valid. Backend unique id matching failed.'; + } else { + $message = 'Invalid token was given.'; } - if ($local->updated >= $entity->updated) { - $keys = iFace::ENTITY_FORCE_UPDATE_FIELDS; + $this->write($request, Logger::ERROR, $message, ['messages' => $log]); + return new Response(401); + } - // -- Handle mark as unplayed logic. - if (false === $entity->isWatched() && true === $local->shouldMarkAsUnplayed($entity)) { - $local = $storage->update( - $local->apply(entity: $entity, fields: [iFace::COLUMN_META_DATA])->markAsUnplayed($entity) - ); - - queuePush($local); - - return jsonResponse( - status: 200, - body: $local->getAll(), - headers: $responseHeaders + [ - 'X-Status' => sprintf('%s Marked as [Unplayed].', ucfirst($entity->type)) - ] - ); - } - - if ((clone $cloned)->apply(entity: $entity, fields: $keys)->isChanged(fields: $keys)) { - $local = $storage->update( - $local->apply( - entity: $entity, - fields: array_merge($keys, [iFace::COLUMN_EXTRA]) - ) - ); - return jsonResponse( - status: 200, - body: $local->getAll(), - headers: $responseHeaders + ['X-Status' => sprintf('[D] Updated %s.', $entity->type)] - ); - } - - return new Response( - status: 200, - headers: $responseHeaders + ['X-Status' => '[D] No difference detected.'] - ); + // -- sanity check in case user has both import.enabled and options.IMPORT_METADATA_ONLY enabled. + // -- @RELEASE remove 'webhook.import' + if (true === (bool)ag($server, ['import.enabled', 'webhook.import'])) { + if (true === ag_exists($server, 'options.' . Options::IMPORT_METADATA_ONLY)) { + $server = ag_delete($server, 'options.' . Options::IMPORT_METADATA_ONLY); } + } - if ((clone $cloned)->apply($entity)->isChanged()) { - $local = $storage->update($local->apply($entity)); + $metadataOnly = true === (bool)ag($server, 'options.' . Options::IMPORT_METADATA_ONLY); - $message = '%1$s Updated.'; - - if ($cloned->isWatched() !== $local->isWatched()) { - $message = '%1$s marked as [%2$s]'; - queuePush($local); - } - - return jsonResponse( - status: 200, - body: $local->getAll(), - headers: $responseHeaders + [ - 'X-Status' => sprintf( - $message, - ucfirst($entity->type), - $entity->isWatched() ? 'Played' : 'Unplayed', - ), - ] - ); - } - - return new Response( - status: 200, - headers: $responseHeaders + ['X-Status' => 'No changes detected.'] - ); - } catch (HttpException $e) { - if (200 === $e->getCode()) { - return new Response( - status: $e->getCode(), - headers: $responseHeaders + ['X-Status' => $e->getMessage()] - ); - } - - $logger->error(message: $e->getMessage(), context: [ - 'attributes' => $request->getAttributes(), - 'log' => $log, - 'context' => array_keys_diff( - $realRequest->getServerParams(), - [ - 'HTTP_HOST', - 'SERVER_NAME', - 'REMOTE_ADDR', - 'X_REQUEST_ID', - 'HTTP_USER_AGENT' - ], - has: true - ), - 'trace' => [ - 'file' => $e->getFile(), - 'line' => $e->getLine(), - 'kind' => get_class($e), - ], + // -- @RELEASE remove 'webhook.import' + if (true !== $metadataOnly && true !== (bool)ag($server, ['import.enabled', 'webhook.import'])) { + $this->write($request, Logger::ERROR, 'Import are disabled for [%(backend)].', [ + 'backend' => $class->getName() ]); - return jsonResponse( - status: $e->getCode(), - body: ['error' => true, 'message' => $e->getMessage()], - headers: $responseHeaders + ['X-Status' => $e->getMessage()] - ); + return new Response(406); } + + $entity = $class->parseWebhook($request); + + // -- Dump Webhook context. + if (true === Config::get('webhook.debug') && true === (bool)ag($request->getQueryParams(), 'wdump')) { + saveWebhookPayload($entity, $request); + } + + if (!$entity->hasGuids() && !$entity->hasRelativeGuid()) { + $this->write( + $request, Logger::INFO, + 'Ignoring [%(backend)] %(item.type) [%(item.title)]. No valid/supported external ids.', + [ + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ] + ] + ); + + return new Response(304); + } + + $storage = Container::get(StorageInterface::class); + + if (null === ($local = $storage->get($entity))) { + if (true === $metadataOnly) { + $this->write( + $request, Logger::INFO, + 'Ignoring [%(backend)] %(item.type) [%(item.title)]. Backend flagged for metadata only.', + [ + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ] + ] + ); + + return new Response(204); + } + + $entity = $storage->insert($entity); + + if (true === $entity->isWatched()) { + queuePush($entity); + } + + $this->write($request, Logger::NOTICE, '[%(backend)] Added [%(item.title)] as new item.', [ + 'id' => $entity->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ] + ]); + + return new Response(200); + } + + $cloned = clone $local; + + if (true === $metadataOnly || true === $entity->isTainted()) { + $flag = true === $metadataOnly ? '[M]' : '[T]'; + $keys = true === $metadataOnly ? [iFace::COLUMN_META_DATA] : iFace::ENTITY_FORCE_UPDATE_FIELDS; + + if ((clone $cloned)->apply(entity: $entity, fields: $keys)->isChanged(fields: $keys)) { + if (true === $metadataOnly) { + $entity->guids = Guid::makeVirtualGuid( + $entity->via, + ag($entity->getMetadata($entity->via), iFace::COLUMN_ID) + ); + $keys = array_merge($keys, [iFace::COLUMN_GUIDS, iFace::COLUMN_EXTRA]); + } + + $local = $storage->update( + $local->apply( + entity: $entity, + fields: array_merge($keys, [iFace::COLUMN_EXTRA]) + ) + ); + + $this->write( + $request, Logger::NOTICE, + '[%(flag)] [%(backend)] updated [%(item.title)] metadata.', + [ + 'flag' => $flag, + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ] + ] + ); + + return new Response(200); + } + + $this->write( + $request, Logger::DEBUG, + '[%(flag)] Ignoring [%(backend)] [%(item.title)] request. This webhook event is irrelevant.', + [ + 'flag' => $flag, + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ], + ] + ); + + return new Response(204); + } + + if ($local->updated >= $entity->updated) { + $keys = iFace::ENTITY_FORCE_UPDATE_FIELDS; + + // -- Handle mark as unplayed logic. + if (false === $entity->isWatched() && true === $local->shouldMarkAsUnplayed($entity)) { + $local = $storage->update( + $local->apply(entity: $entity, fields: [iFace::COLUMN_META_DATA])->markAsUnplayed($entity) + ); + + queuePush($local); + + $this->write( + $request, Logger::NOTICE, + '[%(backend)] marked [%(item.title)] as [Unplayed].', + [ + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + ], + ] + ); + + return new Response(200); + } + + if ((clone $cloned)->apply(entity: $entity, fields: $keys)->isChanged(fields: $keys)) { + $local = $storage->update( + $local->apply( + entity: $entity, + fields: array_merge($keys, [iFace::COLUMN_EXTRA]) + ) + ); + + $this->write( + $request, Logger::INFO, + '[%(backend)] updated [%(item.title)] metadata.', + [ + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ], + ] + ); + + return new Response(200); + } + + $this->write( + $request, Logger::DEBUG, + '[%(backend)] %(item.type) [%(item.title)] metadata is identical to locally stored metadata.', + [ + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ], + ] + ); + + return new Response(200); + } + + if ((clone $cloned)->apply($entity)->isChanged()) { + $local = $storage->update($local->apply($entity)); + $stateChanged = $cloned->isWatched() !== $local->isWatched(); + + $this->write( + $request, + $stateChanged ? Logger::NOTICE : Logger::INFO, + $stateChanged ? '[%(backend)] marked [%(item.title)] as [%(item.state)].' : '[%(backend)] updated [%(item.title)] metadata.', + [ + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + 'state' => $entity->isWatched() ? 'Played' : 'Unplayed', + ], + ] + ); + + if (true === $stateChanged) { + queuePush($local); + } + + return new Response(200); + } + + $this->write( + $request, Logger::DEBUG, + '[%(backend)] %(item.type) [%(item.title)] metadata and play state is identical to local data.', + [ + 'id' => $local->id, + 'backend' => $entity->via, + 'item' => [ + 'title' => $entity->getName(), + 'type' => $entity->type, + ], + ] + ); + + return new Response(200); } private function createDirectories(): void @@ -545,6 +581,16 @@ final class Initializer { $inDocker = (bool)env('IN_DOCKER'); + if (null !== ($logfile = Config::get('webhook.logfile'))) { + $level = Config::get('webhook.debug') ? Logger::DEBUG : Logger::INFO; + $this->accessLog = $logger->withName(name: 'webhook') + ->pushHandler(new StreamHandler($logfile, $level, true)); + + if (true === $inDocker) { + $this->accessLog->pushHandler(new StreamHandler('php://stderr', $level, true)); + } + } + foreach ($loggers as $name => $context) { if (!ag($context, 'type')) { throw new RuntimeException(sprintf('Logger: \'%s\' has no type set.', $name)); @@ -595,4 +641,33 @@ final class Initializer } } } + + private function write( + ServerRequestInterface $request, + int $level, + string $message, + array $context = [], + ): void { + if (null === $this->accessLog) { + return; + } + + $context = array_replace_recursive( + [ + 'request' => [ + 'id' => ag($request->getServerParams(), 'X_REQUEST_ID'), + 'ip' => ag($request->getServerParams(), 'REMOTE_ADDR'), + 'agent' => ag($request->getServerParams(), 'HTTP_USER_AGENT'), + 'uri' => ag($request->getServerParams(), 'REQUEST_URI'), + ], + ], + $context + ); + + if (($attributes = $request->getAttributes()) && count($attributes) >= 1) { + $context['attributes'] = $attributes; + } + + $this->accessLog->log($level, $message, $context); + } }