fix: align log timestamp with nginx (request end, not start)
Massimo Melina committed
Mar 20, 2026 at 18:15 UTC
18f96734d91a03621b64c95d676d8308cf9c72a1
1 file changed
+12
-10
src/log.ts
+12
-10
@@ -72,7 +72,7 @@ const logSpam = defineConfig(CFG.log_spam, false)
72
const debounce = _.debounce(cb => cb(), 1000) // with this technique, i'll be able to debounce some code respecting the references in its closure
73
74
export const logMw: Koa.Middleware = async (ctx, next) => {
75
- const now = new Date() // request start
75
+ const reqStart = new Date() // request start
76
const userAtStart = getCurrentUsername(ctx)
77
// do it now so it's available for returning plugins
78
ctx.state.completed = Promise.race([ once(ctx.res, 'finish'), once(ctx.res, 'close') ])
@@ -96,13 +96,14 @@ export const logMw: Koa.Middleware = async (ctx, next) => {
96
const rotate = logRotation.get()?.[0]
97
let { stream, last, path } = logger
98
if (!stream) return
99
- logger.last = now
99
+ logger.last = reqStart
100
if (rotate && last) { // rotation enabled and a file exists?
101
- const passed = Number(now) - Number(last)
101
+ const passed = Number(reqStart) - Number(last)
102
- 3600_000 // be pessimistic and count a possible DST change
103
- if (rotate === 'm' && (passed >= 31*DAY || now.getMonth() !== last.getMonth())
104
- || rotate === 'd' && (passed >= DAY || now.getDate() !== last.getDate()) // checking passed will solve the case when the day of the month is the same but a month has passed
105
- || rotate === 'w' && (passed >= 7*DAY || now.getDay() < last.getDay())) {
103
+ const t = reqStart
104
+ if (rotate === 'm' && (passed >= 31 * DAY || t.getMonth() !== last.getMonth())
105
+ || rotate === 'd' && (passed >= DAY || t.getDate() !== last.getDate()) // checking passed will solve the case when the day of the month is the same but a month has passed
106
+ || rotate === 'w' && (passed >= 7 * DAY || t.getDay() < last.getDay())) {
107
stream.end()
108
const suffix = '-' + last.getFullYear() + '-' + doubleDigit(last.getMonth() + 1) + '-' + doubleDigit(last.getDate())
109
const newPath = strinsert(path, path.length - extname(path).length, suffix)
@@ -117,12 +118,13 @@ export const logMw: Koa.Middleware = async (ctx, next) => {
118
}
119
}
120
const format = '%s - %s [%s] "%s %s HTTP/%s" %d %s %s\n' // Apache's Common Log Format
120
- const a = now.toString().split(' ') // like nginx, our default log contains the time of log writing
121
- const date = a[2]+'/'+a[1]+'/'+a[3]+':'+a[4]+' '+a[5]?.slice(3)
121
+ // keep reqStart for duration/rotation, but log time should reflect when the line is actually written
122
+ const a = new Date().toString().split(' ') // like nginx, our default log contains the time of log writing
123
+ const date = `${a[2]}/${a[1]}/${a[3]}:${a[4]} ${a[5]?.slice(3)}`
124
const user = getCurrentUsername(ctx) || userAtStart
125
const length = ctx.state.length ?? ctx.length
126
const uri = ctx.originalUrl
125
- const duration = (Date.now() - Number(now)) / 1000
127
+ const duration = (Date.now() - Number(reqStart)) / 1000
128
ctx.logExtra(ctx.vfsNode && {
129
speed: Math.round(length / duration),
130
...ctx.state.includesLastByte && ctx.res.finished && { dl: 1 }
@@ -137,7 +139,7 @@ export const logMw: Koa.Middleware = async (ctx, next) => {
139
ctx.logExtra({ ua: ctx.get('user-agent') || undefined })
140
const extra = ctx.state.logExtra
141
if (events.anyListener(logger.name)) // small optimization: this event can happen often, while most times there's no listener, and the parameters object is constructed pointlessly. A benchmark measured it 20% faster (just the line), while maybe it was not necessary.
140
- events.emit(logger.name, { ctx, length, user, ts: now, uri, extra })
142
+ events.emit(logger.name, { ctx, length, user, ts: reqStart, uri, extra })
143
debounce(() => // once in a while we check if the file is still good (not deleted, etc), or we'll reopen it
144
statWithTimeout(logger.path).catch(() => logger.reopen())) // async = smoother but we may lose some entries
145
stream!.write(util.format( format,