1.新增游戏实时对局日志，方便排查问题

2026-05-29 14:46:57 +08:00
parent 4bd332a6ff
commit 2a5132d70f
4 changed files with 398 additions and 1 deletions
--- a/app/common/service/GameLiveService.php
+++ b/app/common/service/GameLiveService.php
@@ -322,6 +322,7 @@ final class GameLiveService
    {
        self::finalizePayoutGrace();
        self::tickAutoDraw();
+        GameLiveStuckDiagnostic::inspectAfterRecovery();
    }

    public static function buildSnapshot(?int $recordId = null): array
@@ -847,6 +848,12 @@ final class GameLiveService
        $lock = GameHotDataLock::tryAcquireWithWait(GameHotDataLock::TYPE_GAME_RECORD, (string) $id, 2000);
        if (!$lock['acquired']) {
            Log::warning('finalizePayoutGrace: lock not acquired', ['record_id' => $id]);
+            GameLiveStuckDiagnostic::report('payout_finalize_lock', [
+                'record_id' => $id,
+                'period_no' => is_string($row['period_no'] ?? null) ? (string) $row['period_no'] : '',
+                'phase_label' => '派彩结单 finalizePayoutGrace 拿不到 Redis 行锁',
+                'hint' => '键名 dfw:v1:lock:mut:gr:' . $id . '；2s 内未拿到锁，每秒重试',
+            ], $id);

            return;
        }
@@ -961,6 +968,8 @@ final class GameLiveService
        }

        $out = self::drawResult($rid, null);
+        $periodNo = is_string($record['period_no'] ?? null) ? (string) $record['period_no'] : '';
+        GameLiveStuckDiagnostic::noteDrawAttempt($rid, $periodNo, $out);
        if ($out['ok'] ?? false) {
            return;
        }
@@ -972,7 +981,7 @@ final class GameLiveService
        ) {
            Log::warning('tickAutoDraw: drawResult failed', [
                'record_id' => $rid,
-                'period_no' => $record['period_no'] ?? '',
+                'period_no' => $periodNo,
                'msg' => $msg,
            ]);
        }
