From c0faf85618b7fd0cafa3e8c8b1a3a95d8e3348c1 Mon Sep 17 00:00:00 2001 From: Alexis Saettler Date: Fri, 1 Sep 2023 08:32:44 +0200 Subject: [PATCH] feat: add logs for addressbook subscriptions --- app/Console/Kernel.php | 2 + app/Domains/Contact/Dav/Jobs/UpdateVCard.php | 4 +- .../Web/Backend/CardDAV/CardDAVBackend.php | 2 +- .../DavClient/Jobs/DeleteMultipleVCard.php | 17 +++++++ .../Contact/DavClient/Jobs/DeleteVCard.php | 19 +++++++ .../DavClient/Jobs/GetMultipleVCard.php | 17 +++++++ .../Contact/DavClient/Jobs/GetVCard.php | 19 +++++++ .../Contact/DavClient/Jobs/PushVCard.php | 20 +++++++- .../Jobs/SynchronizeAddressBooks.php | 31 +++++++++--- .../Services/SynchronizeAddressBook.php | 2 +- .../Services/Utils/AddressBookGetter.php | 2 +- .../Utils/AddressBookSynchronizer.php | 2 +- .../Services/Utils/Dav/DavClient.php | 8 +-- app/Logging/CleanLogs.php | 19 +++++++ app/Logging/LoggingHandler.php | 43 ++++++++++++++++ app/Models/AddressBookSubscription.php | 11 ++++ app/Models/Log.php | 50 +++++++++++++++++++ config/logging.php | 6 +++ ...230200_create_addressbook_subscription.php | 1 + .../2023_08_30_202650_create_logs_table.php | 37 ++++++++++++++ ...30_202650_fix_addressbook_currentlogid.php | 20 ++++++++ 21 files changed, 314 insertions(+), 18 deletions(-) create mode 100644 app/Logging/CleanLogs.php create mode 100644 app/Logging/LoggingHandler.php create mode 100644 app/Models/Log.php create mode 100644 database/migrations/2023_08_30_202650_create_logs_table.php create mode 100644 database/migrations/2023_08_30_202650_fix_addressbook_currentlogid.php diff --git a/app/Console/Kernel.php b/app/Console/Kernel.php index c413defb2db..02962e68acf 100644 --- a/app/Console/Kernel.php +++ b/app/Console/Kernel.php @@ -6,6 +6,7 @@ use App\Domains\Contact\Dav\Jobs\CleanSyncToken; use App\Domains\Contact\DavClient\Jobs\UpdateAddressBooks; use App\Domains\Contact\ManageReminders\Jobs\ProcessScheduledContactReminders; +use App\Logging\CleanLogs; use Illuminate\Console\Scheduling\Schedule; use Illuminate\Foundation\Console\Kernel as ConsoleKernel; use Illuminate\Support\Facades\App; @@ -44,6 +45,7 @@ protected function schedule(Schedule $schedule) $this->scheduleJob($schedule, UpdateAddressBooks::class, 'hourly'); $this->scheduleJob($schedule, ProcessScheduledContactReminders::class, 'minutes', 1); $this->scheduleJob($schedule, CleanSyncToken::class, 'daily'); + $this->scheduleJob($schedule, CleanLogs::class, 'daily'); } /** diff --git a/app/Domains/Contact/Dav/Jobs/UpdateVCard.php b/app/Domains/Contact/Dav/Jobs/UpdateVCard.php index c6b16991e6d..045f916123e 100644 --- a/app/Domains/Contact/Dav/Jobs/UpdateVCard.php +++ b/app/Domains/Contact/Dav/Jobs/UpdateVCard.php @@ -65,7 +65,7 @@ public function execute(array $data): void $newtag = $this->updateCard($this->data['uri'], $this->data['card']); if ($newtag !== null && ($etag = Arr::get($this->data, 'etag')) !== null && $newtag !== $etag) { - Log::warning(__CLASS__.' '.__FUNCTION__." wrong etag when updating contact. Expected [$etag], got [$newtag]", [ + Log::channel('database')->warning(__CLASS__.' '.__FUNCTION__." wrong etag when updating contact. Expected [$etag], got [$newtag]", [ 'contacturl' => $this->data['uri'], 'carddata' => $this->data['card'], ]); @@ -99,7 +99,7 @@ private function updateCard(string $uri, mixed $card): ?string ]); } } catch (\Exception $e) { - Log::error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ + Log::channel('database')->error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ 'uri' => $uri, 'carddata' => $card, $e, diff --git a/app/Domains/Contact/Dav/Web/Backend/CardDAV/CardDAVBackend.php b/app/Domains/Contact/Dav/Web/Backend/CardDAV/CardDAVBackend.php index c9d77be5ae5..761c0325f95 100644 --- a/app/Domains/Contact/Dav/Web/Backend/CardDAV/CardDAVBackend.php +++ b/app/Domains/Contact/Dav/Web/Backend/CardDAV/CardDAVBackend.php @@ -204,7 +204,7 @@ public function prepareCard(VCardResource $resource): array 'lastmodified' => $resource->updated_at->timestamp, ]; } catch (\Exception $e) { - Log::error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ + Log::channel('database')->error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ 'carddata' => $carddata, 'id' => $resource->id, $e, diff --git a/app/Domains/Contact/DavClient/Jobs/DeleteMultipleVCard.php b/app/Domains/Contact/DavClient/Jobs/DeleteMultipleVCard.php index c968649ecfc..d812be37740 100644 --- a/app/Domains/Contact/DavClient/Jobs/DeleteMultipleVCard.php +++ b/app/Domains/Contact/DavClient/Jobs/DeleteMultipleVCard.php @@ -8,6 +8,7 @@ use Illuminate\Contracts\Queue\ShouldQueue; use Illuminate\Queue\InteractsWithQueue; use Illuminate\Queue\SerializesModels; +use Illuminate\Support\Facades\Log; class DeleteMultipleVCard implements ShouldQueue { @@ -32,6 +33,22 @@ public function handle(): void return; // @codeCoverageIgnore } + Log::shareContext([ + 'addressbook_subscription_id' => $this->subscription->id, + ]); + + try { + $this->run(); + } finally { + Log::flushSharedContext(); + } + } + + /** + * Run the job. + */ + private function run(): void + { $jobs = collect($this->hrefs) ->map(fn (string $href): DeleteVCard => $this->deleteVCard($href)); diff --git a/app/Domains/Contact/DavClient/Jobs/DeleteVCard.php b/app/Domains/Contact/DavClient/Jobs/DeleteVCard.php index 8a19f19ea16..96e5b73ceb8 100644 --- a/app/Domains/Contact/DavClient/Jobs/DeleteVCard.php +++ b/app/Domains/Contact/DavClient/Jobs/DeleteVCard.php @@ -8,6 +8,7 @@ use Illuminate\Contracts\Queue\ShouldQueue; use Illuminate\Queue\InteractsWithQueue; use Illuminate\Queue\SerializesModels; +use Illuminate\Support\Facades\Log; class DeleteVCard implements ShouldQueue { @@ -28,6 +29,24 @@ public function __construct( */ public function handle(): void { + Log::shareContext([ + 'addressbook_subscription_id' => $this->subscription->id, + ]); + + try { + $this->run(); + } finally { + Log::flushSharedContext(); + } + } + + /** + * Run the job. + */ + private function run(): void + { + Log::channel('database')->info("Delete card {$this->uri}"); + $this->subscription->getClient() ->request('DELETE', $this->uri); } diff --git a/app/Domains/Contact/DavClient/Jobs/GetMultipleVCard.php b/app/Domains/Contact/DavClient/Jobs/GetMultipleVCard.php index 11d1e31a460..a7347d9360d 100644 --- a/app/Domains/Contact/DavClient/Jobs/GetMultipleVCard.php +++ b/app/Domains/Contact/DavClient/Jobs/GetMultipleVCard.php @@ -10,6 +10,7 @@ use Illuminate\Queue\InteractsWithQueue; use Illuminate\Queue\SerializesModels; use Illuminate\Support\Arr; +use Illuminate\Support\Facades\Log; use Sabre\CardDAV\Plugin as CardDav; class GetMultipleVCard implements ShouldQueue @@ -35,6 +36,22 @@ public function handle(): void return; // @codeCoverageIgnore } + Log::shareContext([ + 'addressbook_subscription_id' => $this->subscription->id, + ]); + + try { + $this->run(); + } finally { + Log::flushSharedContext(); + } + } + + /** + * Run the job. + */ + private function run(): void + { $data = $this->addressbookMultiget(); $jobs = collect($data) diff --git a/app/Domains/Contact/DavClient/Jobs/GetVCard.php b/app/Domains/Contact/DavClient/Jobs/GetVCard.php index 60bf16a1665..3278c9b79c5 100644 --- a/app/Domains/Contact/DavClient/Jobs/GetVCard.php +++ b/app/Domains/Contact/DavClient/Jobs/GetVCard.php @@ -10,6 +10,7 @@ use Illuminate\Contracts\Queue\ShouldQueue; use Illuminate\Queue\InteractsWithQueue; use Illuminate\Queue\SerializesModels; +use Illuminate\Support\Facades\Log; class GetVCard implements ShouldQueue { @@ -34,6 +35,24 @@ public function handle(): void return; // @codeCoverageIgnore } + Log::shareContext([ + 'addressbook_subscription_id' => $this->subscription->id, + ]); + + try { + $this->run(); + } finally { + Log::flushSharedContext(); + } + } + + /** + * Run the job. + */ + private function run(): void + { + Log::channel('database')->info("Get card {$this->contact->uri}"); + $response = $this->subscription->getClient() ->request('GET', $this->contact->uri); diff --git a/app/Domains/Contact/DavClient/Jobs/PushVCard.php b/app/Domains/Contact/DavClient/Jobs/PushVCard.php index 39a2e6817d6..224c9c29d2b 100644 --- a/app/Domains/Contact/DavClient/Jobs/PushVCard.php +++ b/app/Domains/Contact/DavClient/Jobs/PushVCard.php @@ -45,6 +45,22 @@ public function __construct( * Push VCard data to the distance server. */ public function handle(): void + { + Log::shareContext([ + 'addressbook_subscription_id' => $this->subscription->id, + ]); + + try { + $this->run(); + } finally { + Log::flushSharedContext(); + } + } + + /** + * Run the job. + */ + private function run(): void { $contact = Contact::where('vault_id', $this->subscription->vault_id) ->findOrFail($this->contactId); @@ -64,6 +80,8 @@ public function handle(): void private function pushDistant(int $depth = 1): string { try { + Log::channel('database')->info("Push card {$this->uri}"); + $response = $this->subscription->getClient() ->request('PUT', $this->uri, $this->card, $this->headers()); @@ -75,7 +93,7 @@ private function pushDistant(int $depth = 1): string return $this->pushDistant(--$depth); } else { - Log::error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ + Log::channel('database')->error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ 'body' => $e->response->body(), $e, ]); diff --git a/app/Domains/Contact/DavClient/Jobs/SynchronizeAddressBooks.php b/app/Domains/Contact/DavClient/Jobs/SynchronizeAddressBooks.php index 752549db4f4..a14e0181ba5 100644 --- a/app/Domains/Contact/DavClient/Jobs/SynchronizeAddressBooks.php +++ b/app/Domains/Contact/DavClient/Jobs/SynchronizeAddressBooks.php @@ -16,6 +16,13 @@ class SynchronizeAddressBooks implements ShouldQueue { use Dispatchable, InteractsWithQueue, Queueable, SerializesModels, Localizable; + /** + * The number of times the job may be attempted. + * + * @var int + */ + public $tries = 1; + /** * Create a new job instance. */ @@ -31,7 +38,19 @@ public function __construct( */ public function handle(): void { - $this->withLocale($this->subscription->user->preferredLocale(), fn () => $this->synchronize()); + try { + $logid = $this->subscription->current_logid ?? 0; + $this->subscription->current_logid = $logid + 1; + $this->subscription->save(); + + Log::shareContext([ + 'addressbook_subscription_id' => $this->subscription->id, + ]); + + $this->withLocale($this->subscription->user->preferredLocale(), fn () => $this->synchronize()); + } finally { + Log::flushSharedContext(); + } } /** @@ -39,11 +58,9 @@ public function handle(): void */ private function synchronize(): void { - try { - Log::withContext([ - 'addressbook_subscription_id' => $this->subscription->id, - ]); + Log::channel('database')->info('Synchronize addressbook'); + try { $batchId = app(SynchronizeAddressBook::class)->execute([ 'account_id' => $this->subscription->user->account_id, 'addressbook_subscription_id' => $this->subscription->id, @@ -52,13 +69,13 @@ private function synchronize(): void $this->subscription->last_batch = $batchId; } catch (\Exception $e) { - Log::error(__CLASS__.' '.__FUNCTION__.':'.$e->getMessage(), [$e]); + Log::stack([config('logging.default'), 'database'])->error(__CLASS__.' '.__FUNCTION__.':'.$e->getMessage(), [$e]); $this->fail($e); } finally { $this->subscription->last_synchronized_at = now(); $this->subscription->save(); - Log::withoutContext(); + Log::channel('database')->info('End of synchronization'); } } } diff --git a/app/Domains/Contact/DavClient/Services/SynchronizeAddressBook.php b/app/Domains/Contact/DavClient/Services/SynchronizeAddressBook.php index 35b438c9917..cbe3be202a9 100644 --- a/app/Domains/Contact/DavClient/Services/SynchronizeAddressBook.php +++ b/app/Domains/Contact/DavClient/Services/SynchronizeAddressBook.php @@ -48,7 +48,7 @@ private function synchronize(bool $force): ?string ->withSubscription($this->subscription) ->execute($force); } catch (ClientException $e) { - Log::error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ + Log::channel('database')->error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [ 'body' => $e->hasResponse() ? $e->getResponse()->getBody() : null, $e, ]); diff --git a/app/Domains/Contact/DavClient/Services/Utils/AddressBookGetter.php b/app/Domains/Contact/DavClient/Services/Utils/AddressBookGetter.php index b700f154ccd..e263e2eb769 100644 --- a/app/Domains/Contact/DavClient/Services/Utils/AddressBookGetter.php +++ b/app/Domains/Contact/DavClient/Services/Utils/AddressBookGetter.php @@ -25,7 +25,7 @@ public function execute(): ?array try { return $this->getAddressBookData(); } catch (ClientException $e) { - Log::error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [$e]); + Log::channel('database')->error(__CLASS__.' '.__FUNCTION__.': '.$e->getMessage(), [$e]); throw $e; } } diff --git a/app/Domains/Contact/DavClient/Services/Utils/AddressBookSynchronizer.php b/app/Domains/Contact/DavClient/Services/Utils/AddressBookSynchronizer.php index d2ee508546f..f1d41560bd5 100644 --- a/app/Domains/Contact/DavClient/Services/Utils/AddressBookSynchronizer.php +++ b/app/Domains/Contact/DavClient/Services/Utils/AddressBookSynchronizer.php @@ -230,7 +230,7 @@ private function callSyncCollection(): array $this->subscription->save(); } } catch (RequestException $e) { - Log::error(__CLASS__.' '.__FUNCTION__.':'.$e->getMessage(), [$e]); + Log::channel('database')->error(__CLASS__.' '.__FUNCTION__.':'.$e->getMessage(), [$e]); $collection = []; $this->subscription->distant_sync_token = null; $this->subscription->save(); diff --git a/app/Domains/Contact/DavClient/Services/Utils/Dav/DavClient.php b/app/Domains/Contact/DavClient/Services/Utils/Dav/DavClient.php index 89e61764e29..37dd6639146 100644 --- a/app/Domains/Contact/DavClient/Services/Utils/Dav/DavClient.php +++ b/app/Domains/Contact/DavClient/Services/Utils/Dav/DavClient.php @@ -473,7 +473,7 @@ public function request(string $method, string $url = '', mixed $body = null, ar $url = Str::startsWith($url, 'http') ? $url : $this->path($url); - Log::debug(__CLASS__.' '.__FUNCTION__.'[request]: '.$method.' '.$url, [ + Log::channel('database')->debug(__CLASS__.' '.__FUNCTION__.'[request]: '.$method.' '.$url, [ 'body' => $body, 'headers' => $headers, 'options' => $options, @@ -482,13 +482,13 @@ public function request(string $method, string $url = '', mixed $body = null, ar $response = $request ->send($method, $url, $options) ->throw(function (Response $response) use ($method, $url) { - Log::debug(__CLASS__.' '.__FUNCTION__.'[error]: '.$method.' '.$url.' '.$response->status(), [ + Log::channel('database')->debug(__CLASS__.' '.__FUNCTION__.'[error]: '.$method.' '.$url.' '.$response->status(), [ 'body' => $response->body(), 'headers' => $response->headers(), ]); }); - Log::debug(__CLASS__.' '.__FUNCTION__.'[response]: '.$method.' '.$url.' '.$response->status(), [ + Log::channel('database')->debug(__CLASS__.' '.__FUNCTION__.'[response]: '.$method.' '.$url.' '.$response->status(), [ 'body' => $response->body(), 'headers' => $response->headers(), ]); @@ -557,7 +557,7 @@ private static function addElementNS(\DOMDocument $dom, ?string $namespace, stri /** * Create a new Element and add it as root's child. */ - private static function addElement(\DOMDocument $dom, \DOMNode $root, string $name, string $value = null): \DOMNode + private static function addElement(\DOMDocument $dom, \DOMNode $root, string $name, string $value = ''): \DOMNode { return $root->appendChild($dom->createElement($name, $value)); } diff --git a/app/Logging/CleanLogs.php b/app/Logging/CleanLogs.php new file mode 100644 index 00000000000..0373f2f0999 --- /dev/null +++ b/app/Logging/CleanLogs.php @@ -0,0 +1,19 @@ +subDays(15))->delete(); + } +} diff --git a/app/Logging/LoggingHandler.php b/app/Logging/LoggingHandler.php new file mode 100644 index 00000000000..1f0e8fbe508 --- /dev/null +++ b/app/Logging/LoggingHandler.php @@ -0,0 +1,43 @@ +context; + + try { + if (isset($context['addressbook_subscription_id'])) { + $subscription = AddressBookSubscription::findOrFail($context['addressbook_subscription_id']); + $this->logAddressBookSubscription($record, $subscription); + } + } catch (ModelNotFoundException) { + // ignore log + } + } + + private function logAddressBookSubscription(LogRecord $record, AddressBookSubscription $subscription): void + { + Log::create([ + 'group_id' => $subscription->current_logid ?? 0, + 'level' => $record->level->value, + 'level_name' => $record->level->getName(), + 'channel' => $record->channel, + 'message' => $record->message, + 'context' => json_encode($record->context), + 'extra' => json_encode($record->extra), + 'formatted' => (string) $record->formatted, + 'logged_at' => $record->datetime, + 'loggable_type' => AddressBookSubscription::class, + 'loggable_id' => $subscription->id, + ]); + } +} diff --git a/app/Models/AddressBookSubscription.php b/app/Models/AddressBookSubscription.php index d5392e63723..78260d22f83 100644 --- a/app/Models/AddressBookSubscription.php +++ b/app/Models/AddressBookSubscription.php @@ -9,6 +9,7 @@ use Illuminate\Database\Eloquent\Factories\HasFactory; use Illuminate\Database\Eloquent\Model; use Illuminate\Database\Eloquent\Relations\BelongsTo; +use Illuminate\Database\Eloquent\Relations\MorphMany; class AddressBookSubscription extends Model { @@ -39,6 +40,7 @@ class AddressBookSubscription extends Model 'password', 'sync_way', 'distant_sync_token', + 'current_logid', 'frequency', 'last_synchronized_at', 'active', @@ -62,6 +64,7 @@ class AddressBookSubscription extends Model 'last_synchronized_at' => 'datetime', 'active' => 'boolean', 'capabilities' => 'array', + 'current_logid' => 'integer', ]; /** @@ -105,6 +108,14 @@ public function localSyncToken(): BelongsTo return $this->belongsTo(SyncToken::class); } + /** + * Get the subscription's logs. + */ + public function logs(): MorphMany + { + return $this->morphMany(Log::class, 'loggable'); + } + /** * Get password. * diff --git a/app/Models/Log.php b/app/Models/Log.php new file mode 100644 index 00000000000..716bda2d106 --- /dev/null +++ b/app/Models/Log.php @@ -0,0 +1,50 @@ + + */ + protected $fillable = [ + 'group_id', + 'level', + 'level_name', + 'channel', + 'message', + 'context', + 'extra', + 'formatted', + 'logged_at', + 'loggable_type', + 'loggable_id', + ]; + + /** + * The attributes that should be cast. + * + * @var array + */ + protected $casts = [ + 'context' => 'json', + 'extra' => 'json', + 'logged_at' => 'datetime', + ]; + + /** + * Get the loggable entry. + */ + public function loggable(): MorphTo + { + return $this->morphTo(); + } +} diff --git a/config/logging.php b/config/logging.php index 35b312d95fb..e86879171a3 100644 --- a/config/logging.php +++ b/config/logging.php @@ -119,6 +119,12 @@ 'emergency' => [ 'path' => storage_path('logs/laravel.log'), ], + + 'database' => [ + 'driver' => 'monolog', + 'handler' => App\Logging\LoggingHandler::class, + 'level' => 'debug', + ], ], ]; diff --git a/database/migrations/2023_07_03_230200_create_addressbook_subscription.php b/database/migrations/2023_07_03_230200_create_addressbook_subscription.php index c17f20856e2..6e5010afd49 100644 --- a/database/migrations/2023_07_03_230200_create_addressbook_subscription.php +++ b/database/migrations/2023_07_03_230200_create_addressbook_subscription.php @@ -29,6 +29,7 @@ public function up() $table->string('capabilities', 2048); $table->string('distant_sync_token', 512)->nullable(); $table->string('last_batch')->nullable(); + $table->unsignedBigInteger('current_logid')->nullable(); $table->foreignIdFor(SyncToken::class)->nullable()->constrained()->nullOnDelete(); $table->smallInteger('frequency')->default(180); // 3 hours $table->timestamp('last_synchronized_at', 0)->nullable(); diff --git a/database/migrations/2023_08_30_202650_create_logs_table.php b/database/migrations/2023_08_30_202650_create_logs_table.php new file mode 100644 index 00000000000..d19fa093df4 --- /dev/null +++ b/database/migrations/2023_08_30_202650_create_logs_table.php @@ -0,0 +1,37 @@ +id(); + $table->unsignedBigInteger('group_id')->index(); + $table->string('level')->index(); + $table->string('level_name'); + $table->string('channel')->index(); + $table->longText('message'); + $table->longText('context'); + $table->longText('extra'); + $table->longText('formatted'); + $table->morphs('loggable'); + $table->dateTime('logged_at'); + $table->timestamps(); + }); + } + + /** + * Reverse the migrations. + */ + public function down(): void + { + Schema::dropIfExists('logs'); + } +}; diff --git a/database/migrations/2023_08_30_202650_fix_addressbook_currentlogid.php b/database/migrations/2023_08_30_202650_fix_addressbook_currentlogid.php new file mode 100644 index 00000000000..ac4a96a14ff --- /dev/null +++ b/database/migrations/2023_08_30_202650_fix_addressbook_currentlogid.php @@ -0,0 +1,20 @@ +unsignedBigInteger('current_logid')->after('last_batch')->nullable(); + }); + } + } +};