From 7a3165c7b1e4bb921e3b9de445ec2afca7f041f0 Mon Sep 17 00:00:00 2001 From: Matthew Podwysocki Date: Tue, 25 Aug 2026 12:16:13 -0400 Subject: [PATCH 1/2] fix: startup logging messages never reached clients Two compounding issues: the McpServer never declared the `logging` capability, so sendLoggingMessage was an unconditional no-op regardless of timing; and several of those calls also ran before server.connect(), which would drop them anyway since there's no connected client yet. Fixed both -- declared logging: {} in capabilities, and moved startup logging (.env status, tracing status, detected client capabilities) to after connect(), matching the ordering @mapbox/mcp-server already uses. Added an integration test that spawns the real built server and asserts a real client receives at least one startup log message. Co-Authored-By: Claude Sonnet 5 --- CHANGELOG.md | 4 ++ src/index.ts | 94 +++++++++++++++------------ test/integration/loggingOrder.test.ts | 69 ++++++++++++++++++++ 3 files changed, 124 insertions(+), 43 deletions(-) create mode 100644 test/integration/loggingOrder.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 8cdfb92..efa12ce 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ ## Unreleased +### Fixed + +- **Startup logging messages (`.env` status, tracing status, detected client capabilities) now actually reach clients.** The `McpServer` never declared the `logging` capability, so every `sendLoggingMessage` call was a silent no-op regardless of when it was sent. Several of those calls also ran before `server.connect(transport)`, which would have dropped them anyway even with the capability declared, since there's no connected client yet to receive a notification sent before the transport is connected. Fixed both: `logging: {}` is now declared in the server's capabilities, and startup logging is deferred until after `connect()`. Covered by a new integration test that spawns the real built server and asserts a real client receives at least one startup log message. + ### New Features - **`preview_style_tool` and `style_comparison_tool` no longer require an existing `accessToken`.** Both previously made `accessToken` a required `pk.*` input — meaning a caller had to already have (or separately go create) a public token before either tool would do anything, for even a quick one-off preview. `accessToken` is now optional on both: when omitted, the tool auto-generates a preview token from the server's own access token (the same pattern `geojson_preview_tool`'s resource already used) via a new shared `mintScopedPreviewToken` utility, so a first call needs no setup at all. diff --git a/src/index.ts b/src/index.ts index 6e824de..893f8b5 100644 --- a/src/index.ts +++ b/src/index.ts @@ -77,7 +77,8 @@ const server = new McpServer( listChanged: true // Advertise support for dynamic tool registration }, resources: {}, - prompts: {} + prompts: {}, + logging: {} } } ); @@ -148,44 +149,19 @@ prompts.forEach((prompt) => { }); async function main() { - // Send MCP logging messages about .env loading - if (envLoadError) { - server.server.sendLoggingMessage({ - level: 'warning', - data: `Failed to load .env file: ${envLoadError.message}` - }); - } else if (envLoadedCount > 0) { - server.server.sendLoggingMessage({ - level: 'info', - data: `Loaded ${envLoadedCount} environment variables from ${envPath}` - }); - } else { - server.server.sendLoggingMessage({ - level: 'debug', - data: 'No .env file found or file was empty' - }); - } - - // Initialize OpenTelemetry tracing if not in test mode + // Initialize OpenTelemetry tracing if not in test mode. This happens before + // the transport connects (below), so any resulting MCP logging messages are + // only sent once we're connected -- sending them earlier would be silently + // dropped, since there's no client to receive them yet. + let tracingInitialized = false; + let tracingInitError: Error | null = null; if (process.env.NODE_ENV !== 'test' && !process.env.VITEST) { try { await initializeTracing(); - - // Send MCP logging message about tracing status - if (isTracingInitialized()) { - server.server.sendLoggingMessage({ - level: 'info', - data: 'OpenTelemetry tracing enabled' - }); - } else { - server.server.sendLoggingMessage({ - level: 'debug', - data: 'OpenTelemetry tracing disabled (no OTLP endpoint configured)' - }); - } + tracingInitialized = isTracingInitialized(); // Record .env loading as a span (retrospectively since it happened before tracing init) - if (isTracingInitialized()) { + if (tracingInitialized) { const tracer = getTracer(); const span = tracer.startSpan('config.load_env', { attributes: { @@ -217,14 +193,50 @@ async function main() { span.end(); } } catch (error) { - // Log tracing initialization failure - server.server.sendLoggingMessage({ - level: 'warning', - data: `Failed to initialize tracing: ${error instanceof Error ? error.message : String(error)}` - }); + tracingInitError = + error instanceof Error ? error : new Error(String(error)); } } + // Start receiving messages on stdin and sending messages on stdout + const transport = new StdioServerTransport(); + await server.connect(transport); + + // Now that we're connected, send all the logging messages accumulated above. + if (envLoadError) { + server.server.sendLoggingMessage({ + level: 'warning', + data: `Failed to load .env file: ${envLoadError.message}` + }); + } else if (envLoadedCount > 0) { + server.server.sendLoggingMessage({ + level: 'info', + data: `Loaded ${envLoadedCount} environment variables from ${envPath}` + }); + } else { + server.server.sendLoggingMessage({ + level: 'debug', + data: 'No .env file found or file was empty' + }); + } + + if (tracingInitError) { + server.server.sendLoggingMessage({ + level: 'warning', + data: `Failed to initialize tracing: ${tracingInitError.message}` + }); + } else if (tracingInitialized) { + server.server.sendLoggingMessage({ + level: 'info', + data: 'OpenTelemetry tracing enabled' + }); + } else { + server.server.sendLoggingMessage({ + level: 'debug', + data: 'OpenTelemetry tracing disabled (no OTLP endpoint configured)' + }); + } + const relevantEnvVars = Object.freeze({ MAPBOX_ACCESS_TOKEN: process.env.MAPBOX_ACCESS_TOKEN ? '***' : undefined, MAPBOX_API_ENDPOINT: process.env.MAPBOX_API_ENDPOINT, @@ -240,10 +252,6 @@ async function main() { data: JSON.stringify(relevantEnvVars, null, 2) }); - // Start receiving messages on stdin and sending messages on stdout - const transport = new StdioServerTransport(); - await server.connect(transport); - // After connection, dynamically register capability-dependent tools const clientCapabilities = server.server.getClientCapabilities(); diff --git a/test/integration/loggingOrder.test.ts b/test/integration/loggingOrder.test.ts new file mode 100644 index 0000000..cc058c7 --- /dev/null +++ b/test/integration/loggingOrder.test.ts @@ -0,0 +1,69 @@ +// Copyright (c) Mapbox, Inc. +// Licensed under the MIT License. + +import { describe, it, expect } from 'vitest'; +import { existsSync } from 'node:fs'; +import { join, dirname } from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { Client } from '@modelcontextprotocol/sdk/client/index.js'; +import { StdioClientTransport } from '@modelcontextprotocol/sdk/client/stdio.js'; +import { LoggingMessageNotificationSchema } from '@modelcontextprotocol/sdk/types.js'; + +/** + * Spawns the *actual built server* (dist/esm/index.js) as a real child + * process and drives it over real stdio with a real MCP client. Startup used + * to send several `notifications/message` logging calls (.env status, + * tracing status, a debug env dump) before `server.connect(transport)` ran + * -- a real client can never receive a notification sent before the + * transport it's listening on is connected, so those messages were silently + * dropped every time. Only a test that crosses the real process/transport + * boundary can catch a regression back to that ordering; asserting against + * the return value of some internal function can't, since nothing here is + * about return values. + */ + +const __dirname = dirname(fileURLToPath(import.meta.url)); +const SERVER_ENTRY = join(__dirname, '..', '..', 'dist', 'esm', 'index.js'); + +const DUMMY_TOKEN = 'sk.eyJ1IjoidGVzdC11c2VyIn0.signature'; + +describe.skipIf(!existsSync(SERVER_ENTRY))( + 'startup logging (real server process, real MCP protocol)', + () => { + it('delivers startup logging messages to a client connected before they are sent', async () => { + const transport = new StdioClientTransport({ + command: process.execPath, + args: [SERVER_ENTRY], + env: { + MAPBOX_ACCESS_TOKEN: DUMMY_TOKEN, + PATH: process.env.PATH ?? '' + } + }); + const client = new Client({ + name: 'logging-order-integration-test', + version: '1.0.0' + }); + + const received: unknown[] = []; + client.setNotificationHandler( + LoggingMessageNotificationSchema, + async (notification) => { + received.push(notification.params); + } + ); + + try { + await client.connect(transport); + // Startup logging happens asynchronously right after connect; + // give it a moment to arrive rather than racing it. + await new Promise((resolve) => setTimeout(resolve, 500)); + + expect(received.length).toBeGreaterThan(0); + } finally { + await client.close().catch(() => { + // Already closed or the process exited on its own. + }); + } + }); + } +); From 1b0ed653e79710191c1c9868e3efc159ed168401 Mon Sep 17 00:00:00 2001 From: Matthew Podwysocki Date: Tue, 25 Aug 2026 14:54:01 -0400 Subject: [PATCH 2/2] feat: log which MCP client connected, fix capability-read race server.server.getClientVersion()/getClientCapabilities() are only populated once the client's initialize request has been processed -- reading them synchronously right after server.connect() races that request, since connect() only waits for the transport to start, not for the handshake to finish. Confirmed live: reading capabilities immediately after connect() reliably returned undefined even for a client that declared them. Moved both reads into the existing server.server.oninitialized callback (added in the prior commit for logging-order correctness), which fires only once the handshake is fully done. Also adds client identification as a byproduct: the client's name/version from its initialize request is now logged on connect and recorded as mcp.client.name/mcp.client.version on every subsequent tool-execution trace span, matching the equivalent change in @mapbox/mcp-server. Co-Authored-By: Claude Sonnet 5 --- CHANGELOG.md | 1 + src/index.ts | 35 +++++++++++- src/utils/tracing.ts | 23 ++++++++ test/utils/tracing.test.ts | 109 +++++++++++++++++++++++++++++++++++++ 4 files changed, 166 insertions(+), 2 deletions(-) create mode 100644 test/utils/tracing.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index efa12ce..8ddf671 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ### Fixed - **Startup logging messages (`.env` status, tracing status, detected client capabilities) now actually reach clients.** The `McpServer` never declared the `logging` capability, so every `sendLoggingMessage` call was a silent no-op regardless of when it was sent. Several of those calls also ran before `server.connect(transport)`, which would have dropped them anyway even with the capability declared, since there's no connected client yet to receive a notification sent before the transport is connected. Fixed both: `logging: {}` is now declared in the server's capabilities, and startup logging is deferred until after `connect()`. Covered by a new integration test that spawns the real built server and asserts a real client receives at least one startup log message. +- **The server now identifies which MCP client connected to it, and fixes a related capability-read race.** `server.server.getClientVersion()`/`getClientCapabilities()` are only populated once the client's `initialize` request has been processed, which is not guaranteed by the time `server.connect()`'s promise resolves (it only waits for the transport to start). Reading them right after `connect()`, as the existing capability-gated tool registration did, reliably saw them as unset — confirmed live, even for a client that explicitly declared `elicitation` support. Both reads now happen inside a `server.server.oninitialized` callback, which only fires once the handshake is fully done. As part of this, the client's identity (name/version from its `initialize` request) is now logged on connect (e.g. `Client identified as: claude-ai v1.0.0`) and recorded as `mcp.client.name`/`mcp.client.version` on every subsequent tool-execution trace span, so OTel-backed traces can be filtered or grouped by client. ### New Features diff --git a/src/index.ts b/src/index.ts index 893f8b5..96cbe82 100644 --- a/src/index.ts +++ b/src/index.ts @@ -25,7 +25,8 @@ import { initializeTracing, shutdownTracing, isTracingInitialized, - getTracer + getTracer, + setClientInfo } from './utils/tracing.js'; // Load .env from current working directory (where npm run is executed) @@ -198,6 +199,22 @@ async function main() { } } + // Registered before connect() so it's already in place the moment the + // client's initialize handshake completes. getClientCapabilities() and + // getClientVersion() are only populated once the server has processed the + // client's `initialize` request -- reading them synchronously right after + // `server.connect()` races that request and reliably sees them as unset, + // since connect() only waits for the transport to start, not for the + // handshake to finish. + server.server.oninitialized = () => { + onClientInitialized().catch((error) => { + server.server.sendLoggingMessage({ + level: 'warning', + data: `Error handling client initialization: ${error instanceof Error ? error.message : String(error)}` + }); + }); + }; + // Start receiving messages on stdin and sending messages on stdout const transport = new StdioServerTransport(); await server.connect(transport); @@ -251,8 +268,22 @@ async function main() { level: 'debug', data: JSON.stringify(relevantEnvVars, null, 2) }); +} + +// Runs once per session, after the client's initialize handshake completes +// (see the `oninitialized` registration in main() for why that timing +// matters). Reports which client connected and registers any tools gated on +// capabilities the client declared during that handshake. +async function onClientInitialized() { + const clientInfo = server.server.getClientVersion(); + server.server.sendLoggingMessage({ + level: 'info', + data: `Client identified as: ${clientInfo?.name ?? 'unknown'} v${clientInfo?.version ?? 'unknown'}` + }); + // Recorded so every subsequent tool-execution span carries it too -- + // see setClientInfo's doc comment in tracing.ts. + setClientInfo(clientInfo); - // After connection, dynamically register capability-dependent tools const clientCapabilities = server.server.getClientCapabilities(); // Debug: Log what capabilities we detected diff --git a/src/utils/tracing.ts b/src/utils/tracing.ts index 8c83bd3..c0aa0e0 100644 --- a/src/utils/tracing.ts +++ b/src/utils/tracing.ts @@ -253,6 +253,23 @@ export function getTracer() { return trace.getTracer('mapbox-mcp-devkit-server'); } +/** + * The connected client's `clientInfo` (name/version), as reported in its + * `initialize` request. There is exactly one client per stdio server + * process, so this is safe as module-level state; set once via + * `setClientInfo` after the initialize handshake completes (see + * `server.server.oninitialized` in index.ts) and read by every tool span + * created afterward, so traces can be filtered/grouped by which MCP client + * (Claude Desktop, Cursor, VS Code, etc.) made the call. + */ +let currentClientInfo: { name?: string; version?: string } | undefined; + +export function setClientInfo( + info: { name?: string; version?: string } | undefined +): void { + currentClientInfo = info; +} + /** * Create a span for tool execution with comprehensive attributes */ @@ -275,6 +292,12 @@ export function createToolSpan( 'tool.name': toolName, 'tool.input.size': inputSize, 'operation.type': 'tool_execution', + ...(currentClientInfo?.name && { + 'mcp.client.name': currentClientInfo.name + }), + ...(currentClientInfo?.version && { + 'mcp.client.version': currentClientInfo.version + }), ...(extra?.sessionId && { 'session.id': extra.sessionId }), ...(extra?.userId && { 'user.id': extra.userId }), ...(extra?.accountId && { 'account.id': extra.accountId }), diff --git a/test/utils/tracing.test.ts b/test/utils/tracing.test.ts new file mode 100644 index 0000000..1b8809a --- /dev/null +++ b/test/utils/tracing.test.ts @@ -0,0 +1,109 @@ +// Copyright (c) Mapbox, Inc. +// Licensed under the MIT License. + +import { describe, it, expect, vi, beforeEach } from 'vitest'; +import { + createToolSpan, + getTracer, + setClientInfo +} from '../../src/utils/tracing.js'; + +// Mock the OpenTelemetry modules to avoid actual tracing in tests +vi.mock('@opentelemetry/sdk-node', () => ({ + NodeSDK: vi.fn().mockImplementation(() => ({ + start: vi.fn(), + shutdown: vi.fn().mockResolvedValue(undefined) + })) +})); + +vi.mock('@opentelemetry/api', () => ({ + trace: { + getTracer: vi.fn().mockReturnValue({ + startSpan: vi.fn().mockReturnValue({ + setAttributes: vi.fn(), + setStatus: vi.fn(), + recordException: vi.fn(), + end: vi.fn() + }) + }) + }, + SpanStatusCode: { + OK: 1, + ERROR: 2 + }, + SpanKind: { + INTERNAL: 0, + CLIENT: 3 + }, + diag: { + setLogger: vi.fn() + }, + DiagLogLevel: { + NONE: 0, + ERROR: 30, + WARN: 50, + INFO: 60, + DEBUG: 70, + VERBOSE: 80 + } +})); + +describe('tracing utilities', () => { + beforeEach(() => { + vi.clearAllMocks(); + setClientInfo(undefined); + }); + + describe('createToolSpan', () => { + it('creates a tool span with basic attributes and no client info by default', () => { + const tracer = getTracer(); + const mockSpan = { + setAttributes: vi.fn(), + setStatus: vi.fn(), + recordException: vi.fn(), + end: vi.fn() + }; + + // eslint-disable-next-line @typescript-eslint/no-explicit-any + vi.mocked(tracer.startSpan).mockReturnValue(mockSpan as any); + + createToolSpan('test_tool', 1024); + + expect(tracer.startSpan).toHaveBeenCalledWith('tool.test_tool', { + kind: expect.any(Number), + attributes: { + 'tool.name': 'test_tool', + 'tool.input.size': 1024, + 'operation.type': 'tool_execution' + } + }); + }); + + it('includes the connected client name/version once set via setClientInfo', () => { + const tracer = getTracer(); + const mockSpan = { + setAttributes: vi.fn(), + setStatus: vi.fn(), + recordException: vi.fn(), + end: vi.fn() + }; + + // eslint-disable-next-line @typescript-eslint/no-explicit-any + vi.mocked(tracer.startSpan).mockReturnValue(mockSpan as any); + + setClientInfo({ name: 'claude-ai', version: '1.0.0' }); + createToolSpan('test_tool', 1024); + + expect(tracer.startSpan).toHaveBeenCalledWith('tool.test_tool', { + kind: expect.any(Number), + attributes: { + 'tool.name': 'test_tool', + 'tool.input.size': 1024, + 'operation.type': 'tool_execution', + 'mcp.client.name': 'claude-ai', + 'mcp.client.version': '1.0.0' + } + }); + }); + }); +});