--- a/app/common/service/GameLiveStuckDiagnostic.php
+++ b/app/common/service/GameLiveStuckDiagnostic.php
@@ -0,0 +1,364 @@
+<?php
+
+declare(strict_types=1);
+
+namespace app\common\service;
+
+use support\Log;
+use support\Redis;
+use support\think\Db;
+use Throwable;
+
+/**
+ * 游戏实时对局「卡住」诊断：独立日志通道 game_live_stuck，便于 grep 排查。
+ *
+ * 写入：runtime/logs/game-live-stuck-YYYY-MM-DD.log
+ * 调用：Log::channel('game_live_stuck')->warning(...)
+ */
+final class GameLiveStuckDiagnostic
+{
+    private const LOG_CHANNEL = 'game_live_stuck';
+
+    /** 同 phase+期 30 秒内不重复刷日志 */
+    private const THROTTLE_KEY_PREFIX = 'dfw:v1:log:game_live_stuck:';
+    private const THROTTLE_SECONDS = 30;
+
+    private const LAST_PHASE_KEY_PREFIX = 'dfw:v1:log:game_live_stuck:last:';
+
+    /** @var array{record_id?:int,period_no?:string,ok?:bool,msg?:string,at?:int}|null */
+    private static ?array $lastDrawAttempt = null;
+
+    private const STATUS_LABELS = [
+        0 => '下注中',
+        1 => '已封盘',
+        2 => '算票中(遗留)',
+        3 => '派彩中',
+        4 => '已结束',
+        5 => '已作废',
+    ];
+
+    /**
+     * 记录最近一次自动开奖尝试（tickAutoDraw → drawResult）。
+     *
+     * @param array{ok?:bool,msg?:string} $out
+     */
+    public static function noteDrawAttempt(int $recordId, string $periodNo, array $out): void
+    {
+        if ($recordId <= 0) {
+            return;
+        }
+        self::$lastDrawAttempt = [
+            'record_id' => $recordId,
+            'period_no' => $periodNo,
+            'ok' => (bool) ($out['ok'] ?? false),
+            'msg' => is_string($out['msg'] ?? null) ? (string) $out['msg'] : '',
+            'at' => time(),
+        ];
+        if ($out['ok'] ?? false) {
+            return;
+        }
+        $msg = is_string($out['msg'] ?? null) ? (string) $out['msg'] : '';
+        if ($msg === '') {
+            return;
+        }
+        self::emit('draw_attempt_failed', [
+            'record_id' => $recordId,
+            'period_no' => $periodNo,
+            'draw_ok' => false,
+            'draw_msg' => $msg,
+            'phase_label' => '自动开奖 drawResult 返回失败',
+            'hint' => self::hintForDrawMessage($msg),
+        ], $recordId);
+    }
+
+    /**
+     * 在 recoverLiveRoundState（结单 + 自动开奖）之后巡检当前进行中局。
+     */
+    public static function inspectAfterRecovery(): void
+    {
+        try {
+            $row = Db::name('game_record')
+                ->whereIn('status', [0, 1, 2, 3])
+                ->order('id', 'desc')
+                ->find();
+            if (!is_array($row)) {
+                self::maybeLogRecovered();
+                return;
+            }
+            $recordId = filter_var($row['id'] ?? 0, FILTER_VALIDATE_INT);
+            if ($recordId === false || $recordId <= 0) {
+                return;
+            }
+            $diagnosis = self::diagnoseRow($row);
+            if ($diagnosis === null) {
+                self::maybeLogRecovered($recordId);
+                return;
+            }
+            self::rememberLastPhase($recordId, $diagnosis['phase']);
+            self::emit($diagnosis['phase'], $diagnosis['context'], $recordId);
+        } catch (Throwable $e) {
+            self::emit('inspect_error', [
+                'phase_label' => '卡住巡检异常',
+                'error' => $e->getMessage(),
+                'hint' => '检查数据库与 Redis 连接',
+            ], 0);
+        }
+    }
+
+    /**
+     * 即时上报（如 finalize 拿不到锁），仍受 30s 节流。
+     *
+     * @param array<string, mixed> $context
+     */
+    public static function report(string $phase, array $context, int $recordId = 0): void
+    {
+        $context['phase_label'] = $context['phase_label'] ?? self::phaseLabel($phase);
+        self::emit($phase, $context, $recordId);
+    }
+
+    /**
+     * @param array<string, mixed> $row
+     * @return null|array{phase: string, context: array<string, mixed>}
+     */
+    private static function diagnoseRow(array $row): ?array
+    {
+        $recordId = filter_var($row['id'] ?? 0, FILTER_VALIDATE_INT);
+        if ($recordId === false || $recordId <= 0) {
+            return null;
+        }
+        $periodNo = is_string($row['period_no'] ?? null) ? (string) $row['period_no'] : '';
+        $status = filter_var($row['status'] ?? -1, FILTER_VALIDATE_INT);
+        if ($status === false) {
+            $status = -1;
+        }
+        $periodStartAt = filter_var($row['period_start_at'] ?? 0, FILTER_VALIDATE_INT);
+        if ($periodStartAt === false) {
+            $periodStartAt = 0;
+        }
+        $now = time();
+        $elapsed = $periodStartAt > 0 ? max(0, $now - $periodStartAt) : 0;
+        $periodSeconds = self::getConfigInt('period_seconds', 30);
+        $payoutSeconds = self::getConfigInt('payout_seconds', 3);
+        $abnormalAfter = $periodSeconds + $payoutSeconds + 10;
+
+        $resultNumber = filter_var($row['result_number'] ?? 0, FILTER_VALIDATE_INT);
+        if ($resultNumber === false) {
+            $resultNumber = 0;
+        }
+        $payoutUntil = filter_var($row['payout_until'] ?? 0, FILTER_VALIDATE_INT);
+        if ($payoutUntil === false) {
+            $payoutUntil = 0;
+        }
+
+        $pendingBetCount = (int) Db::name('bet_order')
+            ->where('period_id', $recordId)
+            ->where('status', GameBetSettleService::PLAY_STATUS_PENDING_DRAW)
+            ->count();
+
+        $base = [
+            'record_id' => $recordId,
+            'period_no' => $periodNo,
+            'db_status' => $status,
+            'db_status_label' => self::STATUS_LABELS[$status] ?? '未知',
+            'elapsed_sec' => $elapsed,
+            'period_seconds' => $periodSeconds,
+            'payout_seconds' => $payoutSeconds,
+            'result_number' => $resultNumber > 0 ? $resultNumber : null,
+            'payout_until' => $payoutUntil > 0 ? $payoutUntil : null,
+            'payout_until_at' => $payoutUntil > 0 ? date('Y-m-d H:i:s', $payoutUntil) : null,
+            'ai_locked_number' => filter_var($row['ai_locked_number'] ?? 0, FILTER_VALIDATE_INT) ?: null,
+            'pending_draw_number' => filter_var($row['pending_draw_number'] ?? 0, FILTER_VALIDATE_INT) ?: null,
+            'pending_bet_count' => $pendingBetCount,
+            'runtime_enabled' => GameRecordService::isLiveRuntimeEnabled(),
+            'auto_create_enabled' => GameRecordService::isAutoCreateEnabled(),
+            'last_draw_attempt' => self::$lastDrawAttempt,
+            'server_time' => date('Y-m-d H:i:s', $now),
+        ];
+
+        if ($status === 2) {
+            return [
+                'phase' => 'legacy_settling_status',
+                'context' => array_merge($base, [
+                    'phase_label' => '遗留 status=2 算票中，自动开奖不会处理',
+                    'stuck_sec' => $elapsed,
+                    'hint' => '将 game_record.status 改为 0/1 或 3/4，或重启后依赖启动自愈；检查是否有人工改库',
+                ]),
+            ];
+        }
+
+        if (in_array($status, [0, 1], true)) {
+            if ($elapsed < $periodSeconds) {
+                return null;
+            }
+            $stuckSec = $elapsed - $periodSeconds;
+            if ($elapsed > $abnormalAfter && $resultNumber <= 0) {
+                return [
+                    'phase' => 'await_abnormal_void',
+                    'context' => array_merge($base, [
+                        'phase_label' => '已超异常作废阈值但仍未开奖/作废',
+                        'stuck_sec' => $stuckSec,
+                        'abnormal_after_sec' => $abnormalAfter,
+                        'hint' => '应触发 markAbnormalAndRefundOnStartup；检查 gameLiveTicker 与 Redis 锁 dfw:v1:lock:mut:gr:' . $recordId,
+                    ]),
+                ];
+            }
+
+            return [
+                'phase' => 'await_auto_draw',
+                'context' => array_merge($base, [
+                    'phase_label' => '下注/封盘期已过开奖时刻但未进入派彩',
+                    'stuck_sec' => $stuckSec,
+                    'hint' => '确认 gameLiveTicker 进程在跑；查 Redis 锁与 webman 日志 tickAutoDraw；HTTP snapshot 不会触发开奖',
+                ]),
+            ];
+        }
+
+        if ($status === 3) {
+            $payoutExpired = $payoutUntil <= 0 || $payoutUntil <= $now;
+            if ($payoutExpired) {
+                return [
+                    'phase' => 'payout_finalize_pending',
+                    'context' => array_merge($base, [
+                        'phase_label' => '派彩宽限期已结束但未结单(status→4)',
+                        'stuck_sec' => $payoutUntil > 0 ? max(0, $now - $payoutUntil) : $elapsed,
+                        'hint' => 'finalizePayoutGrace 未成功；查 finalizePayoutGrace: lock not acquired 与 Redis 锁',
+                    ]),
+                ];
+            }
+            if ($pendingBetCount > 0 && $resultNumber > 0) {
+                return [
+                    'phase' => 'settle_pending',
+                    'context' => array_merge($base, [
+                        'phase_label' => '已开奖但仍有待结算注单',
+                        'stuck_sec' => max(0, $now - ($periodStartAt + $periodSeconds)),
+                        'hint' => '查 drawResult settle after lock failed；必要时补偿结算或重推',
+                    ]),
+                ];
+            }
+            if ($payoutUntil > $now && $pendingBetCount > 0 && $resultNumber <= 0) {
+                return [
+                    'phase' => 'payout_without_result',
+                    'context' => array_merge($base, [
+                        'phase_label' => '派彩中但无有效开奖号码',
+                        'stuck_sec' => max(0, $now - ($periodStartAt + $periodSeconds)),
+                        'hint' => '数据异常：status=3 但 result_number 无效，需人工核对 game_record',
+                    ]),
+                ];
+            }
+        }
+
+        return null;
+    }
+
+    /**
+     * @param array<string, mixed> $context
+     */
+    private static function emit(string $phase, array $context, int $recordId): void
+    {
+        $signature = $phase . ':' . ($recordId > 0 ? (string) $recordId : 'global');
+        if (!self::shouldEmit($signature)) {
+            return;
+        }
+        $payload = array_merge([
+            'phase' => $phase,
+            'phase_label' => self::phaseLabel($phase),
+        ], $context);
+        Log::channel(self::LOG_CHANNEL)->warning('game_live_stuck', $payload);
+    }
+
+    private static function shouldEmit(string $signature): bool
+    {
+        try {
+            $key = self::THROTTLE_KEY_PREFIX . $signature;
+            $ok = Redis::set($key, '1', ['nx', 'ex' => self::THROTTLE_SECONDS]);
+
+            return $ok !== false && $ok !== null;
+        } catch (Throwable) {
+            return true;
+        }
+    }
+
+    private static function rememberLastPhase(int $recordId, string $phase): void
+    {
+        try {
+            Redis::setEx(self::LAST_PHASE_KEY_PREFIX . $recordId, 3600, $phase);
+        } catch (Throwable) {
+        }
+    }
+
+    private static function maybeLogRecovered(int $recordId = 0): void
+    {
+        if ($recordId <= 0) {
+            return;
+        }
+        try {
+            $key = self::LAST_PHASE_KEY_PREFIX . $recordId;
+            $last = Redis::get($key);
+            if (!is_string($last) || $last === '') {
+                return;
+            }
+            Redis::del($key);
+            $sig = 'recovered:' . $recordId;
+            if (!self::shouldEmit($sig)) {
+                return;
+            }
+            Log::channel(self::LOG_CHANNEL)->info('game_live_recovered', [
+                'phase' => 'recovered',
+                'phase_label' => '对局已从卡住状态恢复',
+                'record_id' => $recordId,
+                'previous_phase' => $last,
+                'server_time' => date('Y-m-d H:i:s'),
+            ]);
+        } catch (Throwable) {
+        }
+    }
+
+    private static function phaseLabel(string $phase): string
+    {
+        return match ($phase) {
+            'await_auto_draw' => '待自动开奖',
+            'await_abnormal_void' => '待异常作废',
+            'payout_finalize_pending' => '待派彩结单',
+            'payout_finalize_lock' => '派彩结单拿不到锁',
+            'settle_pending' => '待结算注单',
+            'payout_without_result' => '派彩无开奖号',
+            'legacy_settling_status' => '遗留算票状态',
+            'draw_attempt_failed' => '开奖尝试失败',
+            'inspect_error' => '巡检异常',
+            default => $phase,
+        };
+    }
+
+    private static function hintForDrawMessage(string $msg): string
+    {
+        if (str_contains($msg, 'Another operation is in progress')) {
+            return 'Redis 行锁竞争或锁未释放，键名 dfw:v1:lock:mut:gr:{record_id}；500ms 内未拿到锁则静默重试';
+        }
+        if (str_contains($msg, 'Lock wait timeout') || str_contains($msg, '1205')) {
+            return 'InnoDB 锁等待超时，检查是否有长事务占用 game_record / bet_order';
+        }
+        if (str_contains($msg, 'countdown has not ended')) {
+            return '服务端认为倒计时未结束，核对 period_start_at 与 period_seconds 配置';
+        }
+
+        return '见 draw_msg 与 webman 日志 tickAutoDraw: drawResult failed';
+    }
+
+    private static function getConfigInt(string $key, int $default): int
+    {
+        $row = GameHotDataRedis::gameConfigRow($key);
+        if (!$row) {
+            return $default;
+        }
+        $v = $row['config_value'] ?? null;
+        if ($v === null || $v === '') {
+            return $default;
+        }
+        if (!is_numeric((string) $v)) {
+            return $default;
+        }
+        $parsed = filter_var($v, FILTER_VALIDATE_INT);
+
+        return $parsed !== false ? $parsed : $default;
+    }
+}
--- a/app/process/GameLiveTicker.php
+++ b/app/process/GameLiveTicker.php
@@ -3,6 +3,7 @@
 namespace app\process;

 use app\common\service\GameLiveService;
