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) <noreply@anthropic.com>

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([

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

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

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

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,

app/Services/AboRetryPaymentService.php

@@ -201,7 +201,7 @@ class AboRetryPaymentService
         ]);
 
         MyLog::writeLog(
-            'userabo',
+            'abo_order',
             'error',
             'Error:AboRetryPaymentService::retry / makePayment Error',
             $response

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(),
+            ]);
         }
     }
 }

tests/Feature/MyLogNotificationTest.php

@@ -0,0 +1,33 @@
+<?php
+
+use App\Mail\MailLog;
+use App\Services\MyLog;
+use Illuminate\Support\Facades\Mail;
+use Tests\TestCase;
+
+uses(TestCase::class);
+
+it('queues the notification instead of sending it synchronously', function () {
+    Mail::fake();
+
+    MyLog::writeLog('abo_order', 'error', 'Testfehler', ['errorcode' => '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();
+});