cphipps/watchstate
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

Merge pull request #170 from ArabCoders/dev

Browse Source 
Updated system:logs to better reflect the changes to our logging system.
This commit is contained in:
Abdulmohsen
2022-06-20 22:54:01 +03:00
committed by GitHub
parent 7fe944226b 9b162457cf
commit 9070f42221
16 changed files with 522 additions and 396 deletions
Download Patch File Download Diff File Expand all files Collapse all files

39
FAQ.md
View File

@@ -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.

5
config/commands.php
View File

@@ -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,

15
config/config.php
View File

@@ -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,

2
config/directories.php
View File

@@ -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',

20
docker/files/nginx.conf
View File

@@ -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;

9
src/Backends/Emby/Action/InspectRequest.php
View File

@@ -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'),

19
src/Backends/Jellyfin/Action/Import.php
View File

@@ -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.';

3
src/Backends/Jellyfin/Action/InspectRequest.php
View File

@@ -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', ''),

17
src/Backends/Plex/Action/Import.php
View File

@@ -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)) {

9
src/Backends/Plex/Action/InspectRequest.php
View File

@@ -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'),

1
src/Commands/State/ExportCommand.php
View File

@@ -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].');

3
src/Commands/State/ImportCommand.php
View File

@@ -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

3
src/Commands/State/PushCommand.php
View File

@@ -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']);
}
/**

126
src/Commands/System/LogsCommand.php
View File

@@ -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('<info>Log file is empty. No records were found for today.</info>');
return self::SUCCESS;
}
$type = $input->getOption('type');
$output->writeln(sprintf('<error>Unable to read logfile \'%s\'.</error>', $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(
'<info>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.</info>',
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);
}
}
}

10
src/Commands/System/PruneCommand.php
View File

@@ -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;
}

637
src/Libs/Initializer.php
View File

@@ -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);
}
}