From 4f48ddf9a1afd316a1624b609ed4559082a081bb Mon Sep 17 00:00:00 2001 From: Jay Hill <116148+jayhill@users.noreply.github.com> Date: Fri, 31 Oct 2025 16:03:49 -0400 Subject: [PATCH 1/3] #147 additional logging around portal 500 responses --- serverless/TROUBLESHOOTING_LOGGING.md | 210 ++++++++++++++++++++++ serverless/lib/CaseSearchProcessor.ts | 249 +++++++++++++++++++++++++- 2 files changed, 452 insertions(+), 7 deletions(-) create mode 100644 serverless/TROUBLESHOOTING_LOGGING.md diff --git a/serverless/TROUBLESHOOTING_LOGGING.md b/serverless/TROUBLESHOOTING_LOGGING.md new file mode 100644 index 0000000..47658e5 --- /dev/null +++ b/serverless/TROUBLESHOOTING_LOGGING.md @@ -0,0 +1,210 @@ +# Case Search 500 Error Troubleshooting Guide + +## Overview + +This document describes the enhanced logging added to `CaseSearchProcessor.ts` to troubleshoot 500 errors when extracting case IDs from the portal. + +## Enhanced Logging Features + +### 1. Request ID Tracking + +Every portal request now has a unique request ID in the format `{caseNumber}-{timestamp}`, making it easy to trace a specific request through all log entries. + +**Log format:** `[{requestId}]` prefix on all related log entries + +### 2. Timing Metrics + +Comprehensive timing information is captured: + +- `searchRequest`: Time taken for the search form submission +- `resultsRequest`: Time taken for fetching search results +- `htmlParse`: Time taken to parse the HTML response +- `totalDuration`: Total time from start to finish + +These metrics help identify: + +- Network latency issues +- Portal performance problems +- Timeout situations + +### 3. Cookie State Logging + +At the start of each request, the system logs: + +- Number of cookies in the jar +- Cookie names (not values, for security) +- User agent being used + +**Example log:** + +```json +{ + "caseNumber": "12345", + "cookieNames": ["ASP.NET_SessionId", "AuthToken"], + "userAgent": "Mozilla/5.0..." +} +``` + +### 4. Axios Request/Response Interceptors + +Detailed logging for every HTTP request and response: + +**Outgoing requests log:** + +- HTTP method +- Full URL +- Headers +- Data presence and length + +**Incoming responses log:** + +- Status code and status text +- Duration (ms) +- Response headers +- Response data length + +**Error responses log:** + +- Status code (if available) +- Error code (e.g., ECONNABORTED, ETIMEDOUT) +- Error message +- Duration + +### 5. Enhanced Error Details for 500 Responses + +When a 500 error occurs, the system now captures: + +- Full status code and status text +- Response headers (may indicate rate limiting or other server issues) +- Response body preview (first 1000 characters) +- Request duration +- Request ID for correlation + +### 6. Race Condition Detection + +The system tracks the time between consecutive requests for the same case number: + +- Warns if requests for the same case are made within 100ms of each other +- Automatically cleans up tracking data older than 5 minutes +- Helps identify concurrent processing issues + +**Example warning:** + +``` +[12345-1730000000000] POTENTIAL RACE CONDITION: Request for 12345 made 50ms after previous request (< 100ms threshold) +``` + +### 7. Portal-Specific Error Detection + +Enhanced detection and logging for known portal issues: + +- "Smart Search is having trouble" error messages +- Missing case links in results +- Missing case ID attributes +- Each gets specific context and timing information + +## How to Use This Logging + +### Identifying 500 Errors + +Look for log entries with: + +``` +[{requestId}] Search request failed +``` + +or + +``` +[{requestId}] Results request failed +``` + +These will include: + +- `status`: The HTTP status code (500) +- `statusText`: The status message +- `headers`: Response headers that may indicate the cause +- `bodyPreview`: First 1000 chars of the error response +- `duration`: How long the request took + +### Identifying Race Conditions + +Search logs for: + +``` +POTENTIAL RACE CONDITION +``` + +This indicates requests are being made too quickly in succession, which could cause the portal to reject requests or behave unexpectedly. + +### Tracking Request Flow + +Use the request ID to follow a specific case search through the logs: + +1. Initial request with cookie state +2. Search form submission (>>> Outgoing request) +3. Search form response (<<< Incoming response) +4. Results page request (>>> Outgoing request) +5. Results page response (<<< Incoming response) +6. HTML parsing and case ID extraction +7. Final result or error + +### Analyzing Timing Issues + +Compare timing metrics: + +- If `searchRequest` or `resultsRequest` > 15000ms, the portal is slow +- If `totalDuration` approaches 20000ms (timeout threshold), requests are timing out +- Unusually fast responses (<100ms) might indicate cached errors or redirects + +### Comparing with Insomnia + +When comparing with successful Insomnia requests: + +1. Check cookie differences (cookieNames in logs) +2. Compare request headers (in >>> Outgoing request logs) +3. Compare response headers (in <<< Incoming response logs) +4. Check for rate limiting headers (X-RateLimit-\*, Retry-After) +5. Compare timing - Insomnia might be slower/faster + +## Common Issues to Look For + +### 1. Session/Cookie Issues + +- Log shows 0 or 1 cookies when multiple are expected +- Missing authentication cookies + +### 2. Rate Limiting + +- Multiple requests in quick succession (< 100ms apart) +- Response headers contain rate limit information +- 429 or 503 status codes before the 500 + +### 3. Portal State Issues + +- "Smart Search is having trouble" message +- Empty or unexpected response bodies +- Redirects to error pages + +### 4. Network/Timeout Issues + +- `noResponse: true` in error logs +- `requestTimeout: true` in error logs +- Very high duration values (>15000ms) + +### 5. Concurrent Processing + +- Same case number appearing in multiple requests simultaneously +- Race condition warnings for the same case + +## Log Retention + +All enhanced logging uses `console.log` and `console.error`, which are captured by CloudWatch Logs. Error details are also sent to AlertService for centralized monitoring. + +## Configuration + +- **Request interval threshold:** `MIN_REQUEST_INTERVAL_MS = 100ms` +- **Request timeout:** `20000ms` (axios timeout) +- **Max redirects:** `10` + +Adjust these values in `CaseSearchProcessor.ts` if needed based on troubleshooting findings. diff --git a/serverless/lib/CaseSearchProcessor.ts b/serverless/lib/CaseSearchProcessor.ts index 64e6c9d..2593632 100644 --- a/serverless/lib/CaseSearchProcessor.ts +++ b/serverless/lib/CaseSearchProcessor.ts @@ -11,6 +11,10 @@ import * as cheerio from 'cheerio'; import UserAgentClient from './UserAgentClient'; import { CASE_SUMMARY_VERSION_DATE } from './CaseProcessor'; +// Track last request time per user to detect potential race conditions +const lastRequestTimes = new Map(); +const MIN_REQUEST_INTERVAL_MS = 100; // Minimum time between requests (adjust as needed) + // Process API case search requests export async function processCaseSearchRequest(req: CaseSearchRequest): Promise { let caseNumbers = SearchParser.parseSearchInput(req.input); @@ -337,6 +341,30 @@ export async function processCaseSearchRecord( // Fetch case ID from the portal export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: CookieJar): Promise { + const requestId = `${caseNumber}-${Date.now()}`; + const timings: Record = {}; + const startTime = Date.now(); + + // Check for potential race conditions + const lastRequestTime = lastRequestTimes.get(caseNumber); + if (lastRequestTime) { + const timeSinceLastRequest = startTime - lastRequestTime; + if (timeSinceLastRequest < MIN_REQUEST_INTERVAL_MS) { + console.warn( + `[${requestId}] POTENTIAL RACE CONDITION: Request for ${caseNumber} made ${timeSinceLastRequest}ms after previous request (< ${MIN_REQUEST_INTERVAL_MS}ms threshold)` + ); + } + } + lastRequestTimes.set(caseNumber, startTime); + + // Clean up old entries (older than 5 minutes) + const fiveMinutesAgo = startTime - 5 * 60 * 1000; + for (const [key, time] of lastRequestTimes.entries()) { + if (time < fiveMinutesAgo) { + lastRequestTimes.delete(key); + } + } + try { // Get the portal URL from environment variable const portalUrl = process.env.PORTAL_URL; @@ -357,6 +385,14 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki const userAgent = await UserAgentClient.getUserAgent('system'); + // Log cookie state for debugging + const cookies = await cookieJar.getCookies(portalUrl); + console.log(`[${requestId}] Starting case search with ${cookies.length} cookies`, { + caseNumber, + cookieNames: cookies.map(c => c.key), + userAgent, + }); + const client = wrapper(axios).create({ timeout: 20000, maxRedirects: 10, @@ -371,21 +407,119 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki }, }); - console.log(`Searching for case number ${caseNumber}`); + // Track request timings + const requestTimings = new Map(); + + // Add request interceptor for detailed logging + client.interceptors.request.use( + config => { + const requestStart = Date.now(); + const reqKey = `${config.method}-${config.url}`; + requestTimings.set(reqKey, requestStart); + + console.log(`[${requestId}] >>> Outgoing request`, { + method: config.method?.toUpperCase(), + url: config.url, + headers: config.headers, + hasData: !!config.data, + dataLength: config.data ? String(config.data).length : 0, + }); + return config; + }, + error => { + console.error(`[${requestId}] Request interceptor error`, error); + return Promise.reject(error); + } + ); + + // Add response interceptor for detailed logging + client.interceptors.response.use( + response => { + const reqKey = `${response.config.method}-${response.config.url}`; + const startTime = requestTimings.get(reqKey) || Date.now(); + const duration = Date.now() - startTime; + requestTimings.delete(reqKey); + + console.log(`[${requestId}] <<< Incoming response`, { + status: response.status, + statusText: response.statusText, + duration, + headers: response.headers, + dataLength: response.data ? String(response.data).length : 0, + url: response.config.url, + }); + return response; + }, + error => { + const reqKey = `${error.config?.method}-${error.config?.url}`; + const startTime = requestTimings.get(reqKey) || Date.now(); + const duration = Date.now() - startTime; + requestTimings.delete(reqKey); + + console.error(`[${requestId}] <<< Error response`, { + duration, + status: error.response?.status, + statusText: error.response?.statusText, + headers: error.response?.headers, + url: error.config?.url, + code: error.code, + message: error.message, + }); + return Promise.reject(error); + } + ); + + console.log(`[${requestId}] Searching for case number ${caseNumber}`); // Step 1: Submit the search form (following the Insomnia export) const searchFormData = new URLSearchParams(); searchFormData.append('caseCriteria.SearchCriteria', caseNumber); searchFormData.append('caseCriteria.SearchCases', 'true'); - const searchResponse = await client.post(`${portalUrl}/Portal/SmartSearch/SmartSearch/SmartSearch`, searchFormData); + const searchUrl = `${portalUrl}/Portal/SmartSearch/SmartSearch/SmartSearch`; + console.log(`[${requestId}] POST ${searchUrl}`, { + formData: Object.fromEntries(searchFormData.entries()), + headers: { + 'Content-Type': 'application/x-www-form-urlencoded', + Origin: portalUrl, + 'User-Agent': userAgent, + }, + }); + + const searchStartTime = Date.now(); + const searchResponse = await client.post(searchUrl, searchFormData); + timings.searchRequest = Date.now() - searchStartTime; + + console.log(`[${requestId}] Search form submission response`, { + status: searchResponse.status, + statusText: searchResponse.statusText, + duration: timings.searchRequest, + headers: searchResponse.headers, + redirects: searchResponse.request?._redirectable?._redirectCount, + }); if (searchResponse.status !== 200) { const errorMessage = `Search request failed with status ${searchResponse.status}`; + const responseBody = + typeof searchResponse.data === 'string' + ? searchResponse.data.substring(0, 1000) + : JSON.stringify(searchResponse.data).substring(0, 1000); + + console.error(`[${requestId}] Search request failed`, { + status: searchResponse.status, + statusText: searchResponse.statusText, + headers: searchResponse.headers, + bodyPreview: responseBody, + duration: timings.searchRequest, + }); await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { + requestId, caseNumber, statusCode: searchResponse.status, + statusText: searchResponse.statusText, + duration: timings.searchRequest, + bodyPreview: responseBody, resource: 'portal-search', }); @@ -399,14 +533,43 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki } // Step 2: Get the search results page - const resultsResponse = await client.get(`${portalUrl}/Portal/SmartSearch/SmartSearchResults`); + const resultsUrl = `${portalUrl}/Portal/SmartSearch/SmartSearchResults`; + console.log(`[${requestId}] GET ${resultsUrl}`); + + const resultsStartTime = Date.now(); + const resultsResponse = await client.get(resultsUrl); + timings.resultsRequest = Date.now() - resultsStartTime; + + console.log(`[${requestId}] Search results response`, { + status: resultsResponse.status, + statusText: resultsResponse.statusText, + duration: timings.resultsRequest, + headers: resultsResponse.headers, + contentLength: resultsResponse.data?.length || 0, + }); if (resultsResponse.status !== 200) { const errorMessage = `Results request failed with status ${resultsResponse.status}`; + const responseBody = + typeof resultsResponse.data === 'string' + ? resultsResponse.data.substring(0, 1000) + : JSON.stringify(resultsResponse.data).substring(0, 1000); + + console.error(`[${requestId}] Results request failed`, { + status: resultsResponse.status, + statusText: resultsResponse.statusText, + headers: resultsResponse.headers, + bodyPreview: responseBody, + duration: timings.resultsRequest, + }); await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { + requestId, caseNumber, statusCode: resultsResponse.status, + statusText: resultsResponse.statusText, + duration: timings.resultsRequest, + bodyPreview: responseBody, resource: 'portal-search-results', }); @@ -423,8 +586,16 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki if (resultsResponse.data.includes('Smart Search is having trouble processing your search')) { const errorMessage = 'Smart Search is having trouble processing your search. Please try again later.'; + console.error(`[${requestId}] Portal smart search error`, { + caseNumber, + totalDuration: Date.now() - startTime, + timings, + }); + await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { + requestId, caseNumber, + timings, resource: 'smart-search', }); @@ -438,14 +609,25 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki } // Step 3: Extract the case ID from the response using cheerio + const parseStartTime = Date.now(); const $ = cheerio.load(resultsResponse.data); + timings.htmlParse = Date.now() - parseStartTime; // Look for anchor tags with class "caseLink" and get the data-caseid attribute // From the Insomnia export's after-response script const caseLinks = $('a.caseLink'); + console.log(`[${requestId}] Parsed HTML results`, { + caseLinksFound: caseLinks.length, + parseDuration: timings.htmlParse, + totalDuration: Date.now() - startTime, + }); + if (caseLinks.length === 0) { - console.log(`No cases found for case number ${caseNumber}`); + console.log(`[${requestId}] No cases found for case number ${caseNumber}`, { + timings, + totalDuration: Date.now() - startTime, + }); return { caseId: null, error: { @@ -461,8 +643,18 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki if (!caseId) { const errorMessage = `No case ID found in search results for ${caseNumber}`; + console.error(`[${requestId}] No case ID attribute found`, { + caseLinksFound: caseLinks.length, + firstLinkHtml: caseLinks.first().html()?.substring(0, 200), + timings, + totalDuration: Date.now() - startTime, + }); + await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { + requestId, caseNumber, + caseLinksFound: caseLinks.length, + timings, resource: 'case-search-results', }); return { @@ -474,13 +666,56 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki }; } - console.log(`Found case ID ${caseId} for case number ${caseNumber}`); + const totalDuration = Date.now() - startTime; + console.log(`[${requestId}] Found case ID ${caseId} for case number ${caseNumber}`, { + timings, + totalDuration, + }); + return { caseId }; } catch (error) { - await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', error as Error, { + const totalDuration = Date.now() - startTime; + const axiosError = error as any; + + // Enhanced error logging with request/response details + const errorDetails: Record = { + requestId, caseNumber, + timings, + totalDuration, resource: 'case-id-fetch', - }); + }; + + // Capture axios-specific error details + if (axiosError.response) { + // The request was made and the server responded with a status code + // that falls out of the range of 2xx + errorDetails.responseStatus = axiosError.response.status; + errorDetails.responseStatusText = axiosError.response.statusText; + errorDetails.responseHeaders = axiosError.response.headers; + + // Capture response body (truncated) + if (axiosError.response.data) { + const responseBody = + typeof axiosError.response.data === 'string' ? axiosError.response.data : JSON.stringify(axiosError.response.data); + errorDetails.responseBodyPreview = responseBody.substring(0, 1000); + } + } else if (axiosError.request) { + // The request was made but no response was received + errorDetails.requestMade = true; + errorDetails.noResponse = true; + errorDetails.requestTimeout = axiosError.code === 'ECONNABORTED'; + } else { + // Something happened in setting up the request that triggered an Error + errorDetails.setupError = true; + } + + errorDetails.errorCode = axiosError.code; + errorDetails.errorMessage = axiosError.message; + + console.error(`[${requestId}] Error fetching case ID from portal`, errorDetails); + + await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', error as Error, errorDetails); return { caseId: null, From bab68e0188faa9475b17e863da1b71edac346ab2 Mon Sep 17 00:00:00 2001 From: Jay Hill <116148+jayhill@users.noreply.github.com> Date: Wed, 19 Nov 2025 09:09:37 -0500 Subject: [PATCH 2/3] #152 set status to queued when reprocessing a failed or incomplete search --- serverless/lib/CaseSearchProcessor.ts | 24 ++++++++-------- .../lib/__tests__/CaseSearchProcessor.test.ts | 28 +++++++++++++++++-- 2 files changed, 38 insertions(+), 14 deletions(-) diff --git a/serverless/lib/CaseSearchProcessor.ts b/serverless/lib/CaseSearchProcessor.ts index 2593632..13e59d5 100644 --- a/serverless/lib/CaseSearchProcessor.ts +++ b/serverless/lib/CaseSearchProcessor.ts @@ -1,4 +1,4 @@ -import { CaseSearchRequest, CaseSearchResponse, SearchResult, FetchStatus } from '../../shared/types'; +import { CaseSearchRequest, CaseSearchResponse, SearchResult, FetchStatus, ZipCase } from '../../shared/types'; import QueueClient from './QueueClient'; import SearchParser from './SearchParser'; import StorageClient from './StorageClient'; @@ -121,22 +121,24 @@ export async function processCaseSearchRequest(req: CaseSearchRequest): Promise< case 'processing': // We requeue 'queued' and 'processing' because they might be stuck. // When they get picked up from the queue, we'll see whether they became 'complete' in the mean time and exit early. + const zipCase = results[caseNumber].zipCase; + + zipCase.fetchStatus = { status: 'queued' }; + + await StorageClient.saveCase(zipCase); + casesToQueue.push(caseNumber); } } else { // Case doesn't exist yet - create it with queued status and add to queue - results[caseNumber] = { - zipCase: { - caseNumber, - fetchStatus: { status: 'queued' }, - }, - }; - - // Save the new case to storage - await StorageClient.saveCase({ + const zipCase: ZipCase = { caseNumber, fetchStatus: { status: 'queued' }, - }); + }; + + results[caseNumber] = { zipCase: zipCase }; + + await StorageClient.saveCase(zipCase); casesToQueue.push(caseNumber); } diff --git a/serverless/lib/__tests__/CaseSearchProcessor.test.ts b/serverless/lib/__tests__/CaseSearchProcessor.test.ts index ca86bf0..585a057 100644 --- a/serverless/lib/__tests__/CaseSearchProcessor.test.ts +++ b/serverless/lib/__tests__/CaseSearchProcessor.test.ts @@ -221,7 +221,13 @@ describe('CaseSearchProcessor', () => { // Should queue for search (processing cases get re-queued in case they're stuck) expect(mockQueueClient.queueCasesForSearch).toHaveBeenCalledWith(['22CR123456-789'], 'test-user-id', 'Test Agent'); expect(mockQueueClient.queueCaseForDataRetrieval).not.toHaveBeenCalled(); - expect(mockStorageClient.saveCase).not.toHaveBeenCalled(); + // Status should be saved to DynamoDB as 'queued' + expect(mockStorageClient.saveCase).toHaveBeenCalledWith({ + caseNumber: '22CR123456-789', + fetchStatus: { status: 'queued' }, + caseId: 'test-case-id', + lastUpdated: expect.any(String), + }); }); it('should handle cases with notFound status (should queue for search retry)', async () => { @@ -244,7 +250,15 @@ describe('CaseSearchProcessor', () => { // Should queue for search retry, in case the record is not actually in-queue expect(mockQueueClient.queueCaseForDataRetrieval).not.toHaveBeenCalled(); expect(mockQueueClient.queueCasesForSearch).toHaveBeenCalledWith(['22CR123456-789'], 'test-user-id', 'Test Agent'); - expect(mockStorageClient.saveCase).not.toHaveBeenCalled(); + // Status should be saved to DynamoDB as 'queued' + expect(mockStorageClient.saveCase).toHaveBeenCalledWith({ + caseNumber: '22CR123456-789', + fetchStatus: { status: 'queued' }, + caseId: undefined, + lastUpdated: expect.any(String), + }); + // Status should be updated to 'queued' in the response for the UI + expect(result.results['22CR123456-789'].zipCase.fetchStatus.status).toBe('queued'); }); it('should handle cases with failed status (should queue for search)', async () => { @@ -267,7 +281,15 @@ describe('CaseSearchProcessor', () => { // Should queue for search (failed status gets re-queued) expect(mockQueueClient.queueCasesForSearch).toHaveBeenCalledWith(['22CR123456-789'], 'test-user-id', 'Test Agent'); expect(mockQueueClient.queueCaseForDataRetrieval).not.toHaveBeenCalled(); - expect(mockStorageClient.saveCase).not.toHaveBeenCalled(); + // Status should be saved to DynamoDB as 'queued' + expect(mockStorageClient.saveCase).toHaveBeenCalledWith({ + caseNumber: '22CR123456-789', + fetchStatus: { status: 'queued' }, + caseId: undefined, + lastUpdated: expect.any(String), + }); + // Status should be updated to 'queued' in the response for the UI + expect(result.results['22CR123456-789'].zipCase.fetchStatus.status).toBe('queued'); }); it('should handle new cases (not in storage)', async () => { From 20066e3a384ea010304ce8f7eca3b98d59315cba Mon Sep 17 00:00:00 2001 From: Jay Hill <116148+jayhill@users.noreply.github.com> Date: Thu, 20 Nov 2025 08:28:13 -0500 Subject: [PATCH 3/3] #147 revert additional logging around portal 500 responses This reverts commit 4f48ddf9a1afd316a1624b609ed4559082a081bb --- serverless/TROUBLESHOOTING_LOGGING.md | 210 ---------------------- serverless/lib/CaseSearchProcessor.ts | 249 +------------------------- 2 files changed, 7 insertions(+), 452 deletions(-) delete mode 100644 serverless/TROUBLESHOOTING_LOGGING.md diff --git a/serverless/TROUBLESHOOTING_LOGGING.md b/serverless/TROUBLESHOOTING_LOGGING.md deleted file mode 100644 index 47658e5..0000000 --- a/serverless/TROUBLESHOOTING_LOGGING.md +++ /dev/null @@ -1,210 +0,0 @@ -# Case Search 500 Error Troubleshooting Guide - -## Overview - -This document describes the enhanced logging added to `CaseSearchProcessor.ts` to troubleshoot 500 errors when extracting case IDs from the portal. - -## Enhanced Logging Features - -### 1. Request ID Tracking - -Every portal request now has a unique request ID in the format `{caseNumber}-{timestamp}`, making it easy to trace a specific request through all log entries. - -**Log format:** `[{requestId}]` prefix on all related log entries - -### 2. Timing Metrics - -Comprehensive timing information is captured: - -- `searchRequest`: Time taken for the search form submission -- `resultsRequest`: Time taken for fetching search results -- `htmlParse`: Time taken to parse the HTML response -- `totalDuration`: Total time from start to finish - -These metrics help identify: - -- Network latency issues -- Portal performance problems -- Timeout situations - -### 3. Cookie State Logging - -At the start of each request, the system logs: - -- Number of cookies in the jar -- Cookie names (not values, for security) -- User agent being used - -**Example log:** - -```json -{ - "caseNumber": "12345", - "cookieNames": ["ASP.NET_SessionId", "AuthToken"], - "userAgent": "Mozilla/5.0..." -} -``` - -### 4. Axios Request/Response Interceptors - -Detailed logging for every HTTP request and response: - -**Outgoing requests log:** - -- HTTP method -- Full URL -- Headers -- Data presence and length - -**Incoming responses log:** - -- Status code and status text -- Duration (ms) -- Response headers -- Response data length - -**Error responses log:** - -- Status code (if available) -- Error code (e.g., ECONNABORTED, ETIMEDOUT) -- Error message -- Duration - -### 5. Enhanced Error Details for 500 Responses - -When a 500 error occurs, the system now captures: - -- Full status code and status text -- Response headers (may indicate rate limiting or other server issues) -- Response body preview (first 1000 characters) -- Request duration -- Request ID for correlation - -### 6. Race Condition Detection - -The system tracks the time between consecutive requests for the same case number: - -- Warns if requests for the same case are made within 100ms of each other -- Automatically cleans up tracking data older than 5 minutes -- Helps identify concurrent processing issues - -**Example warning:** - -``` -[12345-1730000000000] POTENTIAL RACE CONDITION: Request for 12345 made 50ms after previous request (< 100ms threshold) -``` - -### 7. Portal-Specific Error Detection - -Enhanced detection and logging for known portal issues: - -- "Smart Search is having trouble" error messages -- Missing case links in results -- Missing case ID attributes -- Each gets specific context and timing information - -## How to Use This Logging - -### Identifying 500 Errors - -Look for log entries with: - -``` -[{requestId}] Search request failed -``` - -or - -``` -[{requestId}] Results request failed -``` - -These will include: - -- `status`: The HTTP status code (500) -- `statusText`: The status message -- `headers`: Response headers that may indicate the cause -- `bodyPreview`: First 1000 chars of the error response -- `duration`: How long the request took - -### Identifying Race Conditions - -Search logs for: - -``` -POTENTIAL RACE CONDITION -``` - -This indicates requests are being made too quickly in succession, which could cause the portal to reject requests or behave unexpectedly. - -### Tracking Request Flow - -Use the request ID to follow a specific case search through the logs: - -1. Initial request with cookie state -2. Search form submission (>>> Outgoing request) -3. Search form response (<<< Incoming response) -4. Results page request (>>> Outgoing request) -5. Results page response (<<< Incoming response) -6. HTML parsing and case ID extraction -7. Final result or error - -### Analyzing Timing Issues - -Compare timing metrics: - -- If `searchRequest` or `resultsRequest` > 15000ms, the portal is slow -- If `totalDuration` approaches 20000ms (timeout threshold), requests are timing out -- Unusually fast responses (<100ms) might indicate cached errors or redirects - -### Comparing with Insomnia - -When comparing with successful Insomnia requests: - -1. Check cookie differences (cookieNames in logs) -2. Compare request headers (in >>> Outgoing request logs) -3. Compare response headers (in <<< Incoming response logs) -4. Check for rate limiting headers (X-RateLimit-\*, Retry-After) -5. Compare timing - Insomnia might be slower/faster - -## Common Issues to Look For - -### 1. Session/Cookie Issues - -- Log shows 0 or 1 cookies when multiple are expected -- Missing authentication cookies - -### 2. Rate Limiting - -- Multiple requests in quick succession (< 100ms apart) -- Response headers contain rate limit information -- 429 or 503 status codes before the 500 - -### 3. Portal State Issues - -- "Smart Search is having trouble" message -- Empty or unexpected response bodies -- Redirects to error pages - -### 4. Network/Timeout Issues - -- `noResponse: true` in error logs -- `requestTimeout: true` in error logs -- Very high duration values (>15000ms) - -### 5. Concurrent Processing - -- Same case number appearing in multiple requests simultaneously -- Race condition warnings for the same case - -## Log Retention - -All enhanced logging uses `console.log` and `console.error`, which are captured by CloudWatch Logs. Error details are also sent to AlertService for centralized monitoring. - -## Configuration - -- **Request interval threshold:** `MIN_REQUEST_INTERVAL_MS = 100ms` -- **Request timeout:** `20000ms` (axios timeout) -- **Max redirects:** `10` - -Adjust these values in `CaseSearchProcessor.ts` if needed based on troubleshooting findings. diff --git a/serverless/lib/CaseSearchProcessor.ts b/serverless/lib/CaseSearchProcessor.ts index 13e59d5..c628617 100644 --- a/serverless/lib/CaseSearchProcessor.ts +++ b/serverless/lib/CaseSearchProcessor.ts @@ -11,10 +11,6 @@ import * as cheerio from 'cheerio'; import UserAgentClient from './UserAgentClient'; import { CASE_SUMMARY_VERSION_DATE } from './CaseProcessor'; -// Track last request time per user to detect potential race conditions -const lastRequestTimes = new Map(); -const MIN_REQUEST_INTERVAL_MS = 100; // Minimum time between requests (adjust as needed) - // Process API case search requests export async function processCaseSearchRequest(req: CaseSearchRequest): Promise { let caseNumbers = SearchParser.parseSearchInput(req.input); @@ -343,30 +339,6 @@ export async function processCaseSearchRecord( // Fetch case ID from the portal export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: CookieJar): Promise { - const requestId = `${caseNumber}-${Date.now()}`; - const timings: Record = {}; - const startTime = Date.now(); - - // Check for potential race conditions - const lastRequestTime = lastRequestTimes.get(caseNumber); - if (lastRequestTime) { - const timeSinceLastRequest = startTime - lastRequestTime; - if (timeSinceLastRequest < MIN_REQUEST_INTERVAL_MS) { - console.warn( - `[${requestId}] POTENTIAL RACE CONDITION: Request for ${caseNumber} made ${timeSinceLastRequest}ms after previous request (< ${MIN_REQUEST_INTERVAL_MS}ms threshold)` - ); - } - } - lastRequestTimes.set(caseNumber, startTime); - - // Clean up old entries (older than 5 minutes) - const fiveMinutesAgo = startTime - 5 * 60 * 1000; - for (const [key, time] of lastRequestTimes.entries()) { - if (time < fiveMinutesAgo) { - lastRequestTimes.delete(key); - } - } - try { // Get the portal URL from environment variable const portalUrl = process.env.PORTAL_URL; @@ -387,14 +359,6 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki const userAgent = await UserAgentClient.getUserAgent('system'); - // Log cookie state for debugging - const cookies = await cookieJar.getCookies(portalUrl); - console.log(`[${requestId}] Starting case search with ${cookies.length} cookies`, { - caseNumber, - cookieNames: cookies.map(c => c.key), - userAgent, - }); - const client = wrapper(axios).create({ timeout: 20000, maxRedirects: 10, @@ -409,119 +373,21 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki }, }); - // Track request timings - const requestTimings = new Map(); - - // Add request interceptor for detailed logging - client.interceptors.request.use( - config => { - const requestStart = Date.now(); - const reqKey = `${config.method}-${config.url}`; - requestTimings.set(reqKey, requestStart); - - console.log(`[${requestId}] >>> Outgoing request`, { - method: config.method?.toUpperCase(), - url: config.url, - headers: config.headers, - hasData: !!config.data, - dataLength: config.data ? String(config.data).length : 0, - }); - return config; - }, - error => { - console.error(`[${requestId}] Request interceptor error`, error); - return Promise.reject(error); - } - ); - - // Add response interceptor for detailed logging - client.interceptors.response.use( - response => { - const reqKey = `${response.config.method}-${response.config.url}`; - const startTime = requestTimings.get(reqKey) || Date.now(); - const duration = Date.now() - startTime; - requestTimings.delete(reqKey); - - console.log(`[${requestId}] <<< Incoming response`, { - status: response.status, - statusText: response.statusText, - duration, - headers: response.headers, - dataLength: response.data ? String(response.data).length : 0, - url: response.config.url, - }); - return response; - }, - error => { - const reqKey = `${error.config?.method}-${error.config?.url}`; - const startTime = requestTimings.get(reqKey) || Date.now(); - const duration = Date.now() - startTime; - requestTimings.delete(reqKey); - - console.error(`[${requestId}] <<< Error response`, { - duration, - status: error.response?.status, - statusText: error.response?.statusText, - headers: error.response?.headers, - url: error.config?.url, - code: error.code, - message: error.message, - }); - return Promise.reject(error); - } - ); - - console.log(`[${requestId}] Searching for case number ${caseNumber}`); + console.log(`Searching for case number ${caseNumber}`); // Step 1: Submit the search form (following the Insomnia export) const searchFormData = new URLSearchParams(); searchFormData.append('caseCriteria.SearchCriteria', caseNumber); searchFormData.append('caseCriteria.SearchCases', 'true'); - const searchUrl = `${portalUrl}/Portal/SmartSearch/SmartSearch/SmartSearch`; - console.log(`[${requestId}] POST ${searchUrl}`, { - formData: Object.fromEntries(searchFormData.entries()), - headers: { - 'Content-Type': 'application/x-www-form-urlencoded', - Origin: portalUrl, - 'User-Agent': userAgent, - }, - }); - - const searchStartTime = Date.now(); - const searchResponse = await client.post(searchUrl, searchFormData); - timings.searchRequest = Date.now() - searchStartTime; - - console.log(`[${requestId}] Search form submission response`, { - status: searchResponse.status, - statusText: searchResponse.statusText, - duration: timings.searchRequest, - headers: searchResponse.headers, - redirects: searchResponse.request?._redirectable?._redirectCount, - }); + const searchResponse = await client.post(`${portalUrl}/Portal/SmartSearch/SmartSearch/SmartSearch`, searchFormData); if (searchResponse.status !== 200) { const errorMessage = `Search request failed with status ${searchResponse.status}`; - const responseBody = - typeof searchResponse.data === 'string' - ? searchResponse.data.substring(0, 1000) - : JSON.stringify(searchResponse.data).substring(0, 1000); - - console.error(`[${requestId}] Search request failed`, { - status: searchResponse.status, - statusText: searchResponse.statusText, - headers: searchResponse.headers, - bodyPreview: responseBody, - duration: timings.searchRequest, - }); await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { - requestId, caseNumber, statusCode: searchResponse.status, - statusText: searchResponse.statusText, - duration: timings.searchRequest, - bodyPreview: responseBody, resource: 'portal-search', }); @@ -535,43 +401,14 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki } // Step 2: Get the search results page - const resultsUrl = `${portalUrl}/Portal/SmartSearch/SmartSearchResults`; - console.log(`[${requestId}] GET ${resultsUrl}`); - - const resultsStartTime = Date.now(); - const resultsResponse = await client.get(resultsUrl); - timings.resultsRequest = Date.now() - resultsStartTime; - - console.log(`[${requestId}] Search results response`, { - status: resultsResponse.status, - statusText: resultsResponse.statusText, - duration: timings.resultsRequest, - headers: resultsResponse.headers, - contentLength: resultsResponse.data?.length || 0, - }); + const resultsResponse = await client.get(`${portalUrl}/Portal/SmartSearch/SmartSearchResults`); if (resultsResponse.status !== 200) { const errorMessage = `Results request failed with status ${resultsResponse.status}`; - const responseBody = - typeof resultsResponse.data === 'string' - ? resultsResponse.data.substring(0, 1000) - : JSON.stringify(resultsResponse.data).substring(0, 1000); - - console.error(`[${requestId}] Results request failed`, { - status: resultsResponse.status, - statusText: resultsResponse.statusText, - headers: resultsResponse.headers, - bodyPreview: responseBody, - duration: timings.resultsRequest, - }); await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { - requestId, caseNumber, statusCode: resultsResponse.status, - statusText: resultsResponse.statusText, - duration: timings.resultsRequest, - bodyPreview: responseBody, resource: 'portal-search-results', }); @@ -588,16 +425,8 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki if (resultsResponse.data.includes('Smart Search is having trouble processing your search')) { const errorMessage = 'Smart Search is having trouble processing your search. Please try again later.'; - console.error(`[${requestId}] Portal smart search error`, { - caseNumber, - totalDuration: Date.now() - startTime, - timings, - }); - await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { - requestId, caseNumber, - timings, resource: 'smart-search', }); @@ -611,25 +440,14 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki } // Step 3: Extract the case ID from the response using cheerio - const parseStartTime = Date.now(); const $ = cheerio.load(resultsResponse.data); - timings.htmlParse = Date.now() - parseStartTime; // Look for anchor tags with class "caseLink" and get the data-caseid attribute // From the Insomnia export's after-response script const caseLinks = $('a.caseLink'); - console.log(`[${requestId}] Parsed HTML results`, { - caseLinksFound: caseLinks.length, - parseDuration: timings.htmlParse, - totalDuration: Date.now() - startTime, - }); - if (caseLinks.length === 0) { - console.log(`[${requestId}] No cases found for case number ${caseNumber}`, { - timings, - totalDuration: Date.now() - startTime, - }); + console.log(`No cases found for case number ${caseNumber}`); return { caseId: null, error: { @@ -645,18 +463,8 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki if (!caseId) { const errorMessage = `No case ID found in search results for ${caseNumber}`; - console.error(`[${requestId}] No case ID attribute found`, { - caseLinksFound: caseLinks.length, - firstLinkHtml: caseLinks.first().html()?.substring(0, 200), - timings, - totalDuration: Date.now() - startTime, - }); - await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', new Error(errorMessage), { - requestId, caseNumber, - caseLinksFound: caseLinks.length, - timings, resource: 'case-search-results', }); return { @@ -668,56 +476,13 @@ export async function fetchCaseIdFromPortal(caseNumber: string, cookieJar: Cooki }; } - const totalDuration = Date.now() - startTime; - console.log(`[${requestId}] Found case ID ${caseId} for case number ${caseNumber}`, { - timings, - totalDuration, - }); - + console.log(`Found case ID ${caseId} for case number ${caseNumber}`); return { caseId }; } catch (error) { - const totalDuration = Date.now() - startTime; - const axiosError = error as any; - - // Enhanced error logging with request/response details - const errorDetails: Record = { - requestId, + await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', error as Error, { caseNumber, - timings, - totalDuration, resource: 'case-id-fetch', - }; - - // Capture axios-specific error details - if (axiosError.response) { - // The request was made and the server responded with a status code - // that falls out of the range of 2xx - errorDetails.responseStatus = axiosError.response.status; - errorDetails.responseStatusText = axiosError.response.statusText; - errorDetails.responseHeaders = axiosError.response.headers; - - // Capture response body (truncated) - if (axiosError.response.data) { - const responseBody = - typeof axiosError.response.data === 'string' ? axiosError.response.data : JSON.stringify(axiosError.response.data); - errorDetails.responseBodyPreview = responseBody.substring(0, 1000); - } - } else if (axiosError.request) { - // The request was made but no response was received - errorDetails.requestMade = true; - errorDetails.noResponse = true; - errorDetails.requestTimeout = axiosError.code === 'ECONNABORTED'; - } else { - // Something happened in setting up the request that triggered an Error - errorDetails.setupError = true; - } - - errorDetails.errorCode = axiosError.code; - errorDetails.errorMessage = axiosError.message; - - console.error(`[${requestId}] Error fetching case ID from portal`, errorDetails); - - await AlertService.logError(Severity.ERROR, AlertCategory.PORTAL, '', error as Error, errorDetails); + }); return { caseId: null,