19147127865

Committed 06 Nov 2025 07:17PM UTC coverage: 77.584% (-0.2%) from 77.75%

Build # 19147127865

Build Type

Pull #783

github

Committed by

web-flow

Commit Message

Merge d0fa85cb1 into 6ba23e408

Pull Request Pull Request #783: fix: log connections that timeout, abort, or send unparsable data

Coverage Stats

2025 of 2931 branches covered (69.09%)

Branch coverage included in aggregate %.

76 of 170 new or added lines in 3 files covered. (44.71%)

30 existing lines in 1 file now uncovered.

24663 of 31468 relevant lines covered (78.37%)

91.49 hits per line

Source File
Press 'n' to go to next uncovered line, 'b' for previous

78.85

/src/http/plugins/log-request.ts

import { Socket } from 'net'
import fastifyPlugin from 'fastify-plugin'
import { logSchema, redactQueryParamFromRequest } from '@internal/monitoring'
import { trace } from '@opentelemetry/api'
import { FastifyRequest } from 'fastify/types/request'
import { FastifyReply } from 'fastify/types/reply'
import { IncomingMessage } from 'http'
import { getConfig } from '../../config'
import { parsePartialHttp, PartialHttpData } from '@internal/http'
import { FastifyInstance } from 'fastify'

interface RequestLoggerOptions {
  excludeUrls?: string[]
}

declare module 'fastify' {
  interface FastifyRequest {
    executionError?: Error
    operation?: { type: string }
    resources?: string[]
    startTime: number
  }

  interface FastifyContextConfig {
    operation?: { type: string }
    resources?: (req: FastifyRequest<any>) => string[]
  }
}

const { version } = getConfig()

/**
 * Request logger plugin
 * @param options
 */
export const logRequest = (options: RequestLoggerOptions) =>
  fastifyPlugin(
    async (fastify) => {
      // Watch for connections that timeout or disconnect before complete HTTP headers are received
      // Log if socket closes before request is triggered
      fastify.server.on('connection', (socket) => {
        let hasRequest = false
        const startTime = Date.now()
        const partialData: Buffer[] = []
        // Only store 2kb per request
        const captureByteLimit = 2048

        // Capture partial data sent before connection closes
        const onData = (chunk: Buffer) => {
          const remaining = captureByteLimit - partialData.length
          if (remaining > 0) {
            partialData.push(chunk.subarray(0, Math.min(chunk.length, remaining)))
          }

          if (partialData.length >= captureByteLimit) {
            socket.removeListener('data', onData)
          }
        }
        socket.on('data', onData)

        // Track if this socket ever receives an HTTP request
        const onRequest = (req: IncomingMessage) => {
          if (req.socket === socket) {
            hasRequest = true
            socket.removeListener('data', onData)
            fastify.server.removeListener('request', onRequest)
          }
        }
        fastify.server.on('request', onRequest)

        socket.once('close', () => {
          socket.removeListener('data', onData)
          fastify.server.removeListener('request', onRequest)
          if (hasRequest) {
            return
          }

          const parsedHttp = parsePartialHttp(partialData)
          const req = createPartialLogRequest(fastify, socket, parsedHttp, startTime)

          doRequestLog(req, {
            excludeUrls: options.excludeUrls,
            statusCode: 'ABORTED CONN',
            responseTime: (Date.now() - req.startTime) / 1000,
          })
        })
      })

      fastify.addHook('onRequest', async (req, res) => {
        req.startTime = Date.now()

        res.raw.once('close', () => {
          if (req.raw.aborted) {
            doRequestLog(req, {
              excludeUrls: options.excludeUrls,
              statusCode: 'ABORTED REQ',
              responseTime: (Date.now() - req.startTime) / 1000,
            })
            return
          }

          if (!res.raw.writableFinished) {
            doRequestLog(req, {
              excludeUrls: options.excludeUrls,
              statusCode: 'ABORTED RES',
              responseTime: (Date.now() - req.startTime) / 1000,
            })
          }
        })
      })

      /**
       * Adds req.resources and req.operation to the request object
       */
      fastify.addHook('preHandler', async (req) => {
        const resourceFromParams = Object.values(req.params || {}).join('/')
        const resources = getFirstDefined<string[]>(
          req.resources,
          req.routeOptions.config.resources?.(req),
          (req.raw as any).resources,
          resourceFromParams ? [resourceFromParams] : ([] as string[])
        )

        if (resources && resources.length > 0) {
          resources.map((resource, index) => {
            if (!resource.startsWith('/')) {
              resources[index] = `/${resource}`
            }
          })
        }

        req.resources = resources
        req.operation = req.routeOptions.config.operation

        if (req.operation) {
          trace.getActiveSpan()?.setAttribute('http.operation', req.operation.type)
        }
      })

      fastify.addHook('onResponse', async (req, reply) => {
        doRequestLog(req, {
          reply,
          excludeUrls: options.excludeUrls,
          statusCode: reply.statusCode,
          responseTime: reply.elapsedTime,
        })
      })
    },
    { name: 'log-request' }
  )

