Skip to content

Commit f4aed93

Browse files
Replace console.log with structured logging for Cloud Run
- Add structured logger utility with Cloud Run trace context support - Uses AsyncLocalStorage for request context propagation - Replace all console.log/error/warn statements with structured logger - Add logging middleware to capture request/response metadata - Support Google Cloud Logging severity levels and trace correlation 🤖 Generated with [Claude Code](https://claude.ai/code) Co-Authored-By: Claude <[email protected]>
1 parent af3ced0 commit f4aed93

File tree

8 files changed

+266
-45
lines changed

8 files changed

+266
-45
lines changed

src/handlers/common.ts

Lines changed: 16 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import { NextFunction, Request, Response } from "express";
22
import { withContext } from "../context.js";
33
import { readMcpInstallation } from "../services/auth.js";
4+
import { logger } from "../utils/logger.js";
45

56
import { JSONRPCError, JSONRPCNotification, JSONRPCRequest, JSONRPCResponse } from "@modelcontextprotocol/sdk/types.js";
67

@@ -11,18 +12,23 @@ export function logMcpMessage(
1112
// check if message has a method field
1213
if ("method" in message) {
1314
if (message.method === "tools/call") {
14-
console.info(
15-
`[session ${sessionId}] Processing ${message.method}, for tool ${message.params?.name}`,
16-
);
15+
logger.info('Processing MCP method', {
16+
sessionId,
17+
method: message.method,
18+
toolName: message.params?.name
19+
});
1720
} else {
18-
console.info(
19-
`[session ${sessionId}] Processing ${message.method} method`,
20-
);
21-
}
21+
logger.info('Processing MCP method', {
22+
sessionId,
23+
method: message.method
24+
});
25+
}
2226
} else if ("error" in message) {
23-
console.warn(
24-
`[session ${sessionId}] Received error message: ${message.error.message}, ${message.error.code}`,
25-
)
27+
logger.warning('Received error message', {
28+
sessionId,
29+
errorMessage: message.error.message,
30+
errorCode: message.error.code
31+
});
2632
}
2733
}
2834

