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

@@ -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()
-

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",

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()
-