fix: align log timestamp with nginx (request end, not start)
Massimo Melina committed
Mar 20, 2026 at 18:15 UTC
3ebd65339b407d0b4a8a37b9fad381f3ab1993d2
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') ])
@@ -98,13 +98,14 @@ export const logMw: Koa.Middleware = async (ctx, next) => {
98
const rotate = logRotation.get()?.[0]
99
let { stream, last, path } = logger
100
if (!stream) return
101
- logger.last = now
101
+ logger.last = reqStart
102
if (rotate && last) { // rotation enabled and a file exists?
103
- const passed = Number(now) - Number(last)
103
+ const passed = Number(reqStart) - Number(last)
104
- 3600_000 // be pessimistic and count a possible DST change
105
- if (rotate === 'm' && (passed >= 31*DAY || now.getMonth() !== last.getMonth())
106
- || 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
107
- || rotate === 'w' && (passed >= 7*DAY || now.getDay() < last.getDay())) {
105
+ const t = reqStart
106
+ if (rotate === 'm' && (passed >= 31 * DAY || t.getMonth() !== last.getMonth())
107
+ || 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
108
+ || rotate === 'w' && (passed >= 7 * DAY || t.getDay() < last.getDay())) {
109
stream.end()
110
const suffix = '-' + last.getFullYear() + '-' + doubleDigit(last.getMonth() + 1) + '-' + doubleDigit(last.getDate())
111
const newPath = strinsert(path, path.length - extname(path).length, suffix)
@@ -119,12 +120,13 @@ export const logMw: Koa.Middleware = async (ctx, next) => {
120
}
121
}
122
const format = '%s - %s [%s] "%s %s HTTP/%s" %d %s %s\n' // Apache's Common Log Format
122
- const a = now.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)
123
+ // keep reqStart for duration/rotation, but log time should reflect when the line is actually written
124
+ const a = new Date().toString().split(' ') // like nginx, our default log contains the time of log writing
125
+ const date = `${a[2]}/${a[1]}/${a[3]}:${a[4]} ${a[5]?.slice(3)}`
126
const user = getCurrentUsername(ctx) || userAtStart
127
const length = ctx.state.length ?? ctx.length
128
const uri = ctx.originalUrl
127
- const duration = (Date.now() - Number(now)) / 1000
129
+ const duration = (Date.now() - Number(reqStart)) / 1000
130
ctx.logExtra(ctx.vfsNode && {
131
speed: Math.round(length / duration),
132
...ctx.state.includesLastByte && ctx.res.finished && { dl: 1 }
@@ -139,7 +141,7 @@ export const logMw: Koa.Middleware = async (ctx, next) => {
141
ctx.logExtra({ ua: ctx.get('user-agent') || undefined })
142
const extra = ctx.state.logExtra
143
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.
142
- events.emit(logger.name, { ctx, length, user, ts: now, uri, extra })
144
+ events.emit(logger.name, { ctx, length, user, ts: reqStart, uri, extra })
145
debounce(() => // once in a while we check if the file is still good (not deleted, etc), or we'll reopen it
146
statWithTimeout(logger.path).catch(() => logger.reopen())) // async = smoother but we may lose some entries
147
stream!.write(util.format( format,