+use app\common\service\GameLiveStuckDiagnostic;
 use Workerman\Timer;

 /**
@@ -13,6 +14,7 @@ class GameLiveTicker
    public function onWorkerStart(): void
    {
        GameLiveService::recoverAbnormalPeriodOnStartup();
+        GameLiveStuckDiagnostic::inspectAfterRecovery();

        Timer::add(1, static function (): void {
            GameLiveService::publishSnapshot(null);
--- a/config/log.php
+++ b/config/log.php
@@ -51,4 +51,26 @@ return [
            ],
        ],
    ],
+    /**
+     * 游戏实时对局卡住诊断（独立通道）：
+     * - 写入 runtime/logs/game-live-stuck-YYYY-MM-DD.log，保留 7 天
+     * - 由 GameLiveStuckDiagnostic 在 recoverLiveRoundState 后巡检写入
+     * - 字段含 phase（卡住阶段）、db_status、stuck_sec、hint 等，便于 grep
+     */
+    'game_live_stuck' => [
+        'handlers' => [
+            [
+                'class' => Monolog\Handler\RotatingFileHandler::class,
+                'constructor' => [
+                    runtime_path() . '/logs/game-live-stuck.log',
+                    7,
+                    Monolog\Logger::DEBUG,
+                ],
+                'formatter' => [
+                    'class' => Monolog\Formatter\LineFormatter::class,
+                    'constructor' => [null, 'Y-m-d H:i:s', true],
+                ],
+            ],
+        ],
+    ],
 ];