fix: log was not reporting size for compressed requests
Massimo Melina committed
Mar 10, 2023 at 12:01 UTC
7b81047978390373032174eeb212ce00505297e0
2 files changed
+45
-40
src/log.ts
+43
-40
@@ -66,48 +66,51 @@ export function log(): Koa.Middleware {
66
return async (ctx, next) => { // wrapping in a function will make it use current 'mw' value
67
const now = new Date()
68
await next()
69
- const isError = ctx.status >= 400
70
- const logger = isError && accessErrorLog || accessLogger
71
- const rotate = logRotation.get()?.[0]
72
- let { stream, last, path } = logger
73
- if (!stream) return
74
- const a = now.toString().split(' ')
75
- logger.last = now
76
- if (rotate && last) { // rotation enabled and a file exists?
77
- const passed = Number(now) - Number(last)
78
- - 3600_000 // be pessimistic and count a possible DST change
79
- if (rotate === 'm' && (passed >= 31*DAY || now.getMonth() !== last.getMonth())
80
- || 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
81
- || rotate === 'w' && (passed >= 7*DAY || now.getDay() < last.getDay())) {
82
- stream.end()
83
- const postfix = last.getFullYear() + '-' + doubleDigit(last.getMonth() + 1) + '-' + doubleDigit(last.getDate())
84
- try { // other logging requests shouldn't happen while we are renaming. Since this is very infrequent we can tolerate solving this by making it sync.
85
- renameSync(path, path + '-' + postfix)
86
- }
87
- catch(e) { // ok, rename failed, but this doesn't mean we ain't gonna log
88
- console.error(e)
69
+ console.debug(ctx.status, ctx.method, ctx.path)
70
+ Promise.race([ once(ctx.res, 'finish'), once(ctx.res, 'close') ]).then(() => {
71
+ const isError = ctx.status >= 400
72
+ const logger = isError && accessErrorLog || accessLogger
73
+ const rotate = logRotation.get()?.[0]
74
+ let { stream, last, path } = logger
75
+ if (!stream) return
76
+ logger.last = now
77
+ if (rotate && last) { // rotation enabled and a file exists?
78
+ const passed = Number(now) - Number(last)
79
+ - 3600_000 // be pessimistic and count a possible DST change
80
+ if (rotate === 'm' && (passed >= 31*DAY || now.getMonth() !== last.getMonth())
81
+ || 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
82
+ || rotate === 'w' && (passed >= 7*DAY || now.getDay() < last.getDay())) {
83
+ stream.end()
84
+ const postfix = last.getFullYear() + '-' + doubleDigit(last.getMonth() + 1) + '-' + doubleDigit(last.getDate())
85
+ try { // other logging requests shouldn't happen while we are renaming. Since this is very infrequent we can tolerate solving this by making it sync.
86
+ renameSync(path, path + '-' + postfix)
87
+ }
88
+ catch(e) { // ok, rename failed, but this doesn't mean we ain't gonna log
89
+ console.error(e)
90
+ }
91
+ stream = logger.reopen() // keep variable updated
92
+ if (!stream) return
93
}
90
- stream = logger.reopen() // keep variable updated
91
- if (!stream) return
94
}
93
- }
94
- const format = '%s - %s [%s] "%s %s HTTP/%s" %d %s\n' // Apache's Common Log Format
95
- const date = a[2]+'/'+a[1]+'/'+a[3]+':'+a[4]+' '+a[5]?.slice(3)
96
- const user = getCurrentUsername(ctx)
97
- events.emit(logger.name, Object.assign(_.pick(ctx, ['ip', 'method','status','length']), { user, ts: now, uri: ctx.path }))
98
- console.debug(ctx.status, ctx.method, ctx.path)
99
- debounce(() => // once in a while we check if the file is still good (not deleted, etc), or we'll reopen it
100
- stat(logger.path).catch(() => logger.reopen())) // async = smoother but we may lose some entries
101
- stream.write(util.format( format,
102
- ctx.ip,
103
- user || '-',
104
- date,
105
- ctx.method,
106
- ctx.path,
107
- ctx.req.httpVersion,
108
- ctx.status,
109
- ctx.length ? ctx.length.toString() : '-',
110
- ))
95
+ const format = '%s - %s [%s] "%s %s HTTP/%s" %d %s\n' // Apache's Common Log Format
96
+ const a = now.toString().split(' ')
97
+ const date = a[2]+'/'+a[1]+'/'+a[3]+':'+a[4]+' '+a[5]?.slice(3)
98
+ const user = getCurrentUsername(ctx)
99
+ const length = ctx.state.length ?? ctx.length
100
+ events.emit(logger.name, Object.assign(_.pick(ctx, ['ip', 'method','status']), { length, user, ts: now, uri: ctx.path }))
101
+ debounce(() => // once in a while we check if the file is still good (not deleted, etc), or we'll reopen it
102
+ stat(logger.path).catch(() => logger.reopen())) // async = smoother but we may lose some entries
103
+ stream!.write(util.format( format,
104
+ ctx.ip,
105
+ user || '-',
106
+ date,
107
+ ctx.method,
108
+ ctx.path,
109
+ ctx.req.httpVersion,
110
+ ctx.status,
111
+ length?.toString() ?? '-',
112
+ ))
113
+ })
114
}
115
}
116
src/throttler.ts
+2
@@ -75,6 +75,8 @@ export const throttler: Koa.Middleware = async (ctx, next) => {
75
76
if (bak)
77
ctx.response.length = bak
78
+ ts.once('end', () => // in case of compressed response, we offer calculation of real size
79
+ ctx.state.length = ts.getBytesSent())
80
}
81
82
export function roundSpeed(n: number) {