fix: error if another request is about to be logged while log-rotating
Massimo Melina committed
Apr 25, 2022 at 12:18 UTC
1f01b2245f0c210426704338334fa50a41a5a9a3
1 file changed
+18
-18
server/src/log.ts
+18
-18
@@ -3,9 +3,9 @@
3
import Koa from 'koa'
4
import { Writable } from 'stream'
5
import { defineConfig, getConfig, subscribeConfig } from './config'
6
-import { createWriteStream } from 'fs'
6
+import { createWriteStream, renameSync } from 'fs'
7
import * as util from 'util'
8
-import { rename, stat } from 'fs/promises'
8
+import { stat } from 'fs/promises'
9
import { DAY } from './const'
10
import events from './events'
11
import _ from 'lodash'
@@ -33,7 +33,7 @@ class Logger {
33
}
34
35
reopen() {
36
- this.stream = createWriteStream(this.path, { flags: 'a' })
36
+ return this.stream = createWriteStream(this.path, { flags: 'a' })
37
}
38
}
39
@@ -52,11 +52,6 @@ subscribeConfig({ k: 'error_log', defaultValue: 'error.log' }, path => {
52
errorLogger.setPath(path)
53
})
54
55
-function getMidnight(date: Date=new Date) {
56
- date.setHours(0,0,0,0)
57
- return date
58
-}
59
-
55
defineConfig('log_rotation', { defaultValue: 'weekly' })
56
57
export function log(): Koa.Middleware {
@@ -64,28 +59,33 @@ export function log(): Koa.Middleware {
59
await next()
60
const isError = ctx.status >= 400
61
const logger = isError && errorLogger || accessLogger
67
- const freq = getConfig('log_rotation')?.[0]
68
- const { stream, last, path } = logger
62
+ const rotate = getConfig('log_rotation')?.[0]
63
+ let { stream, last, path } = logger
64
if (!stream) return
65
const now = new Date()
66
const a = now.toString().split(' ')
72
- if (freq && last) {
67
+ logger.last = now
68
+ if (rotate && last) { // rotation enabled and a file exists?
69
const passed = Number(now) - Number(last)
70
- 3600_000 // be pessimistic and count a possible DST change
75
- if (freq === 'm' && (passed >= 31*DAY || now.getMonth() !== last.getMonth())
76
- || freq === 'd' && (passed >= DAY || now.getDate() !== last.getDate())
77
- || freq === 'w' && (passed >= 7*DAY || now.getDay() < last.getDay())) {
71
+ if (rotate === 'm' && (passed >= 31*DAY || now.getMonth() !== last.getMonth())
72
+ || rotate === 'd' && (passed >= DAY || now.getDate() !== last.getDate())
73
+ || rotate === 'w' && (passed >= 7*DAY || now.getDay() < last.getDay())) {
74
stream.end()
75
const postfix = last.getFullYear() + '-' + doubleDigit(last.getMonth() + 1) + '-' + doubleDigit(last.getDate())
80
- await rename(path, path + '-' + postfix)
81
- logger.reopen()
76
+ 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.
77
+ renameSync(path, path + '-' + postfix)
78
+ }
79
+ catch(e) { // ok, rename failed, but this doesn't mean we ain't gonna log
80
+ console.error(e)
81
+ }
82
+ stream = logger.reopen() // keep variable updated
83
}
84
}
84
- logger.last = now
85
const format = '%s - - [%s] "%s %s HTTP/%s" %d %s\n';
86
const date = a[2]+'/'+a[1]+'/'+a[3]+':'+a[4]+' '+a[5].slice(3)
87
events.emit(logger.name, Object.assign(_.pick(ctx, ['ip', 'method','status','length']), { ts: now, uri: ctx.path }))
88
- logger.stream!.write(util.format( format,
88
+ stream.write(util.format( format,
89
ctx.ip,
90
date,
91
ctx.method,