src/handlers/shttp.ts

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import { getShttpTransport, isSessionOwnedBy, redisRelayToMcpServer, ServerRedis
55
import { isInitializeRequest } from "@modelcontextprotocol/sdk/types.js";
66
import { randomUUID } from "crypto";
77
import { createMcpServer } from "../services/mcp.js";
8+
import { logger } from "../utils/logger.js";
89

910

1011
declare module "express-serve-static-core" {
@@ -80,7 +81,11 @@ export async function handleStreamableHTTP(req: Request, res: Response) {
8081
// Handle the request with existing transport - no need to reconnect
8182
await shttpTransport.handleRequest(req, res, req.body);
8283
} catch (error) {
83-
console.error('Error handling MCP request:', error);
84+
logger.error('Error handling MCP request', error as Error, {
85+
sessionId: req.headers['mcp-session-id'] as string | undefined,
86+
method: req.method,
87+
userId: getUserIdFromAuth(req.auth)
88+
});
8489

8590
if (!res.headersSent) {
8691
res.status(500)

src/handlers/sse.ts

Lines changed: 24 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import getRawBody from "raw-body";
66
import { redisClient } from "../redis.js";
77
import { createMcpServer } from "../services/mcp.js";
88
import { logMcpMessage } from "./common.js";
9+
import { logger } from "../utils/logger.js";
910

1011
const MAXIMUM_MESSAGE_SIZE = "4mb";
1112

@@ -25,7 +26,9 @@ function redisChannelForSession(sessionId: string): string {
2526
export async function handleSSEConnection(req: Request, res: Response) {
2627
const { server: mcpServer, cleanup: mcpCleanup } = createMcpServer();
2728
const transport = new SSEServerTransport("/message", res);
28-
console.info(`[session ${transport.sessionId}] Received MCP SSE connection`);
29+
logger.info('Received MCP SSE connection', {
30+
sessionId: transport.sessionId
31+
});
2932

3033
const redisCleanup = await redisClient.createSubscription(
3134
redisChannelForSession(transport.sessionId),
@@ -36,42 +39,41 @@ export async function handleSSEConnection(req: Request, res: Response) {
3639
const message = JSON.parse(json);
3740
logMcpMessage(message, transport.sessionId);
3841
transport.handleMessage(message).catch((error) => {
39-
console.error(
40-
`[session ${transport.sessionId}] Error handling message:`,
41-
error,
42-
);
42+
logger.error('Error handling message', error as Error, {
43+
sessionId: transport.sessionId
44+
});
4345
});
4446
},
4547
(error) => {
46-
console.error(
47-
`[session ${transport.sessionId}] Disconnecting due to error in Redis subscriber:`,
48-
error,
49-
);
48+
logger.error('Disconnecting due to error in Redis subscriber', error as Error, {
49+
sessionId: transport.sessionId
50+
});
5051
transport
5152
.close()
5253
.catch((error) =>
53-
console.error(
54-
`[session ${transport.sessionId}] Error closing transport:`,
55-
error,
56-
),
54+
logger.error('Error closing transport', error as Error, {
55+
sessionId: transport.sessionId
56+
}),
5757
);
5858
},
5959
);
6060

6161
const cleanup = () => {
6262
void mcpCleanup();
6363
redisCleanup().catch((error) =>
64-
console.error(
65-
`[session ${transport.sessionId}] Error disconnecting Redis subscriber:`,
66-
error,
67-
),
64+
logger.error('Error disconnecting Redis subscriber', error as Error, {
65+
sessionId: transport.sessionId
66+
}),
6867
);
6968
}
7069

7170
// Clean up Redis subscription when the connection closes
7271
mcpServer.onclose = cleanup
7372

74-
console.info(`[session ${transport.sessionId}] Listening on Redis channel`);
73+
logger.info('Listening on Redis channel', {
74+
sessionId: transport.sessionId,
75+
channel: redisChannel
76+
});
7577
await mcpServer.connect(transport);
7678
}
7779

@@ -94,7 +96,10 @@ export async function handleMessage(req: Request, res: Response) {
9496
});
9597
} catch (error) {
9698
res.status(400).json(error);
97-
console.error("Bad POST request:", error);
99+
logger.error('Bad POST request', error as Error, {
100+
sessionId,
101+
contentType: req.headers['content-type']
102+
});
98103
return;
99104
}
100105
await redisClient.publish(redisChannelForSession(sessionId), body);

src/index.ts

Lines changed: 34 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import { handleFakeAuthorize, handleFakeAuthorizeRedirect } from "./handlers/fak
99
import { handleStreamableHTTP } from "./handlers/shttp.js";
1010
import { handleMessage, handleSSEConnection } from "./handlers/sse.js";
1111
import { redisClient } from "./redis.js";
12+
import { logger } from "./utils/logger.js";
1213

1314
const app = express();
1415

@@ -34,16 +35,29 @@ const baseSecurityHeaders = (req: express.Request, res: express.Response, next:
3435
next();
3536
};
3637

37-
// simple logging middleware
38-
const logger = (req: express.Request, res: express.Response, next: express.NextFunction) => {
39-
// if GET and /mcp, log the body returned
40-
console.log(`${new Date().toISOString()} ${req.method} ${req.url}`);
41-
if (req.method === 'GET' && req.url.includes('/mcp')) {
42-
console.log(' Body:', JSON.stringify(req.body, null, 2));
43-
}
38+
// Structured logging middleware
39+
const loggingMiddleware = (req: express.Request, res: express.Response, next: express.NextFunction) => {
40+
const startTime = Date.now();
41+
42+
// Log request
43+
logger.info('Request received', {
44+
method: req.method,
45+
url: req.url,
46+
headers: req.headers,
47+
body: req.method === 'GET' && req.url.includes('/mcp') ? req.body : undefined
48+
});
49+
50+
// Log response when finished
4451
res.on('finish', () => {
45-
console.log(' Response:', res.statusCode);
52+
const duration = Date.now() - startTime;
53+
logger.info('Request completed', {
54+
method: req.method,
55+
url: req.url,
56+
statusCode: res.statusCode,
57+
duration: `${duration}ms`
58+
});
4659
});
60+
4761
next();
4862
};
4963

@@ -73,7 +87,12 @@ const corsOptions = {
7387

7488

7589
app.use(express.json());
76-
app.use(logger);
90+
91+
// Add structured logging context middleware first
92+
app.use(logger.middleware());
93+
94+
// Then add the logging middleware
95+
app.use(loggingMiddleware);
7796

7897
// Apply base security headers to all routes
7998
app.use(baseSecurityHeaders);
@@ -126,10 +145,14 @@ app.get("/fakeupstreamauth/callback", cors(corsOptions), handleFakeAuthorizeRedi
126145
try {
127146
await redisClient.connect();
128147
} catch (error) {
129-
console.error("Could not connect to Redis:", error);
148+
logger.error("Could not connect to Redis", error as Error);
130149
process.exit(1);
131150
}
132151

133152
app.listen(PORT, () => {
134-
console.log(`Server running on http://localhost:${PORT}`);
153+
logger.info('Server started', {
154+
port: PORT,
155+
url: `http://localhost:${PORT}`,
156+
environment: process.env.NODE_ENV || 'development'
157+
});
135158
});

src/redis.ts

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
import { createClient, SetOptions } from "@redis/client";
2+
import { logger } from "./utils/logger.js";
23

34
/**
45
* Describes the Redis primitives we use in this application, to be able to mock
@@ -46,7 +47,7 @@ export class RedisClientImpl implements RedisClient {
4647

4748
constructor() {
4849
this.redis.on("error", (error) =>
49-
console.error("Redis client error:", error),
50+
logger.error("Redis client error", error as Error),
5051
);
5152
}
5253

src/services/auth.ts

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import crypto from "crypto";
33
import { redisClient } from "../redis.js";
44
import { McpInstallation, PendingAuthorization, TokenExchange } from "../types.js";
55
import { OAuthClientInformationFull, OAuthTokens } from "@modelcontextprotocol/sdk/shared/auth.js";
6+
import { logger } from "../utils/logger.js";
67

78
export function generatePKCEChallenge(verifier: string): string {
89
const buffer = Buffer.from(verifier);
@@ -243,7 +244,9 @@ export async function exchangeToken(
243244

244245
const tokenExchange: TokenExchange = JSON.parse(decoded);
245246
if (tokenExchange.alreadyUsed) {
246-
console.error("Duplicate use of authorization code detected; revoking tokens");
247+
logger.error('Duplicate use of authorization code detected; revoking tokens', undefined, {
248+
authorizationCode: authorizationCode.substring(0, 8) + '...'
249+
});
247250
await revokeMcpInstallation(tokenExchange.mcpAccessToken);
248251
throw new Error("Duplicate use of authorization code detected; tokens revoked");
249252
}
@@ -257,7 +260,9 @@ export async function exchangeToken(
257260

258261
if (rereadData !== data) {
259262
// Data concurrently changed while we were updating it. This necessarily means a duplicate use.
260-
console.error("2Duplicate use of authorization code detected; revoking tokens");
263+
logger.error('Duplicate use of authorization code detected (concurrent update); revoking tokens', undefined, {
264+
authorizationCode: authorizationCode.substring(0, 8) + '...'
265+
});
261266
await revokeMcpInstallation(tokenExchange.mcpAccessToken);
262267
throw new Error("Duplicate use of authorization code detected; tokens revoked");
263268
}

src/services/redisTransport.ts

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import { redisClient } from "../redis.js";
33
import { Transport, TransportSendOptions } from "@modelcontextprotocol/sdk/shared/transport.js";
44
import { AuthInfo } from "@modelcontextprotocol/sdk/server/auth/types.js";
55
import { JSONRPCMessage, MessageExtraInfo } from "@modelcontextprotocol/sdk/types.js";
6+
import { logger } from "../utils/logger.js";
67

78
let redisTransportCounter = 0;
89
const notificationStreamId = "__GET_stream";
@@ -154,7 +155,10 @@ export class ServerRedisTransport implements Transport {
154155

155156
// Set new timeout
156157
this.inactivityTimeout = setTimeout(() => {
157-
console.log(`Session ${this._sessionId} timed out due to inactivity`);
158+
logger.info('Session timed out due to inactivity', {
159+
sessionId: this._sessionId,
160+
timeoutMs: this.INACTIVITY_TIMEOUT_MS
161+
});
158162
void shutdownSession(this._sessionId);
159163
}, this.INACTIVITY_TIMEOUT_MS);
160164
}

0 commit comments

Comments
 (0)