Merge pull request #139 from mapbox/fix/log-messages-before-connect

fix: startup logging messages never reached clients

Author: mattpodwysocki

CHANGELOG.md

@@ -1,5 +1,10 @@
 ## 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.
+- **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
 
 - **`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.

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)
@@ -77,7 +78,8 @@ const server = new McpServer(
         listChanged: true // Advertise support for dynamic tool registration
       },
       resources: {},
-      prompts: {}
+      prompts: {},
+      logging: {}
     }
   }
 );
@@ -148,44 +150,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,12 +194,64 @@ async function main() {
         span.end();
       }
     } catch (error) {
-      // Log tracing initialization failure
+      tracingInitError =
+        error instanceof Error ? error : new Error(String(error));
+    }
+  }
+
+  // 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: `Failed to initialize tracing: ${error instanceof Error ? error.message : String(error)}`
+        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);
+
+  // 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({
@@ -239,12 +268,22 @@ async function main() {
     level: 'debug',
     data: JSON.stringify(relevantEnvVars, null, 2)
   });
+}
 
-  // Start receiving messages on stdin and sending messages on stdout
-  const transport = new StdioServerTransport();
-  await server.connect(transport);
+// 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

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 }),

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.
+        });
+      }
+    });
+  }
+);

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'
+        }
+      });
+    });
+  });
+});