| 1 | // This file is part of HFS - Copyright 2021-2023, Massimo Melina <a@rejetto.com> - License https://www.gnu.org/licenses/gpl-3.0.txt |
| 2 | |
| 3 | import Koa from 'koa' |
| 4 | import { once } from 'events' |
| 5 | import { Writable } from 'stream' |
| 6 | import { defineConfig } from './config' |
| 7 | import { createWriteStream, renameSync, statSync } from 'fs' |
| 8 | import * as util from 'util' |
| 9 | import _ from 'lodash' |
| 10 | import { createFileWithPath, ensureParentFolder, statWithTimeout } from './util-files' |
| 11 | import { getCurrentUsername } from './auth' |
| 12 | import { DAY, makeNetMatcher, tryJson, Dict, Falsy, CFG, strinsert, repeat, formatTimestamp, HTTP_NOT_FOUND } from './misc' |
| 13 | import { basename, extname } from 'path' |
| 14 | import yazl from 'yazl' |
| 15 | import { pipeline } from 'stream/promises' |
| 16 | import { rm, unlink, utimes } from 'fs/promises' |
| 17 | import events from './events' |
| 18 | import { getConnection } from './connections' |
| 19 | import { app } from './index' |
| 20 | import { logGui } from './serveGuiFiles' |
| 21 | import glob from 'fast-glob' |
| 22 | |
| 23 | class Logger { |
| 24 | stream?: Writable |
| 25 | last?: Date |
| 26 | path: string = '' |
| 27 | |
| 28 | constructor(readonly name: string){ |
| 29 | } |
| 30 | |
| 31 | async setPath(path: string) { |
| 32 | this.path = path |
| 33 | this.stream?.end() |
| 34 | this.last = undefined |
| 35 | if (!path) |
| 36 | return this.stream = undefined |
| 37 | try { |
| 38 | const stats = await statWithTimeout(path) |
| 39 | this.last = stats.mtime |
| 40 | } |
| 41 | catch { |
| 42 | if (await ensureParentFolder(path) === false) |
| 43 | console.log("Cannot create folder for", path) |
| 44 | } |
| 45 | this.reopen() |
| 46 | } |
| 47 | |
| 48 | reopen() { |
| 49 | return this.stream = createFileWithPath(this.path, { flags: 'a' }) |
| 50 | ?.on('error', () => this.stream = undefined) |
| 51 | } |
| 52 | } |
| 53 | |
| 54 | // we'll have names same as config keys. These are used also by the get_log api. |
| 55 | const accessLogger = new Logger(CFG.log) |
| 56 | const accessErrorLog = new Logger(CFG.error_log) |
| 57 | export const loggers = [accessLogger, accessErrorLog] |
| 58 | |
| 59 | defineConfig(accessLogger.name, 'logs/access.log').sub(path => { |
| 60 | console.debug('Access log file: ' + (path || 'disabled')) |
| 61 | accessLogger.setPath(path) |
| 62 | }) |
| 63 | |
| 64 | const errorLogFile = defineConfig(accessErrorLog.name, 'logs/access-error.log') |
| 65 | errorLogFile.sub(path => { |
| 66 | console.debug('Access error log: ' + (path || 'disabled')) |
| 67 | accessErrorLog.setPath(path) |
| 68 | }) |
| 69 | |
| 70 | const logRotation = defineConfig(CFG.log_rotation, 'weekly') |
| 71 | const dontLogNet = defineConfig(CFG.dont_log_net, '127.0.0.1|::1', v => makeNetMatcher(v)) |
| 72 | const logUA = defineConfig(CFG.log_ua, false) |
| 73 | const logSpam = defineConfig(CFG.log_spam, false) |
| 74 | |
| 75 | const debounce = _.debounce(cb => cb(), 1000) // with this technique, i'll be able to debounce some code respecting the references in its closure |
| 76 | |
| 77 | export const logMw: Koa.Middleware = async (ctx, next) => { |
| 78 | const reqStart = new Date() // request start |
| 79 | const userAtStart = getCurrentUsername(ctx) |
| 80 | // do it now so it's available for returning plugins |
| 81 | ctx.state.completed = Promise.race([ once(ctx.res, 'finish'), once(ctx.res, 'close') ]) |
| 82 | await next() |
| 83 | if (!ctx.state.dontLog) // with Finder's webdav spam, it's best to not report even in console |
| 84 | console.debug(ctx.status, ctx.method, ctx.originalUrl, ctx.isAborted() ? '(aborted)' : '') |
| 85 | if (!logSpam.get() |
| 86 | && (ctx.querystring.includes('{.exec|') // v2's bug |
| 87 | // requests generated by security scanners, other bots, and macos' finder |
| 88 | || ctx.status === HTTP_NOT_FOUND && /wlwmanifest.xml$|\.(php)$|cgi|robots.txt$/.test(ctx.path))) { |
| 89 | events.emit('spam', ctx) |
| 90 | return |
| 91 | } |
| 92 | if (ctx.isAborted()) |
| 93 | ctx.logExtra({ aborted: true }) |
| 94 | const conn = getConnection(ctx) // collect reference before close |
| 95 | // don't await, as we don't want to hold the middlewares chain |
| 96 | ctx.state.completed.then(() => { |
| 97 | if (ctx.state.dontLog || ctx.state.considerAsGui && !logGui.get()) return |
| 98 | if (dontLogNet.compiled()(ctx.ip)) return |
| 99 | const isError = ctx.status >= 400 |
| 100 | const logger = isError && accessErrorLog || accessLogger |
| 101 | let { stream, last, path } = logger |
| 102 | if (!stream) return |
| 103 | const rotate = logRotation.get()?.[0] |
| 104 | const reqEnd = logger.last = new Date() |
| 105 | if (rotate && last) { // rotation enabled and a file exists? |
| 106 | const passed = Number(reqEnd) - Number(last) |
| 107 | - 3600_000 // be pessimistic and count a possible DST change |
| 108 | const t = reqEnd |
| 109 | if (rotate === 'm' && (passed >= 31 * DAY || t.getMonth() !== last.getMonth()) |
| 110 | || 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 |
| 111 | || rotate === 'w' && (passed >= 7 * DAY || t.getDay() < last.getDay())) { |
| 112 | stream.end() |
| 113 | const suffix = '-' + last.getFullYear() + '-' + doubleDigit(last.getMonth() + 1) + '-' + doubleDigit(last.getDate()) |
| 114 | const newPath = strinsert(path, path.length - extname(path).length, suffix) |
| 115 | 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. |
| 116 | renameSync(path, newPath) |
| 117 | void zipLogFile(newPath, last).catch(console.error) |
| 118 | } |
| 119 | catch(e: any) { // ok, rename failed, but this doesn't mean we ain't gonna log |
| 120 | console.error(e.message || String(e)) |
| 121 | } |
| 122 | stream = logger.reopen() // keep variable updated |
| 123 | if (!stream) return |
| 124 | } |
| 125 | } |
| 126 | const format = '%s - %s [%s] "%s %s HTTP/%s" %d %s %s\n' // Apache's Common Log Format |
| 127 | const a = reqEnd.toString().split(' ') // like nginx, our default log contains the time of log writing |
| 128 | const date = `${a[2]}/${a[1]}/${a[3]}:${a[4]} ${a[5]?.slice(3)}` |
| 129 | const user = getCurrentUsername(ctx) || userAtStart |
| 130 | const length = ctx.state.length ?? ctx.length |
| 131 | const uri = ctx.originalUrl |
| 132 | const duration = (Number(reqEnd) - Number(reqStart)) / 1000 |
| 133 | ctx.logExtra(ctx.vfsNode && { |
| 134 | speed: Math.round(length / duration), |
| 135 | ...ctx.state.includesLastByte && ctx.res.finished && { dl: 1 } |
| 136 | } || ctx.state.uploadSize !== undefined && { |
| 137 | ul: ctx.state.uploads, |
| 138 | size: ctx.state.uploadSize, |
| 139 | speed: Math.round(ctx.state.uploadSize / duration), |
| 140 | }) |
| 141 | if (conn?.country) |
| 142 | ctx.logExtra({ country: conn.country }) |
| 143 | if (logUA.get()) |
| 144 | ctx.logExtra({ ua: ctx.get('user-agent') || undefined }) |
| 145 | const extra = ctx.state.logExtra |
| 146 | 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. |
| 147 | events.emit(logger.name, { ctx, length, user, ts: reqEnd, uri, extra }) |
| 148 | debounce(() => // once in a while we check if the file is still good (not deleted, etc), or we'll reopen it |
| 149 | statWithTimeout(logger.path).catch(() => logger.reopen())) // async = smoother but we may lose some entries |
| 150 | stream!.write(util.format( format, |
| 151 | ctx.ip, |
| 152 | user || '-', |
| 153 | date, |
| 154 | ctx.method, |
| 155 | uri, |
| 156 | ctx.req.httpVersion, |
| 157 | ctx.status, |
| 158 | length?.toString() ?? '-', |
| 159 | _.isEmpty(extra) ? '' : JSON.stringify(JSON.stringify(extra)), // jsonize twice, as we need a field enclosed by double-quotes |
| 160 | )) |
| 161 | }).catch(e => console.error('log completion:', e.message || String(e))) |
| 162 | } |
| 163 | |
| 164 | declare module "koa" { |
| 165 | interface BaseContext { |
| 166 | logExtra(o: Falsy | Dict<any>, params?: Dict<any>): void |
| 167 | } |
| 168 | interface DefaultState { |
| 169 | dontLog?: boolean // don't log this request |
| 170 | logExtra?: object |
| 171 | completed?: Promise<unknown> |
| 172 | spam?: boolean // this request was marked as spam |
| 173 | considerAsGui?: boolean |
| 174 | } |
| 175 | } |
| 176 | |
| 177 | events.once('app', () => { // wait for app to be set |
| 178 | app.context.logExtra = function(anything, params) { // no => as we need 'this' |
| 179 | _.merge((this as any).state, { logExtra: { ...anything, params } }) // params will be considered as parameters of the API |
| 180 | } |
| 181 | }) |
| 182 | |
| 183 | export async function zipLogFile(path: string, touch: Date) { |
| 184 | const zipPath = path + '.zip' |
| 185 | try { |
| 186 | const zip = new yazl.ZipFile() |
| 187 | const output = createWriteStream(zipPath) |
| 188 | zip.addFile(path, basename(path)) |
| 189 | zip.end() |
| 190 | await pipeline(zip.outputStream, output) |
| 191 | } |
| 192 | catch (e) { |
| 193 | await rm(zipPath, { force: true }).catch(() => {}) |
| 194 | throw e |
| 195 | } |
| 196 | await utimes(zipPath, touch, touch).catch(console.error) |
| 197 | await events.emitAsync('logRotated', { path, zipPath }) |
| 198 | await unlink(path).catch(console.error) |
| 199 | } |
| 200 | |
| 201 | function doubleDigit(n: number) { |
| 202 | return n > 9 ? n : '0'+n |
| 203 | } |
| 204 | |
| 205 | export async function getRotatedFiles() { |
| 206 | return Object.fromEntries(await Promise.all(loggers.map(async x => { |
| 207 | const mask = strinsert(x.path, x.path.length - extname(x.path).length, '-2*') // including 2, initial digit of the year, will only take rotated files and not "-error" |
| 208 | const list = await Promise.all(['', '.zip'].map(async postfix => // before 3.2 rotated logs were not zipped, and even today there's a very small (negligible) chance that the zipping fails |
| 209 | (await glob(mask + postfix, { stats: true })) |
| 210 | .map(x => ({ path: x.path, size: x.stats?.size })) |
| 211 | )) |
| 212 | return [x.name, list.flat()] |
| 213 | }))) |
| 214 | } |
| 215 | |
| 216 | // dump console.error to file |
| 217 | let debugLogFile = createWriteStream('debug.log', { flags: 'a' }) |
| 218 | debugLogFile.once('open', () => { |
| 219 | const was = console.error |
| 220 | console.error = function(...args: any[]) { |
| 221 | was.apply(this, args) |
| 222 | args = args.map(x => typeof x === 'string' ? x : (tryJson(x) ?? String(x))) |
| 223 | debugLogFile.write(formatTimestamp(new Date) + ' - ' + args.join(' ') + '\n') |
| 224 | } |
| 225 | // limit log size |
| 226 | const LIMIT = 1_000_000 |
| 227 | const { path } = debugLogFile |
| 228 | repeat(DAY, () => { // do it sync, to avoid overlapping |
| 229 | if (statSync(path).size < LIMIT) return // no need |
| 230 | renameSync(path, 'old-' + path) |
| 231 | debugLogFile = createWriteStream(path) // new file |
| 232 | }) |
| 233 | }).on('error', () => console.log("Cannot create debug.log")) |