Add AI debug logging and switch from fetch to https module

- Add toggle-able debug logging (AI_DEBUG env var) that logs prompts, request metadata, raw responses, parsed output, and full error chains - Replace Node.js native fetch() with https module for Docker Alpine compatibility (fixes "fetch failed" error with large payloads) - Reduce max_tokens from 16384 to 4096 (qwen3.5 doesn't need thinking token budget) - Strip <think> blocks from model responses - Add AI_DEBUG to docker-compose.yml and .env.example Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
2026-02-25 20:50:39 -05:00
parent fe4989bbcc
commit 25663fc79e
3 changed files with 143 additions and 23 deletions
--- a/.env.example
+++ b/.env.example
@@ -10,3 +10,5 @@ NODE_ENV=development
 AI_API_URL=https://integrate.api.nvidia.com/v1
 AI_API_KEY=your_nvidia_api_key_here
 AI_MODEL=qwen/qwen3.5-397b-a17b
+# Set to 'true' to enable detailed AI prompt/response logging
+AI_DEBUG=false
--- a/backend/src/modules/investment-planning/investment-planning.service.ts
+++ b/backend/src/modules/investment-planning/investment-planning.service.ts
@@ -60,12 +60,27 @@ export interface AIResponse {
@Injectable()
 export class InvestmentPlanningService {
  private readonly logger = new Logger(InvestmentPlanningService.name);
+  private debugEnabled: boolean;

  constructor(
    private tenant: TenantService,
    private configService: ConfigService,
    private dataSource: DataSource,
-  ) {}
+  ) {
+    // Toggle with AI_DEBUG=true in .env for detailed prompt/response logging
+    this.debugEnabled = this.configService.get<string>('AI_DEBUG') === 'true';
+    if (this.debugEnabled) {
+      this.logger.warn('AI DEBUG MODE ENABLED — prompts and responses will be logged');
+    }
+  }
+
+  private debug(label: string, data: any) {
+    if (!this.debugEnabled) return;
+    const text = typeof data === 'string' ? data : JSON.stringify(data, null, 2);
+    // Truncate very long output to keep logs manageable
+    const truncated = text.length > 5000 ? text.slice(0, 5000) + `\n... [truncated, ${text.length} total chars]` : text;
+    this.logger.log(`[AI_DEBUG] ${label}:\n${truncated}`);
+  }

  // ── Public API Methods ──

@@ -152,13 +167,32 @@ export class InvestmentPlanningService {
   * 5. Parse and return structured recommendations
   */
  async getAIRecommendations(): Promise<AIResponse> {
+    this.debug('getAIRecommendations', 'Starting AI recommendation flow');
+
    const [snapshot, cdRates] = await Promise.all([
      this.getFinancialSnapshot(),
      this.getCdRates(),
    ]);

+    this.debug('snapshot_summary', {
+      operating_cash: snapshot.summary.operating_cash,
+      reserve_cash: snapshot.summary.reserve_cash,
+      total_all: snapshot.summary.total_all,
+      investment_accounts: snapshot.investment_accounts.length,
+      budgets: snapshot.budgets.length,
+      projects: snapshot.projects.length,
+      cd_rates: cdRates.length,
+    });
+
    const messages = this.buildPromptMessages(snapshot, cdRates);
    const aiResponse = await this.callAI(messages);
+
+    this.debug('final_response', {
+      recommendation_count: aiResponse.recommendations.length,
+      has_assessment: !!aiResponse.overall_assessment,
+      risk_notes_count: aiResponse.risk_notes?.length || 0,
+    });
+
    return aiResponse;
  }

@@ -413,39 +447,92 @@ Based on this complete financial picture, provide your investment recommendation
      };
    }

-    try {
-      this.logger.log(`Calling AI API: ${apiUrl} with model ${model}`);
+    const requestBody = {
+      model,
+      messages,
+      temperature: 0.3,
+      max_tokens: 4096,
+    };

-      const response = await fetch(`${apiUrl}/chat/completions`, {
+    const bodyString = JSON.stringify(requestBody);
+
+    this.debug('prompt_system', messages[0]?.content);
+    this.debug('prompt_user', messages[1]?.content);
+    this.debug('request_meta', {
+      url: `${apiUrl}/chat/completions`,
+      model,
+      temperature: 0.3,
+      max_tokens: 4096,
+      body_length_bytes: Buffer.byteLength(bodyString, 'utf-8'),
+      message_count: messages.length,
+    });
+
+    try {
+      this.logger.log(`Calling AI API: ${apiUrl} with model ${model} (body: ${Buffer.byteLength(bodyString, 'utf-8')} bytes)`);
+
+      const startTime = Date.now();
+
+      // Use Node.js https module instead of native fetch for better
+      // compatibility in Docker Alpine environments
+      const { URL } = await import('url');
+      const https = await import('https');
+
+      const aiResult = await new Promise<any>((resolve, reject) => {
+        const url = new URL(`${apiUrl}/chat/completions`);
+
+        const options = {
+          hostname: url.hostname,
+          port: url.port || 443,
+          path: url.pathname,
          method: 'POST',
          headers: {
            'Authorization': `Bearer ${apiKey}`,
            'Content-Type': 'application/json',
+            'Content-Length': Buffer.byteLength(bodyString, 'utf-8'),
          },
-        body: JSON.stringify({
-          model,
-          messages,
-          temperature: 0.3,
-          // High token limit to accommodate thinking models (e.g. kimi-k2.5)
-          // which use tokens for internal reasoning before generating output
-          max_tokens: 16384,
-        }),
-        signal: AbortSignal.timeout(180000), // 3 minute timeout for thinking models
+          timeout: 180000, // 3 minute timeout
+        };
+
+        const req = https.request(options, (res) => {
+          let data = '';
+          res.on('data', (chunk) => { data += chunk; });
+          res.on('end', () => {
+            resolve({ status: res.statusCode, body: data });
+          });
        });

-      if (!response.ok) {
-        const errorBody = await response.text();
-        this.logger.error(`AI API error ${response.status}: ${errorBody}`);
-        throw new Error(`AI API returned ${response.status}: ${errorBody}`);
+        req.on('error', (err) => reject(err));
+        req.on('timeout', () => {
+          req.destroy();
+          reject(new Error(`Request timed out after 180s`));
+        });
+
+        req.write(bodyString);
+        req.end();
+      });
+
+      const elapsed = Date.now() - startTime;
+      this.logger.log(`AI API responded in ${elapsed}ms with status ${aiResult.status}`);
+      this.debug('response_timing', { elapsed_ms: elapsed, status: aiResult.status });
+
+      if (aiResult.status >= 400) {
+        this.logger.error(`AI API error ${aiResult.status}: ${aiResult.body}`);
+        this.debug('response_error_body', aiResult.body);
+        throw new Error(`AI API returned ${aiResult.status}: ${aiResult.body}`);
      }

-      const data = await response.json() as any;
+      const data = JSON.parse(aiResult.body);
      const msg = data.choices?.[0]?.message;
      // Thinking models (kimi-k2.5) may return content in 'content' or
      // spend all tokens on 'reasoning_content' with content=null
      const content = msg?.content || null;

      this.logger.log(`AI response: content=${content ? content.length + ' chars' : 'null'}, reasoning=${msg?.reasoning_content ? 'yes' : 'no'}, finish=${data.choices?.[0]?.finish_reason}`);
+      this.debug('response_raw_content', content);
+      this.debug('response_usage', data.usage);
+      if (msg?.reasoning_content) {
+        this.debug('response_reasoning', msg.reasoning_content);
+      }

      if (!content) {
        throw new Error('AI model returned empty content — it may have exhausted tokens on reasoning. Try a non-thinking model or increase max_tokens.');
@@ -457,17 +544,47 @@ Based on this complete financial picture, provide your investment recommendation
        cleaned = cleaned.replace(/^```(?:json)?\s*\n?/, '').replace(/\n?```\s*$/, '');
      }

+      // Handle thinking model wrapper: strip <think>...</think> blocks
+      cleaned = cleaned.replace(/<think>[\s\S]*?<\/think>\s*/g, '').trim();
+
      const parsed = JSON.parse(cleaned) as AIResponse;

      // Validate the response structure
      if (!parsed.recommendations || !Array.isArray(parsed.recommendations)) {
+        this.debug('invalid_response_structure', parsed);
        throw new Error('Invalid AI response: missing recommendations array');
      }

      this.logger.log(`AI returned ${parsed.recommendations.length} recommendations`);
+      this.debug('parsed_recommendations', parsed.recommendations.map((r) => ({
+        type: r.type,
+        priority: r.priority,
+        title: r.title,
+        fund_type: r.fund_type,
+        suggested_amount: r.suggested_amount,
+      })));
+
      return parsed;
    } catch (error: any) {
+      // Log the full error chain for debugging
      this.logger.error(`AI recommendation failed: ${error.message}`);
+      if (error.cause) {
+        this.logger.error(`  → cause: ${error.cause?.message || error.cause}`);
+        this.debug('error_cause', {
+          message: error.cause?.message,
+          code: error.cause?.code,
+          errno: error.cause?.errno,
+          syscall: error.cause?.syscall,
+          hostname: error.cause?.hostname,
+          stack: error.cause?.stack,
+        });
+      }
+      this.debug('error_full', {
+        message: error.message,
+        name: error.name,
+        code: error.code,
+        stack: error.stack,
+      });

      // For JSON parse errors, return what we can
      if (error instanceof SyntaxError) {
--- a/docker-compose.yml
+++ b/docker-compose.yml
@@ -25,6 +25,7 @@ services:
      - AI_API_URL=${AI_API_URL}
      - AI_API_KEY=${AI_API_KEY}
      - AI_MODEL=${AI_MODEL}
+      - AI_DEBUG=${AI_DEBUG:-false}
    volumes:
      - ./backend/src:/app/src
      - ./backend/nest-cli.json:/app/nest-cli.json