interface LogRequestOptions {
  reply?: FastifyReply
  excludeUrls?: string[]
  statusCode: number | 'ABORTED REQ' | 'ABORTED RES' | 'ABORTED CONN'
  responseTime: number
}

function doRequestLog(req: FastifyRequest, options: LogRequestOptions) {
  if (options.excludeUrls?.includes(req.url)) {
    return
  }

  const rMeth = req.method
  const rUrl = redactQueryParamFromRequest(req, [
    'token',
    'X-Amz-Credential',
    'X-Amz-Signature',
    'X-Amz-Security-Token',
  ])
  const uAgent = req.headers['user-agent']
  const rId = req.id
  const cIP = req.ip
  const statusCode = options.statusCode
  const error = (req.raw as any).executionError || req.executionError
  const tenantId = req.tenantId

  const buildLogMessage = `${tenantId} | ${rMeth} | ${statusCode} | ${cIP} | ${rId} | ${rUrl} | ${uAgent}`

  logSchema.request(req.log, buildLogMessage, {
    type: 'request',
    req,
    res: options.reply,
    responseTime: options.responseTime,
    error: error,
    owner: req.owner,
    role: req.jwtPayload?.role,
    resources: req.resources,
    operation: req.operation?.type ?? req.routeOptions.config.operation?.type,
    serverTimes: req.serverTimings,
  })
}

function getFirstDefined<T>(...values: any[]): T | undefined {
  for (const value of values) {
    if (value !== undefined) {
      return value
    }
  }
  return undefined
}

/**
 * Creates a minimal FastifyRequest from partial HTTP data.
 * Used for consistent logging when request parsing fails.
 */
export function createPartialLogRequest(
  fastify: FastifyInstance,
  socket: Socket,
  httpData: PartialHttpData,
  startTime: number
) {
  return {
    method: httpData.method,
    url: httpData.url,
    headers: httpData.headers,
    ip: socket.remoteAddress || 'unknown',
    id: 'no-request',
    log: fastify.log.child({
      tenantId: httpData.tenantId,
      project: httpData.tenantId,
      reqId: 'no-request',
      appVersion: version,
      dataLength: httpData.length,
    }),
    startTime,
    tenantId: httpData.tenantId,
    raw: {},
    routeOptions: { config: {} },
    resources: [],
  } as unknown as FastifyRequest
}

