From 5bf7785c86e1f3a11aaf62dd69272b78c869ee26 Mon Sep 17 00:00:00 2001 From: Kevin Date: Wed, 23 Sep 2026 15:41:06 +0000 Subject: [PATCH] Logs: Kanal userabo ersetzt, Log-Mails ueber die Queue, weniger Rauschen Log-Analyse 26.08. (P1-1, P2-1, P2-7, P2-8): - MyLog schrieb in den nicht definierten Kanal userabo (109 EMERGENCY- Eintraege, laravel.log rotierte nicht mehr); jetzt abo_order. - MyLog verschickt die Benachrichtigung ueber die Queue, ein Mailfehler bricht den Zahllauf nicht mehr ab. MailLog sammelt Nutzer, User-Agent und Zeit beim Erzeugen ein, weil der Worker keinen Request hat. - Abgelehnte OAuth-Anfragen (falscher grant_type) werden als Warnung geloggt statt als Fehler gemailt. - payments:check-accounts loggt je Berater nur noch auf debug und schreibt am Ende eine Zusammenfassung (geprueft, versendet, uebersprungen). Co-Authored-By: Claude Opus 5.5 (1M context) --- app/Console/Commands/CheckPaymentsAccount.php | 37 ++++++++++++++----- .../Commands/RetryFailedPaypalAbos.php | 2 +- app/Console/Commands/UserMakeAboOrder.php | 2 +- app/Exceptions/Handler.php | 15 ++++++++ app/Mail/MailLog.php | 35 +++++++++++++----- app/Services/AboRetryPaymentService.php | 2 +- app/Services/MyLog.php | 16 ++++++-- tests/Feature/MyLogNotificationTest.php | 33 +++++++++++++++++ 8 files changed, 116 insertions(+), 26 deletions(-) create mode 100644 tests/Feature/MyLogNotificationTest.php diff --git a/app/Console/Commands/CheckPaymentsAccount.php b/app/Console/Commands/CheckPaymentsAccount.php index a9a8ee59..be3f8889 100644 --- a/app/Console/Commands/CheckPaymentsAccount.php +++ b/app/Console/Commands/CheckPaymentsAccount.php @@ -32,6 +32,11 @@ class CheckPaymentsAccount extends Command /** * Execute the console command. */ + /** Zaehler fuer die Zusammenfassung am Ende des Laufs. */ + private int $remindersSent = 0; + + private int $remindersSkipped = 0; + public function handle() { Log::channel('cron')->info('COMMAND [payments:check-accounts] started.'); @@ -39,7 +44,7 @@ class CheckPaymentsAccount extends Command // Die Logik wurde 1:1 aus der checkPaymentsAccounts-Methode übernommen $renewalDate = Carbon::now()->modify('+'.(config('mivita.remind_first_days') + 1).' days'); - Log::channel('cron')->info('Erneuerungsdatum für Zahlungen: '.$renewalDate->format('Y-m-d H:i:s')); + Log::channel('cron')->debug('Erneuerungsdatum für Zahlungen: '.$renewalDate->format('Y-m-d H:i:s')); $users = User::where('payment_account', '!=', null) ->where('active', '=', 1) @@ -50,13 +55,22 @@ class CheckPaymentsAccount extends Command Log::channel('cron')->info('Found '.$users->count().' users for payment reminders.'); $this->info('Found '.$users->count().' users for payment reminders.'); + $this->remindersSent = 0; + $this->remindersSkipped = 0; + foreach ($users as $user) { - Log::channel('cron')->info('Prüfe Zahlungserinnerungen für Benutzer: '.$user->email); + Log::channel('cron')->debug('Prüfe Zahlungserinnerungen für Benutzer: '.$user->email); $this->checkReminderPayments($user); } - Log::channel('cron')->info('COMMAND [payments:check-accounts] finished.'); - $this->info('COMMAND [payments:check-accounts] finished.'); + $summary = sprintf( + 'COMMAND [payments:check-accounts] finished. Geprüft: %d, versendet: %d, übersprungen: %d.', + $users->count(), + $this->remindersSent, + $this->remindersSkipped + ); + Log::channel('cron')->info($summary); + $this->info($summary); return 0; // Success } @@ -79,7 +93,7 @@ class CheckPaymentsAccount extends Command { // 35 reminder_deaktiv, 36 reminder_deaktiv_sepa if (! $user->isActiveAccount()) { - Log::channel('cron')->info('Inaktives Konto für Benutzer: '.$user->email); + Log::channel('cron')->debug('Inaktives Konto für Benutzer: '.$user->email); $this->checkIsReminderSend($user, 35); return; @@ -87,7 +101,7 @@ class CheckPaymentsAccount extends Command // 34 reminder_last if ($user->daysActiveAccount() <= config('mivita.remind_last_days')) { - Log::channel('cron')->info('Letzte Erinnerung für Benutzer: '.$user->email.' (Tage aktiv: '.$user->daysActiveAccount().')'); + Log::channel('cron')->debug('Letzte Erinnerung für Benutzer: '.$user->email.' (Tage aktiv: '.$user->daysActiveAccount().')'); $this->checkIsReminderSend($user, 34); return; @@ -95,7 +109,7 @@ class CheckPaymentsAccount extends Command // 33 reminder_sec if ($user->daysActiveAccount() <= config('mivita.remind_sec_days')) { - Log::channel('cron')->info('Zweite Erinnerung für Benutzer: '.$user->email.' (Tage aktiv: '.$user->daysActiveAccount().')'); + Log::channel('cron')->debug('Zweite Erinnerung für Benutzer: '.$user->email.' (Tage aktiv: '.$user->daysActiveAccount().')'); $this->checkIsReminderSend($user, 33); return; @@ -103,7 +117,7 @@ class CheckPaymentsAccount extends Command // 31 reminder_first if ($user->daysActiveAccount() > config('mivita.remind_sec_days')) { - Log::channel('cron')->info('Erste Erinnerung für Benutzer: '.$user->email.' (Tage aktiv: '.$user->daysActiveAccount().')'); + Log::channel('cron')->debug('Erste Erinnerung für Benutzer: '.$user->email.' (Tage aktiv: '.$user->daysActiveAccount().')'); $this->checkIsReminderSend($user, 31); return; @@ -127,12 +141,15 @@ class CheckPaymentsAccount extends Command ->first(); if ($isSend) { - Log::channel('cron')->info('Erinnerung bereits gesendet für Benutzer: '.$user->email.' (Status: '.$status.')'); + $this->remindersSkipped++; + Log::channel('cron')->debug('Erinnerung bereits gesendet für Benutzer: '.$user->email.' (Status: '.$status.')'); return true; } - Log::channel('cron')->info('Sende neue Erinnerung für Benutzer: '.$user->email.' (Status: '.$status.')'); + $this->remindersSent++; + + Log::channel('cron')->debug('Sende neue Erinnerung für Benutzer: '.$user->email.' (Status: '.$status.')'); $referenz = $this->sendReminderMail($user, $status); UserHistory::create([ diff --git a/app/Console/Commands/RetryFailedPaypalAbos.php b/app/Console/Commands/RetryFailedPaypalAbos.php index 95b0c1c2..fff13d24 100644 --- a/app/Console/Commands/RetryFailedPaypalAbos.php +++ b/app/Console/Commands/RetryFailedPaypalAbos.php @@ -207,7 +207,7 @@ class RetryFailedPaypalAbos extends Command $this->error(" Zahlung FEHLGESCHLAGEN für Abo #{$userAbo->id}: [{$errorCode}] {$errorMsg}"); MyLog::writeLog( - 'userabo', + 'abo_order', 'error', 'Error:RetryPaypal RetryFailedPaypalAbos / makePayment Error', $response diff --git a/app/Console/Commands/UserMakeAboOrder.php b/app/Console/Commands/UserMakeAboOrder.php index 43d66d68..c882c236 100644 --- a/app/Console/Commands/UserMakeAboOrder.php +++ b/app/Console/Commands/UserMakeAboOrder.php @@ -291,7 +291,7 @@ class UserMakeAboOrder extends Command $this->error("Zahlungsfehler für Abo {$userAbo->id}"); MyLog::writeLog( - 'userabo', + 'abo_order', 'error', 'Error:3002 App\Console\Commands\UserMakeAboOrder::makeOrder / makePayment Error response', $response diff --git a/app/Exceptions/Handler.php b/app/Exceptions/Handler.php index 2a001fde..d5c716f5 100644 --- a/app/Exceptions/Handler.php +++ b/app/Exceptions/Handler.php @@ -7,6 +7,7 @@ use Illuminate\Auth\AuthenticationException; use Illuminate\Foundation\Exceptions\Handler as ExceptionHandler; use Illuminate\Support\Facades\Log; use Illuminate\Support\Facades\Mail; +use Laravel\Passport\Exceptions\OAuthServerException; use Symfony\Component\ErrorHandler\ErrorRenderer\HtmlErrorRenderer; use Symfony\Component\ErrorHandler\Exception\FlattenException; use Symfony\Component\HttpFoundation\Response; @@ -45,6 +46,20 @@ class Handler extends ExceptionHandler */ public function report(Throwable $exception) { + /* + * OAuth-Fehler entstehen durch den aufrufenden Client (falscher grant_type, + * ungueltige Credentials) und werden vom OAuth-Server bereits sauber als 4xx + * beantwortet. Sie als ERROR zu melden und zu mailen erzeugt nur Rauschen. + */ + if ($exception instanceof OAuthServerException) { + Log::warning('OAuth-Anfrage abgelehnt', [ + 'message' => $exception->getMessage(), + 'grant_type' => request()->input('grant_type'), + 'client_id' => request()->input('client_id'), + ]); + + return; + } if ($this->shouldReport($exception)) { $this->sendEmail($exception); diff --git a/app/Mail/MailLog.php b/app/Mail/MailLog.php index 3e60c982..a7d03c04 100644 --- a/app/Mail/MailLog.php +++ b/app/Mail/MailLog.php @@ -3,10 +3,11 @@ namespace App\Mail; use Illuminate\Bus\Queueable; +use Illuminate\Contracts\Queue\ShouldQueue; use Illuminate\Mail\Mailable; use Illuminate\Queue\SerializesModels; -class MailLog extends Mailable +class MailLog extends Mailable implements ShouldQueue { use Queueable, SerializesModels; @@ -18,6 +19,17 @@ class MailLog extends Mailable protected $data; + /** + * Request-Kontext wird beim Erzeugen eingesammelt, nicht erst in build(). + * Die Mail wird in die Queue gelegt und im Worker gibt es weder eine + * angemeldete Session noch den urspruenglichen Request. + */ + protected $origin; + + protected $userAgent; + + protected $occurredAt; + public $subject; public function __construct($channel, $context, $message, $data) @@ -27,7 +39,11 @@ class MailLog extends Mailable $this->message = $message; $this->data = $data; $this->subject = 'mivita Log'; - + $this->origin = \Auth::check() + ? \Auth::user()->id.' | '.\Auth::user()->email + : null; + $this->userAgent = request()->header('User-Agent'); + $this->occurredAt = now()->format('d.m.Y H:i'); } public function build() @@ -35,24 +51,23 @@ class MailLog extends Mailable $title = 'Log: '.$this->channel.' '.$this->context; // make Data readable - $this->data = json_encode($this->data, JSON_PRETTY_PRINT); - $content = ''; + $data = json_encode($this->data, JSON_PRETTY_PRINT); - $content .= "\n"; + $content = "\n"; $content .= 'Channel: '.$this->channel."\n"; $content .= 'Context: '.$this->context."\n"; - if (\Auth::check()) { - $content .= 'From User: '.\Auth::user()->id.' | '.\Auth::user()->email."\n"; + if ($this->origin) { + $content .= 'From User: '.$this->origin."\n"; } $content .= "\n"; $content .= 'Message: '.$this->message."\n"; $content .= "\n"; - $content .= 'Data: '.$this->data."\n"; + $content .= 'Data: '.$data."\n"; $content .= "\n"; $content .= "\n"; - $content .= 'Time: '.now()->format('d.m.Y H:i'); + $content .= 'Time: '.$this->occurredAt; $content .= "\n"; - $content .= request()->header('User-Agent'); + $content .= $this->userAgent; return $this->view('emails.sys')->with([ 'title' => $title, diff --git a/app/Services/AboRetryPaymentService.php b/app/Services/AboRetryPaymentService.php index 04845894..1ab16e15 100644 --- a/app/Services/AboRetryPaymentService.php +++ b/app/Services/AboRetryPaymentService.php @@ -201,7 +201,7 @@ class AboRetryPaymentService ]); MyLog::writeLog( - 'userabo', + 'abo_order', 'error', 'Error:AboRetryPaymentService::retry / makePayment Error', $response diff --git a/app/Services/MyLog.php b/app/Services/MyLog.php index a2cc9597..c30c3335 100644 --- a/app/Services/MyLog.php +++ b/app/Services/MyLog.php @@ -9,7 +9,6 @@ class MyLog { public static function writeLog($channel = 'payment', $context = 'error', $message = '', $data = [], $mail = true) { - switch ($context) { case 'notice': \Log::channel($channel)->notice($message.' : '.json_encode($data)); @@ -24,8 +23,19 @@ class MyLog \Log::channel($channel)->error($message.' : '.json_encode($data)); break; } - if ($mail) { - Mail::to(config('app.exception_mail'))->send(new MailLog($channel, $context, $message, $data)); + + if (! $mail) { + return; + } + + // Die Benachrichtigung laeuft ueber die Queue: der Zahllauf darf nicht auf + // den SMTP-Roundtrip warten und ein Mailfehler darf ihn nicht abbrechen. + try { + Mail::to(config('app.exception_mail'))->queue(new MailLog($channel, $context, $message, $data)); + } catch (\Throwable $e) { + \Log::channel($channel)->warning('MyLog: Benachrichtigungsmail konnte nicht zugestellt werden', [ + 'error' => $e->getMessage(), + ]); } } } diff --git a/tests/Feature/MyLogNotificationTest.php b/tests/Feature/MyLogNotificationTest.php new file mode 100644 index 00000000..3103bc0e --- /dev/null +++ b/tests/Feature/MyLogNotificationTest.php @@ -0,0 +1,33 @@ + '5']); + + Mail::assertQueued(MailLog::class); + Mail::assertNothingSent(); +}); + +it('does not send a notification when the caller opts out', function () { + Mail::fake(); + + MyLog::writeLog('abo_order', 'error', 'Testfehler', ['errorcode' => '5'], false); + + Mail::assertNothingQueued(); +}); + +it('does not let a failing notification abort the caller', function () { + Mail::shouldReceive('to')->once()->andThrow(new RuntimeException('SMTP down')); + + MyLog::writeLog('abo_order', 'error', 'Testfehler', ['errorcode' => '5']); + + expect(true)->toBeTrue(); +});