From b3dabff7db9172c2205627e851e51360761cd545 Mon Sep 17 00:00:00 2001 From: Tobbe Lundberg Date: Sun, 27 Jul 2025 13:27:54 +0200 Subject: [PATCH] chore(api-server): Perf logging --- .github/workflows/ci.yml | 20 ++ .github/workflows/diagnose-timeouts.yml | 119 +++++++ packages/api-server/package.json | 1 + packages/api-server/scripts/README.md | 218 ++++++++++++ .../api-server/scripts/diagnose-timeouts.mjs | 334 ++++++++++++++++++ .../src/__tests__/createServer.test.ts | 53 ++- ...t-diagnostic-2025-07-27T11-38-56-701Z.json | 41 +++ packages/api-server/src/createServer.ts | 35 ++ packages/api-server/src/plugins/api.ts | 27 +- .../api-server/src/plugins/lambdaLoader.ts | 25 ++ 10 files changed, 871 insertions(+), 2 deletions(-) create mode 100644 .github/workflows/diagnose-timeouts.yml create mode 100644 packages/api-server/scripts/README.md create mode 100644 packages/api-server/scripts/diagnose-timeouts.mjs create mode 100644 packages/api-server/src/__tests__/fixtures/graphql/cedar-app/timeout-diagnostic-2025-07-27T11-38-56-701Z.json diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index bdab9c393a..762d85fda9 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -123,6 +123,26 @@ jobs: - name: ๐Ÿงช Test run: yarn test-ci --minWorkers=1 --maxWorkers=${{ steps.cpu-cores.outputs.count }} + # Run timeout diagnostics if tests failed on Windows + - name: ๐Ÿ” Diagnose Timeout Issues (Windows) + if: failure() && matrix.os == 'windows-latest' + run: | + echo "::group::Running timeout diagnostics for Windows" + cd packages/api-server + yarn diagnose:timeouts 10 30000 + echo "::endgroup::" + continue-on-error: true + + # Upload diagnostic report if it was generated + - name: ๐Ÿ“‹ Upload Timeout Diagnostic Report + if: failure() && matrix.os == 'windows-latest' + uses: actions/upload-artifact@v4 + with: + name: timeout-diagnostic-report-${{ matrix.os }} + path: packages/api-server/timeout-diagnostic-report.json + retention-days: 30 + continue-on-error: true + build-lint-test-skip: needs: detect-changes if: needs.detect-changes.outputs.code == 'false' diff --git a/.github/workflows/diagnose-timeouts.yml b/.github/workflows/diagnose-timeouts.yml new file mode 100644 index 0000000000..c1f84ec678 --- /dev/null +++ b/.github/workflows/diagnose-timeouts.yml @@ -0,0 +1,119 @@ +name: ๐Ÿ” Diagnose Timeout Issues + +on: + workflow_dispatch: + inputs: + os: + description: 'Operating system to test' + required: true + default: 'windows-latest' + type: choice + options: + - ubuntu-latest + - windows-latest + - macos-latest + iterations: + description: 'Number of test iterations to run' + required: true + default: '20' + type: string + timeout_ms: + description: 'Timeout in milliseconds' + required: true + default: '30000' + type: string + enable_debug: + description: 'Enable detailed debug logging' + required: false + default: true + type: boolean + +permissions: + contents: read + +jobs: + timeout-diagnostics: + name: ๐Ÿ” Timeout Diagnostics / ${{ inputs.os }} + runs-on: ${{ inputs.os }} + + steps: + - name: Checkout repository + uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 # v4 + + - name: Set up job + uses: ./.github/actions/set-up-job + + - name: Display test configuration + run: | + echo "::notice::Running timeout diagnostics with the following configuration:" + echo "::notice::OS: ${{ inputs.os }}" + echo "::notice::Iterations: ${{ inputs.iterations }}" + echo "::notice::Timeout: ${{ inputs.timeout_ms }}ms" + echo "::notice::Debug logging: ${{ inputs.enable_debug }}" + echo "::notice::Platform: ${{ runner.os }}" + echo "::notice::Node version: $(node --version)" + + - name: Run timeout diagnostics + id: diagnostics + run: | + cd packages/api-server + yarn diagnose:timeouts ${{ inputs.iterations }} ${{ inputs.timeout_ms }} + env: + CEDAR_DEBUG_TIMEOUT: ${{ inputs.enable_debug && '1' || '0' }} + continue-on-error: true + + - name: Upload diagnostic report + if: always() + uses: actions/upload-artifact@v4 + with: + name: timeout-diagnostic-report-${{ inputs.os }}-${{ github.run_number }} + path: packages/api-server/timeout-diagnostic-report.json + retention-days: 30 + + - name: Display quick summary + if: always() + run: | + if [ -f packages/api-server/timeout-diagnostic-report.json ]; then + echo "::group::Diagnostic Summary" + cd packages/api-server + node -e " + const report = JSON.parse(require('fs').readFileSync('timeout-diagnostic-report.json', 'utf8')); + console.log('Total iterations:', report.metadata.iterations); + console.log('Success rate:', report.summary.successRate + '%'); + console.log('Timeout rate:', report.summary.timeoutRate + '%'); + console.log('Average time:', report.summary.avgTime.toFixed(2) + 'ms'); + console.log('Max time:', report.summary.maxTime.toFixed(2) + 'ms'); + if (report.summary.timeoutRate > 0) { + console.log('::warning::Timeouts detected - this confirms the issue exists'); + } else { + console.log('::notice::No timeouts detected - issue may be environment-specific'); + } + " + echo "::endgroup::" + else + echo "::error::No diagnostic report generated" + fi + shell: bash + + - name: Set job conclusion + if: always() + run: | + if [ -f packages/api-server/timeout-diagnostic-report.json ]; then + cd packages/api-server + TIMEOUT_RATE=$(node -e " + const report = JSON.parse(require('fs').readFileSync('timeout-diagnostic-report.json', 'utf8')); + console.log(report.summary.timeoutRate); + ") + + if (( $(echo "$TIMEOUT_RATE > 0" | bc -l) )); then + echo "::warning::Timeout diagnostics completed with $TIMEOUT_RATE% timeout rate" + exit 1 + else + echo "::notice::Timeout diagnostics completed successfully - no timeouts detected" + exit 0 + fi + else + echo "::error::Diagnostic script failed to generate report" + exit 1 + fi + shell: bash diff --git a/packages/api-server/package.json b/packages/api-server/package.json index 3e08e5150e..8bc96f917a 100644 --- a/packages/api-server/package.json +++ b/packages/api-server/package.json @@ -23,6 +23,7 @@ "build:pack": "yarn pack -o cedarjs-api-server.tgz", "build:types": "tsc --build --verbose tsconfig.build.json", "build:watch": "nodemon --watch src --ext \"js,jsx,ts,tsx\" --ignore dist --exec \"yarn build && yarn fix:permissions\"", + "diagnose:timeouts": "yarn build && node scripts/diagnose-timeouts.mjs", "fix:permissions": "chmod +x dist/index.js; chmod +x dist/watch.js", "prepublishOnly": "NODE_ENV=production yarn build", "test": "vitest run", diff --git a/packages/api-server/scripts/README.md b/packages/api-server/scripts/README.md new file mode 100644 index 0000000000..113b27c370 --- /dev/null +++ b/packages/api-server/scripts/README.md @@ -0,0 +1,218 @@ +# API Server Scripts + +This directory contains diagnostic and utility scripts for the CedarJS API Server package. + +## Timeout Diagnostics + +### Overview + +The `diagnose-timeouts.mjs` script helps identify and analyze intermittent timeout issues that can occur during server creation, particularly on Windows environments. + +### Background + +We've observed intermittent timeouts in CI, specifically: + +- Occurs primarily on Windows +- Happens during `createServer()` calls in tests +- Manifests as 10-second timeouts in `beforeAll` hooks +- Is sporadic rather than consistent + +### Usage + +#### Local Development + +```bash +# Run basic diagnostics (10 iterations) +yarn diagnose:timeouts + +# Run with custom parameters +yarn diagnose:timeouts [iterations] [timeout-ms] + +# Examples: +yarn diagnose:timeouts 20 30000 # 20 iterations, 30s timeout +yarn diagnose:timeouts 5 15000 # 5 iterations, 15s timeout +``` + +#### With Debug Logging + +```bash +# Enable detailed logging to see where timeouts occur +CEDAR_DEBUG_TIMEOUT=1 yarn diagnose:timeouts 10 +``` + +#### In CI/CD + +The diagnostic script is automatically triggered when: + +1. Tests fail on Windows in the main CI workflow +2. Manual execution via the "Diagnose Timeout Issues" workflow + +### Script Behavior + +The diagnostic script: + +1. **Creates multiple server instances** in sequence +2. **Measures timing** for each creation attempt +3. **Detects timeouts** and other errors +4. **Generates a detailed report** with statistics +5. **Provides recommendations** based on findings + +### Output + +#### Console Output + +- Real-time progress for each iteration +- Success/timeout/error status +- Final summary with statistics +- Platform-specific recommendations + +#### Report File + +- `timeout-diagnostic-report.json` (CI) +- `timeout-diagnostic-TIMESTAMP.json` (local) + +Contains: + +```json +{ + "metadata": { + "platform": "win32", + "nodeVersion": "v20.x.x", + "iterations": 10, + "timeoutMs": 30000 + }, + "summary": { + "successful": 8, + "timeouts": 2, + "errors": 0, + "successRate": 80.0, + "timeoutRate": 20.0, + "avgTime": 1250.45, + "maxTime": 2100.23 + }, + "details": [...] +} +``` + +### Debug Logging + +When `CEDAR_DEBUG_TIMEOUT=1` is set, detailed logs show: + +- Server creation steps +- Plugin registration timing +- Function loading progress +- GraphQL import status +- Hook registration timing + +Example debug output: + +``` +[CEDAR_DEBUG] 2024-01-15T10:30:00.000Z - createServer: Starting +[CEDAR_DEBUG] 2024-01-15T10:30:00.100Z - createServer: Options resolved +[CEDAR_DEBUG] 2024-01-15T10:30:00.150Z - redwoodFastifyAPI: Loading functions from dist +[CEDAR_DEBUG] 2024-01-15T10:30:01.200Z - setLambdaFunctions: Import of hello completed +``` + +### CI Integration + +#### Automatic Triggering + +The diagnostic runs automatically when tests fail on Windows: + +```yaml +- name: ๐Ÿ” Diagnose Timeout Issues (Windows) + if: failure() && matrix.os == 'windows-latest' + run: yarn diagnose:timeouts 10 30000 +``` + +#### Manual Workflow + +Use the "Diagnose Timeout Issues" workflow dispatch to: + +- Test specific operating systems +- Adjust iteration count and timeout values +- Enable/disable debug logging +- Run diagnostics on-demand + +#### Artifacts + +Failed CI runs upload diagnostic reports as artifacts: + +- Retention: 30 days +- Name: `timeout-diagnostic-report-{os}-{run-number}` +- Location: GitHub Actions artifacts + +### Interpreting Results + +#### Success Rate < 100% + +- **High timeout rate (>10%)**: Likely environment-specific timing issue +- **Occasional timeouts (<5%)**: May be acceptable, consider increasing timeouts +- **Consistent errors**: Check for configuration or dependency issues + +#### Common Patterns + +- **Windows timeout clusters**: Often related to file system or port binding +- **Slow function imports**: May indicate disk I/O or module resolution issues +- **GraphQL import hangs**: Check for missing exports or circular dependencies + +### Recommendations + +#### For Windows Timeout Issues + +1. **Increase hook timeout** in `vitest.config.mts` +2. **Check antivirus settings** (real-time scanning can slow file operations) +3. **Verify system resources** (CPU, memory, disk I/O) +4. **Consider retry logic** for CI environments + +#### For Consistent Failures + +1. **Review debug logs** to identify hanging operations +2. **Check fixture files** for missing exports or imports +3. **Verify test environment** setup and teardown +4. **Monitor resource cleanup** between test iterations + +### Troubleshooting + +#### Script Won't Run + +```bash +# Ensure the package is built +yarn build + +# Check Node.js version +node --version + +# Verify fixture files exist +ls -la src/__tests__/fixtures/graphql/cedar-app/ +``` + +#### No Report Generated + +- Check file permissions in output directory +- Verify script has write access +- Look for uncaught exceptions in console output + +#### High Error Rate + +- Review error details in console output +- Check test fixture integrity +- Verify all dependencies are installed + +### Contributing + +When modifying the diagnostic script: + +1. **Test locally** on multiple platforms +2. **Verify CI integration** doesn't break existing workflows +3. **Update documentation** for new features or parameters +4. **Add appropriate logging** for new diagnostic points + +### Related Files + +- `../src/createServer.ts` - Main server creation logic with debug logging +- `../src/plugins/api.ts` - API plugin with debug logging +- `../src/plugins/lambdaLoader.ts` - Function loading with debug logging +- `../vitest.config.mts` - Test configuration with hook timeout +- `../../.github/workflows/ci.yml` - CI integration +- `../../.github/workflows/diagnose-timeouts.yml` - Manual diagnostic workflow diff --git a/packages/api-server/scripts/diagnose-timeouts.mjs b/packages/api-server/scripts/diagnose-timeouts.mjs new file mode 100644 index 0000000000..3341b75bb6 --- /dev/null +++ b/packages/api-server/scripts/diagnose-timeouts.mjs @@ -0,0 +1,334 @@ +#!/usr/bin/env node + +/* eslint-env node */ + +/** + * CI-friendly diagnostic script for debugging Windows timeout issues in createServer tests + * + * Usage: + * node scripts/diagnose-timeouts.mjs [iterations] [timeout-ms] + * + * Environment variables: + * CEDAR_DEBUG_TIMEOUT=1 - Enable detailed logging + * CI=true - CI mode (affects output formatting) + */ + +import { writeFile } from 'node:fs/promises' +import { resolve } from 'node:path' +import { performance } from 'node:perf_hooks' +import { setTimeout } from 'node:timers/promises' + +// Configuration +const DEFAULT_ITERATIONS = process.env.CI ? 5 : 10 +const DEFAULT_TIMEOUT_MS = 30000 +const DELAY_BETWEEN_RUNS = process.env.CI ? 500 : 1000 + +// Parse arguments +const iterations = parseInt(process.argv[2]) || DEFAULT_ITERATIONS +const timeoutMs = parseInt(process.argv[3]) || DEFAULT_TIMEOUT_MS + +// Enable diagnostic mode +process.env.NODE_ENV = 'test' +process.env.CEDAR_DEBUG_TIMEOUT = '1' + +// Set up test environment like the actual test +const fixturesPath = new URL( + '../src/__tests__/fixtures/graphql/cedar-app', + import.meta.url, +).pathname +process.env.RWJS_CWD = fixturesPath + +// Change to the fixture directory before importing +process.chdir(fixturesPath) + +const isCI = process.env.CI === 'true' + +// CI-friendly logging +function log(message, level = 'info') { + const timestamp = new Date().toISOString() + const prefix = isCI ? `::${level}::` : '' + console.log(`${prefix}[${timestamp}] ${message}`) +} + +function logError(message) { + log(message, 'error') +} + +function logWarning(message) { + log(message, 'warning') +} + +function logGroup(title, fn) { + if (isCI) { + console.log(`::group::${title}`) + fn() + console.log('::endgroup::') + } else { + console.log(`\n๐Ÿ“‹ ${title}`) + console.log('='.repeat(title.length + 4)) + fn() + } +} + +// Initialize results tracking +const results = { + successful: 0, + timeouts: 0, + errors: 0, + times: [], + details: [], + systemInfo: { + platform: process.platform, + nodeVersion: process.version, + isCI: isCI, + timestamp: new Date().toISOString(), + }, +} + +log(`Starting timeout diagnostics`) +log(`Platform: ${process.platform}, Node: ${process.version}`) +log(`Iterations: ${iterations}, Timeout: ${timeoutMs}ms`) +log(`Test fixture: ${fixturesPath}`) + +// Import createServer after setting up the environment +const { createServer } = await import('../dist/createServer.js') + +async function runSingleTest(iteration) { + const startTime = performance.now() + const label = `Test ${iteration + 1}/${iterations}` + + if (!isCI) { + process.stdout.write(`${label}... `) + } + + try { + // Create a timeout promise + const timeoutPromise = setTimeout(timeoutMs).then(() => { + throw new Error(`TIMEOUT_${timeoutMs}`) + }) + + // Race between server creation and timeout + const server = await Promise.race([createServer(), timeoutPromise]) + + const duration = performance.now() - startTime + + // Clean up + if (server && typeof server.close === 'function') { + await server.close() + } + + results.successful++ + results.times.push(duration) + results.details.push({ + iteration: iteration + 1, + status: 'success', + duration, + timestamp: new Date().toISOString(), + }) + + if (isCI) { + log(`${label} SUCCESS (${duration.toFixed(2)}ms)`) + } else { + console.log(`โœ… (${duration.toFixed(2)}ms)`) + } + + return true + } catch (error) { + const duration = performance.now() - startTime + + if (error.message.includes('TIMEOUT_')) { + results.timeouts++ + results.details.push({ + iteration: iteration + 1, + status: 'timeout', + duration, + error: error.message, + timestamp: new Date().toISOString(), + }) + + if (isCI) { + logWarning(`${label} TIMEOUT after ${duration.toFixed(2)}ms`) + } else { + console.log(`โฐ TIMEOUT`) + } + } else { + results.errors++ + results.details.push({ + iteration: iteration + 1, + status: 'error', + duration, + error: error.message, + stack: error.stack?.split('\n').slice(0, 5).join('\n'), // Truncate stack for CI + timestamp: new Date().toISOString(), + }) + + if (isCI) { + logError(`${label} ERROR: ${error.message}`) + } else { + console.log(`โŒ ${error.message}`) + } + } + + return false + } +} + +async function runDiagnosticTests() { + log(`Running ${iterations} diagnostic iterations...`) + + for (let i = 0; i < iterations; i++) { + await runSingleTest(i) + + // Add delay between runs to avoid resource conflicts + if (i < iterations - 1) { + await setTimeout(DELAY_BETWEEN_RUNS) + } + } + + // Calculate statistics + const totalTime = results.times.reduce((sum, time) => sum + time, 0) + const avgTime = + results.times.length > 0 ? totalTime / results.times.length : 0 + const minTime = results.times.length > 0 ? Math.min(...results.times) : 0 + const maxTime = results.times.length > 0 ? Math.max(...results.times) : 0 + const successRate = ((results.successful / iterations) * 100).toFixed(1) + const timeoutRate = ((results.timeouts / iterations) * 100).toFixed(1) + + // Print summary + logGroup('DIAGNOSTIC RESULTS', () => { + log(`Total iterations: ${iterations}`) + log(`Successful: ${results.successful} (${successRate}%)`) + log(`Timeouts: ${results.timeouts} (${timeoutRate}%)`) + log( + `Errors: ${results.errors} (${((results.errors / iterations) * 100).toFixed(1)}%)`, + ) + + if (results.times.length > 0) { + log(`Average time: ${avgTime.toFixed(2)}ms`) + log(`Min time: ${minTime.toFixed(2)}ms`) + log(`Max time: ${maxTime.toFixed(2)}ms`) + } + }) + + // Analysis and recommendations + if (results.timeouts > 0) { + logGroup('TIMEOUT ANALYSIS', () => { + logWarning( + `Timeout rate: ${timeoutRate}% - This indicates a timing issue`, + ) + + if (process.platform === 'win32') { + log('Windows-specific recommendations:') + log('- Consider increasing hookTimeout in vitest.config.mts') + log('- Check for antivirus interference') + log('- Verify adequate system resources') + log('- Consider retry logic for CI') + } + }) + } + + if (results.errors > 0) { + logGroup('ERROR ANALYSIS', () => { + results.details + .filter((d) => d.status === 'error') + .forEach((detail) => { + logError(`Iteration ${detail.iteration}: ${detail.error}`) + }) + }) + } + + // Save detailed results + const reportData = { + metadata: { + ...results.systemInfo, + iterations, + timeoutMs, + testCommand: process.argv.join(' '), + }, + summary: { + successful: results.successful, + timeouts: results.timeouts, + errors: results.errors, + successRate: parseFloat(successRate), + timeoutRate: parseFloat(timeoutRate), + avgTime, + minTime, + maxTime, + }, + details: results.details, + } + + // Determine output file + const timestamp = new Date().toISOString().replace(/[:.]/g, '-') + const filename = process.env.CI + ? `timeout-diagnostic-report.json` + : `timeout-diagnostic-${timestamp}.json` + + const reportPath = resolve(filename) + + try { + await writeFile(reportPath, JSON.stringify(reportData, null, 2)) + log(`Diagnostic report saved: ${reportPath}`) + + // In CI, also output key metrics for GitHub Actions + if (isCI) { + console.log(`::set-output name=success_rate::${successRate}`) + console.log(`::set-output name=timeout_rate::${timeoutRate}`) + console.log(`::set-output name=avg_time::${avgTime.toFixed(2)}`) + console.log(`::set-output name=report_file::${reportPath}`) + } + } catch (err) { + logError(`Could not save diagnostic report: ${err.message}`) + } + + // Final assessment + if (results.timeouts > 0) { + logWarning( + `Detected ${results.timeouts} timeouts out of ${iterations} runs`, + ) + if (isCI) { + logWarning( + 'This confirms the intermittent timeout issue exists in this environment', + ) + } + return 1 // Exit code indicating timeouts detected + } else if (results.errors > 0) { + logError(`Detected ${results.errors} errors out of ${iterations} runs`) + return 2 // Exit code indicating errors + } else { + log( + `All ${iterations} tests completed successfully - no timeout issues detected`, + ) + return 0 // Success + } +} + +// Error handling +process.on('SIGINT', () => { + logWarning('Interrupted by user') + process.exit(130) +}) + +process.on('uncaughtException', (error) => { + logError(`Uncaught exception: ${error.message}`) + if (!isCI) { + console.error(error.stack) + } + process.exit(1) +}) + +process.on('unhandledRejection', (reason) => { + logError(`Unhandled rejection: ${reason}`) + process.exit(1) +}) + +// Run the diagnostic tests +runDiagnosticTests() + .then((exitCode) => process.exit(exitCode)) + .catch((error) => { + logError(`Diagnostic script failed: ${error.message}`) + if (!isCI) { + console.error(error.stack) + } + process.exit(1) + }) diff --git a/packages/api-server/src/__tests__/createServer.test.ts b/packages/api-server/src/__tests__/createServer.test.ts index 25d37aab6d..92af2e926d 100644 --- a/packages/api-server/src/__tests__/createServer.test.ts +++ b/packages/api-server/src/__tests__/createServer.test.ts @@ -21,6 +21,15 @@ import { getDefaultCreateServerOptions, } from '../createServerHelpers' +// Performance monitoring for debugging timeouts +const perfLog = (message: string, startTime?: number) => { + const timestamp = new Date().toISOString() + const duration = startTime + ? ` (${(performance.now() - startTime).toFixed(2)}ms)` + : '' + console.log(`[PERF] ${timestamp} - ${message}${duration}`) +} + // Set up RWJS_CWD. let original_RWJS_CWD: string | undefined @@ -44,9 +53,16 @@ describe('createServer', () => { let server: Awaited> beforeAll(async () => { + const startTime = performance.now() + perfLog('beforeAll: Starting server creation') + consoleWarnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}) consoleLogSpy = vi.spyOn(console, 'log').mockImplementation(() => {}) + + perfLog('beforeAll: Console spies set up, creating server') server = await createServer() + + perfLog('beforeAll: Server creation complete', startTime) }) afterEach(() => { @@ -54,9 +70,19 @@ describe('createServer', () => { }) afterAll(async () => { - await server?.close() + const startTime = performance.now() + perfLog('afterAll: Starting cleanup') + + if (server) { + perfLog('afterAll: Closing server') + await server.close() + perfLog('afterAll: Server closed') + } + vi.mocked(console.log).mockRestore() vi.mocked(console.warn).mockRestore() + + perfLog('afterAll: Cleanup complete', startTime) }) it('serves functions', async () => { @@ -108,6 +134,9 @@ describe('createServer', () => { // // This should be fixed so that all logs go to the same place it("doesn't handle logs consistently", async () => { + const testStartTime = performance.now() + perfLog('logs test: Starting') + // Here we create a logger that outputs to an array. const loggerLogs: Record | string>[] = [] const stream = build(async (source) => { @@ -118,14 +147,21 @@ describe('createServer', () => { const logger = pino(stream) // Generate some logs. + perfLog('logs test: Creating server with custom logger') const server = await createServer({ logger }) + perfLog('logs test: Server created, making request') + const res = await server.inject({ method: 'GET', url: '/hello', }) expect(res.json()).toEqual({ data: 'hello function' }) + + perfLog('logs test: Request completed, starting server listen') await server.listen({ port: 8910 }) + perfLog('logs test: Server listening, closing server') await server.close() + perfLog('logs test: Server closed', testStartTime) // We expect console log to be called with `withFunctions` logs. expect(consoleLogSpy.mock.calls[0][0]).toMatch(/Importing Server Functions/) @@ -192,8 +228,13 @@ describe('createServer', () => { describe('`server.start`', () => { it('starts the server using [api].port in redwood.toml if none is specified', async () => { + const testStartTime = performance.now() + perfLog('server.start test: Starting') + const server = await createServer() + perfLog('server.start test: Server created, starting server') await server.start() + perfLog('server.start test: Server started, checking address') const address = server.server.address() @@ -203,14 +244,22 @@ describe('createServer', () => { expect(address.port).toBe(getConfig().api.port) + perfLog('server.start test: Closing server') await server.close() + perfLog('server.start test: Complete', testStartTime) }) it('the `REDWOOD_API_PORT` env var takes precedence over [api].port', async () => { + const testStartTime = performance.now() + perfLog('REDWOOD_API_PORT test: Starting') + process.env.REDWOOD_API_PORT = '8920' + perfLog('REDWOOD_API_PORT test: Creating server') const server = await createServer() + perfLog('REDWOOD_API_PORT test: Server created, starting') await server.start() + perfLog('REDWOOD_API_PORT test: Server started, checking address') const address = server.server.address() @@ -220,9 +269,11 @@ describe('createServer', () => { expect(address.port).toBe(+process.env.REDWOOD_API_PORT) + perfLog('REDWOOD_API_PORT test: Closing server') await server.close() delete process.env.REDWOOD_API_PORT + perfLog('REDWOOD_API_PORT test: Complete', testStartTime) }) }) }) diff --git a/packages/api-server/src/__tests__/fixtures/graphql/cedar-app/timeout-diagnostic-2025-07-27T11-38-56-701Z.json b/packages/api-server/src/__tests__/fixtures/graphql/cedar-app/timeout-diagnostic-2025-07-27T11-38-56-701Z.json new file mode 100644 index 0000000000..7fe79791c9 --- /dev/null +++ b/packages/api-server/src/__tests__/fixtures/graphql/cedar-app/timeout-diagnostic-2025-07-27T11-38-56-701Z.json @@ -0,0 +1,41 @@ +{ + "metadata": { + "platform": "darwin", + "nodeVersion": "v20.19.4", + "isCI": false, + "timestamp": "2025-07-27T11:38:54.432Z", + "iterations": 3, + "timeoutMs": 15000, + "testCommand": "/usr/local/bin/node /Users/tobbe/dev/cedarjs/cedar/packages/api-server/scripts/diagnose-timeouts.mjs 3 15000" + }, + "summary": { + "successful": 3, + "timeouts": 0, + "errors": 0, + "successRate": 100, + "timeoutRate": 0, + "avgTime": 66.55741699999983, + "minTime": 9.01766699999962, + "maxTime": 178.42075 + }, + "details": [ + { + "iteration": 1, + "status": "success", + "duration": 178.42075, + "timestamp": "2025-07-27T11:38:54.676Z" + }, + { + "iteration": 2, + "status": "success", + "duration": 12.233833999999888, + "timestamp": "2025-07-27T11:38:55.690Z" + }, + { + "iteration": 3, + "status": "success", + "duration": 9.01766699999962, + "timestamp": "2025-07-27T11:38:56.700Z" + } + ] +} \ No newline at end of file diff --git a/packages/api-server/src/createServer.ts b/packages/api-server/src/createServer.ts index ffe5d07a3c..459762441d 100644 --- a/packages/api-server/src/createServer.ts +++ b/packages/api-server/src/createServer.ts @@ -18,6 +18,15 @@ import type { } from './createServerHelpers.js' import { redwoodFastifyAPI } from './plugins/api.js' +// Diagnostic logging for timeout debugging +const isDiagnosticMode = + process.env.NODE_ENV === 'test' && process.env.CEDAR_DEBUG_TIMEOUT +function debugLog(message: string) { + if (isDiagnosticMode) { + console.log(`[CEDAR_DEBUG] ${new Date().toISOString()} - ${message}`) + } +} + // Load .env files if they haven't already been loaded. This makes importing this file effectful: // // ```js @@ -64,6 +73,8 @@ if (!process.env.REDWOOD_ENV_FILES_LOADED) { * ``` */ export async function createServer(options: CreateServerOptions = {}) { + debugLog('createServer: Starting') + const { apiRootPath, fastifyServerOptions, @@ -73,13 +84,17 @@ export async function createServer(options: CreateServerOptions = {}) { apiHost, } = resolveOptions(options) + debugLog('createServer: Options resolved') + // Warn about `api/server.config.js` + debugLog('createServer: Checking for server.config.js') const serverConfigPath = path.join( getPaths().base, getConfig().api.serverConfig, ) if (fs.existsSync(serverConfigPath)) { + debugLog('createServer: Found server.config.js, showing warning') console.warn( ansis.yellow( [ @@ -101,19 +116,24 @@ export async function createServer(options: CreateServerOptions = {}) { ), ) } + debugLog('createServer: Server config check complete') // Initialize the fastify instance + debugLog('createServer: Initializing fastify instance') const server: Server = Object.assign(fastify(fastifyServerOptions), { // `start` will get replaced further down in this file start: async () => { throw new Error('Not implemented yet') }, }) + debugLog('createServer: Fastify instance created') + debugLog('createServer: Adding onRequest hook') server.addHook('onRequest', (_req, _reply, done) => { getAsyncStoreInstance().run(new Map(), done) }) + debugLog('createServer: Registering redwoodFastifyAPI plugin') await server.register(redwoodFastifyAPI, { redwood: { apiRootPath, @@ -124,20 +144,30 @@ export async function createServer(options: CreateServerOptions = {}) { configureServer: configureApiServer, }, }) + debugLog('createServer: redwoodFastifyAPI plugin registered') // If we can find `api/dist/functions/graphql.js`, register the GraphQL plugin + debugLog('createServer: Searching for GraphQL function') const [graphqlFunctionPath] = await fg('dist/functions/graphql.{ts,js}', { cwd: getPaths().api.base, absolute: true, }) + debugLog( + `createServer: GraphQL search complete, found: ${graphqlFunctionPath || 'none'}`, + ) if (graphqlFunctionPath) { + debugLog('createServer: Importing GraphQL plugin') const { redwoodFastifyGraphQLServer } = await import('./plugins/graphql.js') + debugLog('createServer: GraphQL plugin imported, importing GraphQL options') // This comes from a babel plugin that's applied to // api/dist/functions/graphql.{ts,js} in user projects const { __rw_graphqlOptions } = await import( `file://${graphqlFunctionPath}` ) + debugLog( + 'createServer: GraphQL options imported, registering GraphQL server', + ) await server.register(redwoodFastifyGraphQLServer, { redwood: { @@ -145,14 +175,17 @@ export async function createServer(options: CreateServerOptions = {}) { graphql: __rw_graphqlOptions, }, }) + debugLog('createServer: GraphQL server registered') } // For baremetal and pm2. See https://github.com/redwoodjs/redwood/pull/4744 + debugLog('createServer: Adding onReady hook') server.addHook('onReady', (done) => { process.send?.('ready') done() }) + debugLog('createServer: Adding onListen hook') server.addHook('onListen', (done) => { console.log( `Server listening at ${ansis.magenta( @@ -170,6 +203,7 @@ export async function createServer(options: CreateServerOptions = {}) { * - `REDWOOD_API_PORT` * - [api].port in redwood.toml */ + debugLog('createServer: Setting up server.start method') server.start = (options: StartOptions = {}) => { return server.listen({ ...options, @@ -178,5 +212,6 @@ export async function createServer(options: CreateServerOptions = {}) { }) } + debugLog('createServer: Server creation complete') return server } diff --git a/packages/api-server/src/plugins/api.ts b/packages/api-server/src/plugins/api.ts index a6a7708301..4e7e78522c 100644 --- a/packages/api-server/src/plugins/api.ts +++ b/packages/api-server/src/plugins/api.ts @@ -5,13 +5,22 @@ import fastifyRawBody from 'fastify-raw-body' import type { GlobalContext } from '@cedarjs/context' import { getAsyncStoreInstance } from '@cedarjs/context/dist/store' -import { coerceRootPath } from '@cedarjs/fastify-web/dist/helpers' +import { coerceRootPath } from '@cedarjs/fastify-web/dist/helpers.js' import type { Server } from '../createServerHelpers.js' import { loadFastifyConfig } from '../fastify.js' import { lambdaRequestHandler, loadFunctionsFromDist } from './lambdaLoader.js' +// Diagnostic logging for timeout debugging +const isDiagnosticMode = + process.env.NODE_ENV === 'test' && process.env.CEDAR_DEBUG_TIMEOUT +function debugLog(message: string) { + if (isDiagnosticMode) { + console.log(`[CEDAR_DEBUG] ${new Date().toISOString()} - ${message}`) + } +} + export interface RedwoodFastifyAPIOptions { redwood: { apiRootPath?: string @@ -26,21 +35,28 @@ export async function redwoodFastifyAPI( fastify: FastifyInstance, opts: RedwoodFastifyAPIOptions, ) { + debugLog('redwoodFastifyAPI: Starting plugin registration') + const redwoodOptions = opts.redwood ?? {} redwoodOptions.apiRootPath ??= '/' redwoodOptions.apiRootPath = coerceRootPath(redwoodOptions.apiRootPath) redwoodOptions.fastGlobOptions ??= {} redwoodOptions.loadUserConfig ??= false + debugLog('redwoodFastifyAPI: Registering fastifyUrlData') fastify.register(fastifyUrlData) // Starting in Fastify v4, we have to await the fastifyRawBody plugin's registration // to ensure it's ready + debugLog('redwoodFastifyAPI: Registering fastifyRawBody') await fastify.register(fastifyRawBody) + debugLog('redwoodFastifyAPI: fastifyRawBody registered') + debugLog('redwoodFastifyAPI: Adding onRequest hook') fastify.addHook('onRequest', (_req, _reply, done) => { getAsyncStoreInstance().run(new Map(), done) }) + debugLog('redwoodFastifyAPI: Adding content type parsers') fastify.addContentTypeParser( ['application/x-www-form-urlencoded', 'multipart/form-data'], { parseAs: 'string' }, @@ -48,24 +64,33 @@ export async function redwoodFastifyAPI( ) if (redwoodOptions.loadUserConfig) { + debugLog('redwoodFastifyAPI: Loading user config') const { configureFastify } = await loadFastifyConfig() if (configureFastify) { + debugLog('redwoodFastifyAPI: Configuring fastify with user config') await configureFastify(fastify, { side: 'api', apiRootPath: redwoodOptions.apiRootPath, }) + debugLog('redwoodFastifyAPI: User config applied') } } // Run users custom server configuration function if (redwoodOptions.configureServer) { + debugLog('redwoodFastifyAPI: Running custom server configuration') await redwoodOptions.configureServer(fastify as Server) + debugLog('redwoodFastifyAPI: Custom server configuration complete') } + debugLog('redwoodFastifyAPI: Setting up route handlers') fastify.all(`${redwoodOptions.apiRootPath}:routeName`, lambdaRequestHandler) fastify.all(`${redwoodOptions.apiRootPath}:routeName/*`, lambdaRequestHandler) + + debugLog('redwoodFastifyAPI: Loading functions from dist') await loadFunctionsFromDist({ fastGlobOptions: redwoodOptions.fastGlobOptions, discoverFunctionsGlob: redwoodOptions.discoverFunctionsGlob, }) + debugLog('redwoodFastifyAPI: Plugin registration complete') } diff --git a/packages/api-server/src/plugins/lambdaLoader.ts b/packages/api-server/src/plugins/lambdaLoader.ts index d995b3b235..e727e33fbf 100644 --- a/packages/api-server/src/plugins/lambdaLoader.ts +++ b/packages/api-server/src/plugins/lambdaLoader.ts @@ -15,12 +15,24 @@ import { getPaths } from '@cedarjs/project-config' import { requestHandler } from '../requestHandlers/awsLambdaFastify.js' import { escape } from '../utils.js' +// Diagnostic logging for timeout debugging +const isDiagnosticMode = + process.env.NODE_ENV === 'test' && process.env.CEDAR_DEBUG_TIMEOUT +function debugLog(message: string) { + if (isDiagnosticMode) { + console.log(`[CEDAR_DEBUG] ${new Date().toISOString()} - ${message}`) + } +} + export type Lambdas = Record export const LAMBDA_FUNCTIONS: Lambdas = {} // Import the API functions and add them to the LAMBDA_FUNCTIONS object export const setLambdaFunctions = async (foundFunctions: string[]) => { + debugLog( + `setLambdaFunctions: Starting import of ${foundFunctions.length} functions`, + ) const tsImport = Date.now() console.log(ansis.dim.italic('Importing Server Functions... ')) @@ -28,7 +40,11 @@ export const setLambdaFunctions = async (foundFunctions: string[]) => { const ts = Date.now() const routeName = path.basename(fnPath).replace('.js', '') + debugLog( + `setLambdaFunctions: Importing function ${routeName} from ${fnPath}`, + ) const fnImport = await import(`file://${fnPath}`) + debugLog(`setLambdaFunctions: Import of ${routeName} completed`) const handler: Handler = (() => { if ('handler' in fnImport) { // ESModule export of handler - when using @@ -69,7 +85,9 @@ export const setLambdaFunctions = async (foundFunctions: string[]) => { ) }) + debugLog('setLambdaFunctions: Waiting for all imports to complete') await Promise.all(imports) + debugLog('setLambdaFunctions: All imports completed') console.log( ansis.dim.italic('...Done importing in ' + (Date.now() - tsImport) + ' ms'), @@ -85,19 +103,26 @@ type LoadFunctionsFromDistOptions = { export const loadFunctionsFromDist = async ( options: LoadFunctionsFromDistOptions = {}, ) => { + debugLog('loadFunctionsFromDist: Starting function discovery') const serverFunctions = findApiDistFunctions({ cwd: getPaths().api.base, options: options?.fastGlobOptions, discoverFunctionsGlob: options?.discoverFunctionsGlob, }) + debugLog( + `loadFunctionsFromDist: Found ${serverFunctions.length} functions: ${serverFunctions.map((f) => path.basename(f)).join(', ')}`, + ) // Place `GraphQL` serverless function at the start. const i = serverFunctions.findIndex((x) => path.basename(x) === 'graphql.js') if (i >= 0) { const graphQLFn = serverFunctions.splice(i, 1)[0] serverFunctions.unshift(graphQLFn) + debugLog('loadFunctionsFromDist: Moved GraphQL function to front') } + debugLog('loadFunctionsFromDist: Starting function loading') await setLambdaFunctions(serverFunctions) + debugLog('loadFunctionsFromDist: Function loading complete') } // NOTE: Copied from @cedarjs/internal/dist/files to avoid depending on