Skip to content
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.

Sign up for GitHub

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

Jump to bottom

log full body only on slow requests and only 10 per day #3215

Draft
wants to merge 1 commit into
base: log-req-body-core-189
Choose a base branch
from
Draft

log full body only on slow requests and only 10 per day #3215

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 30 additions & 2 deletions packages/cli/src/daemon/log-requests.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,10 +2,38 @@ import { LoggerProvider } from '@ceramicnetwork/common'
import { Request, Response } from 'express'
import morgan from 'morgan'

const EXPECTED_RESPONSE_TIME_MS = 2000
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the default threshold for what's considered a "slow" request should probably be higher. Maybe 15 seconds?

Also might be nice to make this threshold configurable.

const MAX_DAILY_SLOW_REQUESTS_TO_LOG = 10
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about only logging one slow query per minute instead? I think that will still be infrequent enough to not flood the logs, while making the slow queries a lot more visible if they are happening often.


const ACCESS_LOG_FMT =
'ip=:remote-addr ts=:date[iso] method=:method original_url=:original-url base_url=:base-url path=:path:params :body http_version=:http-version req_header:req[header] status=:status content_length=:res[content-length] content_type=":res[content-type]" ref=:referrer user_agent=":user-agent" elapsed_ms=:total-time[3] error_message=":error-message" error_code=:error-code'

export function logRequests(loggerProvider: LoggerProvider): any[] {

// these trackers and middleware enable us to log just a sample of slow requests each day or app restart
let slowRequestCount = 0;
let lastLoggedDate = new Date().toISOString().slice(0, 10);

// Middleware to calculate response time and handle daily reset of the counter
const responseTimeMiddleware = (req: Request, res: Response, next: Function) => {
const start = Date.now();
const currentDate = new Date().toISOString().slice(0, 10);

if (lastLoggedDate !== currentDate) {
slowRequestCount = 0; // Reset counter if it's a new day
lastLoggedDate = currentDate; // Update the last logged date
}

res.on('finish', () => {
const responseTime = Date.now() - start;
if (responseTime > EXPECTED_RESPONSE_TIME_MS && slowRequestCount < MAX_DAILY_SLOW_REQUESTS_TO_LOG) {
slowRequestCount++;
res.locals.logSlowRequest = true; // Flag to log this request
}
});
next();
};

morgan.token<Request, Response>('error-message', (req, res: Response) => {
return res.locals.error?.message
})
Expand Down Expand Up @@ -33,8 +61,8 @@ export function logRequests(loggerProvider: LoggerProvider): any[] {
}
return ' params=-'
})
morgan.token<Request, Response>('body', (req) => {
if (req.body) {
morgan.token<Request, Response>('body', (req, res: Response) => {
if (req.body && res.locals.logSlowRequest) {
const keys = Object.keys(req.body)
if (keys.length > 0) {
const body = keys.reduce((prev, curr) => {
Expand Down