1	import { Socket } from 'net'	1✔
2	import fastifyPlugin from 'fastify-plugin'	1✔
3	import { logSchema, redactQueryParamFromRequest } from '@internal/monitoring'	1✔
4	import { trace } from '@opentelemetry/api'	1✔
5	import { FastifyRequest } from 'fastify/types/request'	1✔
6	import { FastifyReply } from 'fastify/types/reply'	1✔
7	import { IncomingMessage } from 'http'	1✔
8	import { getConfig } from '../../config'	1✔
9	import { parsePartialHttp, PartialHttpData } from '@internal/http'	1✔
10	import { FastifyInstance } from 'fastify'	1✔
11		1✔
12	interface RequestLoggerOptions {	1✔
13	excludeUrls?: string[]	1✔
14	}	1✔
15		1✔
16	declare module 'fastify' {	1✔
17	interface FastifyRequest {	1✔
18	executionError?: Error	1✔
19	operation?: { type: string }	1✔
20	resources?: string[]	1✔
21	startTime: number	1✔
22	}	1✔
23		1✔
24	interface FastifyContextConfig {	1✔
25	operation?: { type: string }	1✔
26	resources?: (req: FastifyRequest<any>) => string[]	1✔
27	}	1✔
28	}	1✔
29		1✔
30	const { version } = getConfig()	1✔
31		1✔
32	/**	1✔
33	* Request logger plugin	1✔
34	* @param options	1✔
35	*/	1✔
36	export const logRequest = (options: RequestLoggerOptions) =>	1✔
37	fastifyPlugin(	123✔
38	async (fastify) => {	123✔
39	// Watch for connections that timeout or disconnect before complete HTTP headers are received	122✔
40	// Log if socket closes before request is triggered	122✔
41	fastify.server.on('connection', (socket) => {	122✔
42	let hasRequest = false	2✔
43	const startTime = Date.now()	2✔
44	const partialData: Buffer[] = []	2✔
45	// Only store 2kb per request	2✔
46	const captureByteLimit = 2048	2✔
47		2✔
48	// Capture partial data sent before connection closes	2✔
49	const onData = (chunk: Buffer) => {	2✔
50	const remaining = captureByteLimit - partialData.length	2✔
51	if (remaining > 0) {	2✔
52	partialData.push(chunk.subarray(0, Math.min(chunk.length, remaining)))	2✔
53	}	2✔
54		2✔
55	if (partialData.length >= captureByteLimit) {	2!
NEW 56	socket.removeListener('data', onData)	×
NEW 57	}	×
58	}	2✔
59	socket.on('data', onData)	2✔
60		2✔
61	// Track if this socket ever receives an HTTP request	2✔
62	const onRequest = (req: IncomingMessage) => {	2✔
63	if (req.socket === socket) {	2✔
64	hasRequest = true	2✔
65	socket.removeListener('data', onData)	2✔
66	fastify.server.removeListener('request', onRequest)	2✔
67	}	2✔
68	}	2✔
69	fastify.server.on('request', onRequest)	2✔
70		2✔
71	socket.once('close', () => {	2✔
72	socket.removeListener('data', onData)	2✔
73	fastify.server.removeListener('request', onRequest)	2✔
74	if (hasRequest) {	2✔
75	return	2✔
76	}	2✔
NEW 77		×
NEW 78	const parsedHttp = parsePartialHttp(partialData)	×
NEW 79	const req = createPartialLogRequest(fastify, socket, parsedHttp, startTime)	×
NEW 80		×
NEW 81	doRequestLog(req, {	×
NEW 82	excludeUrls: options.excludeUrls,	×
NEW 83	statusCode: 'ABORTED CONN',	×
NEW 84	responseTime: (Date.now() - req.startTime) / 1000,	×
NEW 85	})	×
86	})	2✔
87	})	122✔
88		122✔
89	fastify.addHook('onRequest', async (req, res) => {	122✔
90	req.startTime = Date.now()	126✔
91		126✔
92	res.raw.once('close', () => {	126✔
93	if (req.raw.aborted) {	126!
94	doRequestLog(req, {	×
95	excludeUrls: options.excludeUrls,	×
96	statusCode: 'ABORTED REQ',	×
97	responseTime: (Date.now() - req.startTime) / 1000,	×
98	})	×
99	return	×
100	}	×
101		126✔
102	if (!res.raw.writableFinished) {	126✔
103	doRequestLog(req, {	126✔
104	excludeUrls: options.excludeUrls,	126✔
105	statusCode: 'ABORTED RES',	126✔
106	responseTime: (Date.now() - req.startTime) / 1000,	126✔
107	})	126✔
108	}	126✔
109	})	126✔
110	})	122✔
111		122✔
112	/**	122✔
113	* Adds req.resources and req.operation to the request object	122✔
114	*/	122✔
115	fastify.addHook('preHandler', async (req) => {	122✔
116	const resourceFromParams = Object.values(req.params \|\| {}).join('/')	111!
117	const resources = getFirstDefined<string[]>(	111✔
118	req.resources,	111✔
119	req.routeOptions.config.resources?.(req),	111✔
120	(req.raw as any).resources,	111✔
121	resourceFromParams ? [resourceFromParams] : ([] as string[])	111✔
122	)	111✔
123		111✔
124	if (resources && resources.length > 0) {	111✔
125	resources.map((resource, index) => {	111✔
126	if (!resource.startsWith('/')) {	40,131✔
127	resources[index] = `/${resource}`	40,131✔
128	}	40,131✔
129	})	111✔
130	}	111✔
131		111✔
132	req.resources = resources	111✔
133	req.operation = req.routeOptions.config.operation	111✔
134		111✔
135	if (req.operation) {	111✔
136	trace.getActiveSpan()?.setAttribute('http.operation', req.operation.type)	111!
137	}	111✔
138	})	122✔
139		122✔
140	fastify.addHook('onResponse', async (req, reply) => {	122✔
141	doRequestLog(req, {	126✔
142	reply,	126✔
143	excludeUrls: options.excludeUrls,	126✔
144	statusCode: reply.statusCode,	126✔
145	responseTime: reply.elapsedTime,	126✔
146	})	126✔
147	})	122✔
148	},	122✔
149	{ name: 'log-request' }	123✔
150	)	1✔
151		1✔
152	interface LogRequestOptions {	1✔
153	reply?: FastifyReply	1✔
154	excludeUrls?: string[]	1✔
155	statusCode: number \| 'ABORTED REQ' \| 'ABORTED RES' \| 'ABORTED CONN'	1✔
156	responseTime: number	1✔
157	}	1✔
158		1✔
159	function doRequestLog(req: FastifyRequest, options: LogRequestOptions) {	252✔
160	if (options.excludeUrls?.includes(req.url)) {	252!
UNCOV 161	return	×
UNCOV 162	}	×
163		252✔
164	const rMeth = req.method	252✔
165	const rUrl = redactQueryParamFromRequest(req, [	252✔
166	'token',	252✔
167	'X-Amz-Credential',	252✔
168	'X-Amz-Signature',	252✔
169	'X-Amz-Security-Token',	252✔
170	])	252✔
171	const uAgent = req.headers['user-agent']	252✔
172	const rId = req.id	252✔
173	const cIP = req.ip	252✔
174	const statusCode = options.statusCode	252✔
175	const error = (req.raw as any).executionError \|\| req.executionError	252✔
176	const tenantId = req.tenantId	252✔
177		252✔
178	const buildLogMessage = `${tenantId} \| ${rMeth} \| ${statusCode} \| ${cIP} \| ${rId} \| ${rUrl} \| ${uAgent}`	252✔
179		252✔
180	logSchema.request(req.log, buildLogMessage, {	252✔
181	type: 'request',	252✔
182	req,	252✔
183	res: options.reply,	252✔
184	responseTime: options.responseTime,	252✔
185	error: error,	252✔
186	owner: req.owner,	252✔
187	role: req.jwtPayload?.role,	252✔
188	resources: req.resources,	252✔
189	operation: req.operation?.type ?? req.routeOptions.config.operation?.type,	252✔
190	serverTimes: req.serverTimings,	252✔
191	})	252✔
192	}	252✔
193		1✔
194	function getFirstDefined<T>(...values: any[]): T \| undefined {	111✔
195	for (const value of values) {	111✔
196	if (value !== undefined) {	394✔
197	return value	111✔
198	}	111✔
199	}	394✔
UNCOV 200	return undefined	×
UNCOV 201	}	×
202		1✔
203	/**	1✔
204	* Creates a minimal FastifyRequest from partial HTTP data.	1✔
205	* Used for consistent logging when request parsing fails.	1✔
206	*/	1✔
NEW UNCOV 207	export function createPartialLogRequest(	×
NEW UNCOV 208	fastify: FastifyInstance,	×
NEW UNCOV 209	socket: Socket,	×
NEW UNCOV 210	httpData: PartialHttpData,	×
NEW UNCOV 211	startTime: number	×
NEW UNCOV 212	) {	×
NEW UNCOV 213	return {	×
NEW UNCOV 214	method: httpData.method,	×
NEW UNCOV 215	url: httpData.url,	×
NEW UNCOV 216	headers: httpData.headers,	×
NEW UNCOV 217	ip: socket.remoteAddress \|\| 'unknown',	×
NEW UNCOV 218	id: 'no-request',	×
NEW UNCOV 219	log: fastify.log.child({	×
NEW UNCOV 220	tenantId: httpData.tenantId,	×
NEW UNCOV 221	project: httpData.tenantId,	×
NEW UNCOV 222	reqId: 'no-request',	×
NEW UNCOV 223	appVersion: version,	×
NEW UNCOV 224	dataLength: httpData.length,	×
NEW UNCOV 225	}),	×
NEW UNCOV 226	startTime,	×
NEW UNCOV 227	tenantId: httpData.tenantId,	×
NEW UNCOV 228	raw: {},	×
NEW UNCOV 229	routeOptions: { config: {} },	×
NEW UNCOV 230	resources: [],	×
NEW UNCOV 231	} as unknown as FastifyRequest	×
NEW UNCOV 232	}	×

supabase / storage / 19147127865

Source File Press 'n' to go to next uncovered line, 'b' for previous

Source File
Press 'n' to go to next uncovered line, 'b' for previous