-
-
Notifications
You must be signed in to change notification settings - Fork 276
fix: log connections that timeout, abort, or send unparsable data #783
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Open
itslenny
wants to merge
2
commits into
master
Choose a base branch
from
fix/log-aborted-connections
base: master
Could not load branches
Branch not found: {{ refName }}
Loading
Could not load tags
Nothing to show
Loading
Are you sure you want to change the base?
Some commits from the old base branch may be removed from the timeline,
and old review comments may become outdated.
Open
Changes from all commits
Commits
Show all changes
2 commits
Select commit
Hold shift + click to select a range
File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,7 +1,10 @@ | ||
| import { logger, logSchema, redactQueryParamFromRequest } from '@internal/monitoring' | ||
| import { FastifyInstance } from 'fastify' | ||
| import { FastifyReply } from 'fastify/types/reply' | ||
| import { FastifyRequest } from 'fastify/types/request' | ||
| import fastifyPlugin from 'fastify-plugin' | ||
| import { Socket } from 'net' | ||
| import { getConfig } from '../../config' | ||
|
|
||
| interface RequestLoggerOptions { | ||
| excludeUrls?: string[] | ||
|
|
@@ -23,13 +26,79 @@ declare module 'fastify' { | |
| } | ||
| } | ||
|
|
||
| const { version } = getConfig() | ||
|
|
||
| /** | ||
| * Request logger plugin | ||
| * @param options | ||
| */ | ||
| export const logRequest = (options: RequestLoggerOptions) => | ||
| fastifyPlugin( | ||
| async (fastify) => { | ||
| // Used to track cleanup functions per socket | ||
| const socketCleanupMap = new WeakMap<Socket, () => void>() | ||
| const cleanupSocketListeners = (socket: Socket) => { | ||
| const cleanup = socketCleanupMap.get(socket) | ||
| if (cleanup) { | ||
| socketCleanupMap.delete(socket) | ||
| cleanup() | ||
| } | ||
| } | ||
|
|
||
| // Watch for connections that timeout or disconnect before complete HTTP headers are received | ||
| // For keep-alive connections, track each potential request independently | ||
| const onConnection = (socket: Socket) => { | ||
| const connectionStart = Date.now() | ||
| let currentRequestStart = connectionStart | ||
| let hasReceivedData = false | ||
| let requestLogged = false | ||
|
|
||
| // Store cleanup function so hooks can mark requests as logged | ||
| socketCleanupMap.set(socket, () => { | ||
| requestLogged = true | ||
| }) | ||
|
|
||
| // Track when data arrives for a potential request | ||
| const onData = () => { | ||
| // Reset tracking for each new request on keep-alive connections | ||
| if (!hasReceivedData || requestLogged) { | ||
| hasReceivedData = true | ||
| currentRequestStart = Date.now() | ||
| requestLogged = false | ||
| } | ||
| } | ||
| socket.on('data', onData) | ||
|
|
||
| // Remove data listener on socket error to prevent listener leak | ||
| socket.once('error', () => { | ||
| socket.removeListener('data', onData) | ||
| }) | ||
|
|
||
| socket.once('close', () => { | ||
| socket.removeListener('data', onData) | ||
| socketCleanupMap.delete(socket) | ||
|
|
||
| // Log if connection closed without a logged request | ||
| // This covers: idle timeouts, partial data, malformed requests | ||
| if (!requestLogged) { | ||
| const req = createPartialLogRequest(fastify, socket, currentRequestStart) | ||
|
|
||
| doRequestLog(req, { | ||
| excludeUrls: options.excludeUrls, | ||
| statusCode: 'ABORTED CONN', | ||
| responseTime: (Date.now() - req.startTime) / 1000, | ||
| }) | ||
| } | ||
| }) | ||
| } | ||
|
Comment on lines
+77
to
+93
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think this can fire before raw.once(close) on partial body then we can log twice again since callback wouldn't be running. We should set requestLogged inside as well to prevent other log |
||
|
|
||
| fastify.server.on('connection', onConnection) | ||
|
|
||
| // Clean up on close | ||
| fastify.addHook('onClose', async () => { | ||
| fastify.server.removeListener('connection', onConnection) | ||
| }) | ||
|
|
||
| fastify.addHook('onRequest', async (req, res) => { | ||
| req.startTime = Date.now() | ||
|
|
||
|
|
@@ -40,6 +109,7 @@ export const logRequest = (options: RequestLoggerOptions) => | |
| statusCode: 'ABORTED REQ', | ||
| responseTime: (Date.now() - req.startTime) / 1000, | ||
| }) | ||
| cleanupSocketListeners(req.raw.socket) | ||
| return | ||
| } | ||
|
|
||
|
|
@@ -49,6 +119,7 @@ export const logRequest = (options: RequestLoggerOptions) => | |
| statusCode: 'ABORTED RES', | ||
| responseTime: (Date.now() - req.startTime) / 1000, | ||
| }) | ||
| cleanupSocketListeners(req.raw.socket) | ||
| } | ||
| }) | ||
| }) | ||
|
|
@@ -94,6 +165,9 @@ export const logRequest = (options: RequestLoggerOptions) => | |
| responseTime: reply.elapsedTime, | ||
| executionTime: req.executionTime, | ||
| }) | ||
|
|
||
| // Mark request as logged so socket close handler doesn't log it again | ||
| cleanupSocketListeners(req.raw.socket) | ||
| }) | ||
| }, | ||
| { name: 'log-request' } | ||
|
|
@@ -102,7 +176,7 @@ export const logRequest = (options: RequestLoggerOptions) => | |
| interface LogRequestOptions { | ||
| reply?: FastifyReply | ||
| excludeUrls?: string[] | ||
| statusCode: number | 'ABORTED REQ' | 'ABORTED RES' | ||
| statusCode: number | 'ABORTED REQ' | 'ABORTED RES' | 'ABORTED CONN' | ||
| responseTime: number | ||
| executionTime?: number | ||
| } | ||
|
|
@@ -179,3 +253,29 @@ function getFirstDefined<T>(...values: any[]): T | undefined { | |
| } | ||
| return undefined | ||
| } | ||
|
|
||
| /** | ||
| * Creates a minimal FastifyRequest for logging aborted connections. | ||
| * Used when connection closes before a complete HTTP request is received. | ||
| */ | ||
| export function createPartialLogRequest( | ||
| fastify: FastifyInstance, | ||
| socket: Socket, | ||
| startTime: number | ||
| ) { | ||
| return { | ||
| method: 'UNKNOWN', | ||
| headers: {}, | ||
| url: '/', | ||
| ip: socket.remoteAddress || 'unknown', | ||
| id: 'no-request', | ||
| log: fastify.log.child({ | ||
| reqId: 'no-request', | ||
| appVersion: version, | ||
| }), | ||
| startTime, | ||
| raw: {}, | ||
| routeOptions: { config: {} }, | ||
| resources: [], | ||
| } as unknown as FastifyRequest | ||
| } | ||
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
cleanup is registered once and it's removed after first request but keep-alive on the same connection can revert requestLogged then new request wouldn't have the callback and would do extra log