event('prepare', [ 'duration_ms' => 120, 'aggregate_ms' => 75, 'compaction_ms' => 0, 'source_bytes' => 1000, 'query_bytes' => 1100, 'attachment_count' => 2, 'compaction_attempted' => false, 'status' => 'ok', 'patient_name' => '患者姓名', 'query' => '患者正文', 'url' => 'https://private.example/path', 'api_key' => 'secret', ]); $second = $one->event('upstream_done', [ 'duration_ms' => 4300, 'retry_ms' => 1200, 'retry_attempted' => true, 'delta_count' => 4, 'delta_bytes' => 24, 'status' => 'error', 'error_code' => 'UPSTREAM_TIMEOUT', ]); timingExpect(preg_match('/^[a-f0-9]{32}$/', $first['trace_id']) === 1, 'trace id is random hex only'); timingExpect($first['trace_id'] !== $two->event('prepare')['trace_id'], 'requests use distinct trace ids'); timingExpect($first['trace_id'] === $second['trace_id'], 'all phases share one trace id'); timingExpect( $first['aggregate_ms'] === 75 && $first['attachment_count'] === 2 && $first['compaction_attempted'] === false, 'prepare phase retains useful numeric metadata' ); timingExpect( $second['retry_attempted'] === true && $second['retry_ms'] === 1200 && $second['error_code'] === 'UPSTREAM_TIMEOUT', 'upstream phase retains retry, duration and safe status' ); $encoded = json_encode($first, JSON_UNESCAPED_UNICODE); foreach (['患者姓名', '患者正文', 'private.example', 'secret'] as $sensitive) { timingExpect(!str_contains($encoded, $sensitive), 'timing log excludes sensitive payload'); } timingExpect(!isset($one->event('prepare', ['duration_ms' => '患者正文'])['duration_ms']), 'numeric fields reject text'); timingExpect(!isset($one->event('upstream_done', ['error_code' => 'KEY=secret'])['error_code']), 'error code is validated'); timingExpect(!isset($one->event('upstream_done', ['error_code' => 'API_KEY_SECRET'])['error_code']), 'unknown machine codes are not logged'); $startedAt = hrtime(true); timingExpect(AssistantSseTiming::elapsedMs($startedAt) >= 0, 'monotonic elapsed time is non-negative'); timingExpect(isset($first['request_elapsed_ms']) && is_int($first['request_elapsed_ms']), 'request timing includes the phase before SSE'); timingExpect($one->event('first_delta')['request_elapsed_ms'] >= $first['request_elapsed_ms'], 'full request time remains monotonic across preparation and first text'); timingExpect($one->event('prepare', ['compaction_cache_hit' => true])['compaction_cache_hit'] === true, 'cache hit is safe boolean telemetry'); // Exercise a buffered web-style channel: timing must reach disk before HTTP end/exit. $app = new \think\App(dirname(__DIR__) . '/'); $directory = sys_get_temp_dir() . '/zyt-ai-timing-' . bin2hex(random_bytes(8)); $app->config->set(['default' => 'timing', 'channels' => ['timing' => [ 'type' => 'File', 'path' => $directory, 'single' => 'timing', 'realtime_write' => false, ]]], 'log'); $logger = $app->make('log'); $channel = $logger->channel('timing'); (new ReflectionProperty(\think\log\Channel::class, 'lazy'))->setValue($channel, true); $logger->info('buffered control'); $logFile = $directory . '/timing.log'; timingExpect(!is_file($logFile), 'control channel really buffers before the SSE timing write'); $one->log('first_delta', ['duration_ms' => 123, 'api_key' => 'must-not-be-logged']); timingExpect(is_file($logFile), 'SSE timing persists immediately without HTTP-end save'); $logged = file_get_contents($logFile); timingExpect(str_contains($logged, $one->id()) && !str_contains($logged, 'must-not-be-logged'), 'persisted timing remains patient and credential free'); unlink($logFile); rmdir($directory); $controller = file_get_contents(dirname(__DIR__) . '/app/adminapi/controller/tcm/DiagnosisController.php'); $logic = file_get_contents(dirname(__DIR__) . '/app/adminapi/logic/tcm/DiagnosisAiLogic.php'); timingExpect(is_string($controller) && is_string($logic), 'instrumented source is readable'); timingExpect(str_contains($controller, "log('first_delta'") && str_contains($controller, "log('sse_done'"), 'SSE first delta and completion are timed'); timingExpect(str_contains($logic, "log('prepare'") && str_contains($logic, "log('upstream_done'"), 'prepare and upstream are timed'); timingExpect(str_contains($logic, 'compaction_attempted') && str_contains($logic, 'retry_attempted'), 'compression and compatibility retry are recorded'); timingExpect(str_contains($controller, "'trace_id' => \$timing->id()"), 'SSE start exposes only the random trace id for timing correlation'); echo "Diagnosis AI assistant timing: OK\n";