From 166211b27846a96ad6c764d28c4df19aaf18e322 Mon Sep 17 00:00:00 2001 From: Eric Mc Sween Date: Thu, 24 Oct 2019 22:02:55 -0400 Subject: [PATCH] Stackdriver logging When the environment variable STACKDRIVER_LOGGING is set to true, send request logs in a format that Stackdriver knows how to interpret. Also, set the log level accordint to the status code. 4xx responses are logged as warnings and 5xx responses are logged as errors. --- libraries/metrics/http.coffee | 62 +++++++++++++++++++-------- libraries/metrics/package.json | 7 ++-- libraries/metrics/statsd/http.coffee | 63 +++++++++++++++++++--------- 3 files changed, 92 insertions(+), 40 deletions(-) diff --git a/libraries/metrics/http.coffee b/libraries/metrics/http.coffee index f5e3719d53..5b0dad072f 100644 --- a/libraries/metrics/http.coffee +++ b/libraries/metrics/http.coffee @@ -1,29 +1,55 @@ os = require("os") +yn = require("yn") + +STACKDRIVER_LOGGING = yn(process.env['STACKDRIVER_LOGGING']) module.exports.monitor = (logger) -> return (req, res, next) -> Metrics = require("./metrics") - startTime = new Date() + startTime = process.hrtime() end = res.end res.end = () -> end.apply(this, arguments) - responseTime = new Date() - startTime + responseTime = process.hrtime(startTime) + responseTimeMs = Math.round(responseTime[0] * 1000 + responseTime[1] / 1000) if req.route?.path? routePath = req.route.path.toString().replace(/\//g, '_').replace(/\:/g, '').slice(1) - Metrics.timing("http_request", responseTime, null, {method:req.method, status_code: res.statusCode, path:routePath}) - logger.log - req: - url: req.originalUrl || req.url - method: req.method - referrer: req.headers['referer'] || req.headers['referrer'] - "remote-addr": req.ip || req.socket?.socket?.remoteAddress || req.socket?.remoteAddress - "user-agent": req.headers["user-agent"] - "content-length": req.headers["content-length"] - res: - "content-length": res._headers?["content-length"] - statusCode: res.statusCode - "response-time": responseTime - "http request" - + Metrics.timing("http_request", responseTimeMs, null, {method:req.method, status_code: res.statusCode, path:routePath}) + remoteIp = req.ip || req.socket?.socket?.remoteAddress || req.socket?.remoteAddress + reqUrl = req.originalUrl || req.url + referrer = req.headers['referer'] || req.headers['referrer'] + if STACKDRIVER_LOGGING + info = + httpRequest: + requestMethod: req.method + requestUrl: reqUrl + requestSize: req.headers["content-length"] + status: res.statusCode + responseSize: res._headers?["content-length"] + userAgent: req.headers["user-agent"] + remoteIp: remoteIp + referer: referrer + latency: + seconds: responseTime[0] + nanos: responseTime[1] + protocol: req.protocol + else + info = + req: + url: reqUrl + method: req.method + referrer: referrer + "remote-addr": remoteIp + "user-agent": req.headers["user-agent"] + "content-length": req.headers["content-length"] + res: + "content-length": res._headers?["content-length"] + statusCode: res.statusCode + "response-time": responseTimeMs + if res.statusCode >= 500 + logger.error(info, "%s %s", req.method, reqUrl) + else if res.statusCode >= 400 and res.statusCode < 500 + logger.warn(info, "%s %s", req.method, reqUrl) + else + logger.info(info, "%s %s", req.method, reqUrl) next() - diff --git a/libraries/metrics/package.json b/libraries/metrics/package.json index 24daa5da46..d206cf8886 100644 --- a/libraries/metrics/package.json +++ b/libraries/metrics/package.json @@ -7,13 +7,14 @@ "url": "https://github.com/sharelatex/metrics-sharelatex.git" }, "dependencies": { + "@google-cloud/debug-agent": "^3.0.0", + "@google-cloud/profiler": "^0.2.3", + "@google-cloud/trace-agent": "^3.2.0", "coffee-script": "1.6.0", "lynx": "~0.1.1", "prom-client": "^11.1.3", "underscore": "~1.6.0", - "@google-cloud/debug-agent": "^3.0.0", - "@google-cloud/profiler": "^0.2.3", - "@google-cloud/trace-agent": "^3.2.0" + "yn": "^3.1.1" }, "devDependencies": { "bunyan": "^1.0.0", diff --git a/libraries/metrics/statsd/http.coffee b/libraries/metrics/statsd/http.coffee index c175f26a14..f9320ed758 100644 --- a/libraries/metrics/statsd/http.coffee +++ b/libraries/metrics/statsd/http.coffee @@ -1,31 +1,56 @@ os = require("os") +yn = require("yn") + +STACKDRIVER_LOGGING = yn(process.env['STACKDRIVER_LOGGING']) module.exports.monitor = (logger) -> return (req, res, next) -> Metrics = require("./metrics") - startTime = new Date() + startTime = process.hrtime() end = res.end res.end = () -> end.apply(this, arguments) - responseTime = new Date() - startTime + responseTime = process.hrtime(startTime) + responseTimeMs = Math.round(responseTime[0] * 1000 + responseTime[1] / 1000) if req.route?.path? routePath = req.route.path.toString().replace(/\//g, '_').replace(/\:/g, '').slice(1) key = "http-requests.#{routePath}.#{req.method}.#{res.statusCode}" - - Metrics.timing(key, responseTime) - logger.log - req: - url: req.originalUrl || req.url - method: req.method - referrer: req.headers['referer'] || req.headers['referrer'] - "remote-addr": req.ip || req.socket?.socket?.remoteAddress || req.socket?.remoteAddress - "user-agent": req.headers["user-agent"] - "content-length": req.headers["content-length"] - res: - "content-length": res._headers?["content-length"] - statusCode: res.statusCode - "response-time": responseTime - "http request" - + Metrics.timing(key, responseTimeMs) + remoteIp = req.ip || req.socket?.socket?.remoteAddress || req.socket?.remoteAddress + reqUrl = req.originalUrl || req.url + referrer = req.headers['referer'] || req.headers['referrer'] + if STACKDRIVER_LOGGING + info = + httpRequest: + requestMethod: req.method + requestUrl: reqUrl + requestSize: req.headers["content-length"] + status: res.statusCode + responseSize: res._headers?["content-length"] + userAgent: req.headers["user-agent"] + remoteIp: remoteIp + referer: referrer + latency: + seconds: responseTime[0] + nanos: responseTime[1] + protocol: req.protocol + else + info = + req: + url: reqUrl + method: req.method + referrer: referrer + "remote-addr": remoteIp + "user-agent": req.headers["user-agent"] + "content-length": req.headers["content-length"] + res: + "content-length": res._headers?["content-length"] + statusCode: res.statusCode + "response-time": responseTimeMs + if res.statusCode >= 500 + logger.error(info, "%s %s", req.method, reqUrl) + else if res.statusCode >= 400 and res.statusCode < 500 + logger.warn(info, "%s %s", req.method, reqUrl) + else + logger.info(info, "%s %s", req.method, reqUrl) next() -