master Added performance and usage logging for prometheus

master.js

@@ -63,6 +63,44 @@ app.use(express.static('static'));
 // mod downloads
 app.use(express.static(masterModFolder));
 
+// set up logging software
+const prometheusPrefix = "clusterio_";
+const Prometheus = require('prom-client');
+Prometheus.collectDefaultMetrics({ timeout: 10000 }); // collects RAM usage etc every 10 s
+const httpRequestDurationMilliseconds = new Prometheus.Histogram({
+  name: prometheusPrefix+'http_request_duration_ms',
+  help: 'Duration of HTTP requests in ms',
+  labelNames: ['route'],
+  // buckets for response time from 0.1ms to 500ms
+  buckets: [0.10, 5, 15, 50, 100, 200, 300, 400, 500]
+});
+const endpointHitCounter = new Prometheus.Gauge({
+	name: prometheusPrefix+'endpoint_hit_gauge',
+	help: "How many requests a particular endpoint has gotten",
+	labelNames: ['route'],
+});
+const prometheusConnectedInstancesCounter = new Prometheus.Gauge({
+	name: prometheusPrefix+'connected_instaces_gauge',
+	help: "How many instances are currently connected to this master server",
+});
+setInterval(()=>{
+	let numberOfActiveSlaves = 0;
+	for(let instance in slaves){
+		if(Date.now() - Number(slaves[instance].time) < 1000 * 30) numberOfActiveSlaves++;
+	}
+	prometheusConnectedInstancesCounter.set(numberOfActiveSlaves);
+},10000);
+/**
+Prometheus metrics endpoint. Returns performance and usage metrics in a prometheus readable format.
+*/
+app.get('/metrics', (req, res) => {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
+	res.set('Content-Type', Prometheus.register.contentType);
+	res.end(Prometheus.register.metrics());
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
+});
+
 // set up database
 var Datastore = require('nedb');
 db = {};
@@ -145,6 +183,8 @@ process.on('SIGINT', function () {
 // world ID management
 // slaves post here to tell the server they exist
 app.post("/api/getID", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	// request.body should be an object
 	// {rconPort, rconPassword, serverPort, mac, time}
 	// time us a unix timestamp we can use to check for how long the server has been unresponsive
@@ -163,9 +203,12 @@ app.post("/api/getID", function(req,res) {
 		}
 		console.log("Slave registered: " + slaves[req.body.unique].mac + " : " + slaves[req.body.unique].serverPort+" at " + slaves[req.body.unique].publicIP + " with name " + slaves[req.body.unique].instanceName);
 	}
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 
 app.post("/api/editSlaveMeta", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	// request.body should be an object
 	// {instanceID, pass, meta:{x,y,z}}
 	
@@ -181,10 +224,13 @@ app.post("/api/editSlaveMeta", function(req,res) {
 			res.send("ERROR: Invalid instanceID or password")
 		}
 	}
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 // mod management
 // should handle uploading and checking if mods are uploaded
 app.post("/api/checkMod", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	let files = fs.readdirSync(masterModFolder);
 	let found = false;
 	files.forEach(file => {
@@ -199,25 +245,31 @@ app.post("/api/checkMod", function(req,res) {
 		res.send("found");
 	}
 	res.end();
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 app.post("/api/uploadMod", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	if (!req.files) {
         res.send('No files were uploaded.');
         return;
     } else {
 		console.log(req.files.file);
 		req.files.file.mv('./database/masterMods/'+req.files.file.name, function(err) {
-		if (err) {
-			res.status(500).send(err);
-		} else {
-			res.send('File uploaded!');
-			console.log("Uploaded mod: " + req.files.file.name);
-		}
-	});
+			if (err) {
+				res.status(500).send(err);
+			} else {
+				res.send('File uploaded!');
+				console.log("Uploaded mod: " + req.files.file.name);
+			}
+			httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
+		});
 	}
 });
 // endpoint for getting information about all our slaves
 app.get("/api/slaves", function(req, res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	res.header("Access-Control-Allow-Origin", "*");
 	res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
 	let copyOfSlaves = JSON.parse(JSON.stringify(slaves));
@@ -226,6 +278,7 @@ app.get("/api/slaves", function(req, res) {
 		copyOfSlaves[key].rconPassword = "hidden";
 	}
 	res.send(copyOfSlaves);
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 var recievedItemStatisticsBySlaveID = {};
 var sentItemStatisticsBySlaveID = {};
@@ -247,6 +300,8 @@ POST endpoint for storing items in master's inventory.
 @returns {string} status either "success" or "failure"
 */
 app.post("/api/place", function(req, res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	res.header("Access-Control-Allow-Origin", "*");
 	res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
 	let x;
@@ -297,6 +352,7 @@ app.post("/api/place", function(req, res) {
 	} else {
 		res.send("failure");
 	}
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 /**
 POST endpoint to remove items from DB when client orders items.
@@ -311,6 +367,8 @@ POST endpoint to remove items from DB when client orders items.
 */
 _doleDivisionFactor = {}; //If the server regularly can't fulfill requests, this number grows until it can. Then it slowly shrinks back down.
 app.post("/api/remove", function(req, res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	const doleDivisionRetardation = 10; //lower rates will equal more dramatic swings
 	const maxDoleDivision = 250; //a higher cap will divide the store more ways, but will take longer to recover as supplies increase
 	res.header("Access-Control-Allow-Origin", "*");
@@ -361,10 +419,12 @@ app.post("/api/remove", function(req, res) {
 				sentItemStatisticsBySlaveID[object.instanceID] = sentItemStatistics;
 			}
 			res.send({count: object.count, name: object.name});
+			httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 		} else {
 			// if we didn't have enough, attempt giving out a smaller amount next time
 			_doleDivisionFactor[object.name] = Math.min(maxDoleDivision, Math.max((_doleDivisionFactor[object.name]||0)||1, 1) * 2);
 			res.send({name:object.name, count:0});
+			httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 			//console.log('failure out of ' + object.name + " | " + object.count + " from " + object.instanceID + " ("+object.instanceName+")");
 		}
 	}
@@ -382,8 +442,11 @@ Gives no response
 @param {number} circuitFrame.time
 */
 app.post("/api/setSignal", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	if(typeof req.body == "object" && req.body.time){
 		db.signals.insert(req.body);
+		httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 		// console.log("signal set");
 	}
 });
@@ -396,12 +459,15 @@ POST endpoint to read database of circuit signals sent to master
 @returns {object} circuitFrame
 */
 app.post("/api/readSignal", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	// request.body should be an object
 	// {since:UNIXTIMESTAMP,}
 	// we should send an array of all signals since then
 	db.signals.find({time:{$gte: req.body.since}}, function (err, docs) {
 		// $gte means greater than or equal to, meaning we only get entries newer than the timestamp
 		res.send(docs);
+		httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 		// console.log(docs);
 	});
 });
@@ -415,6 +481,8 @@ GET endpoint to read the masters current inventory of items.
 */
 // endpoint for getting an inventory of what we got
 app.get("/api/inventory", function(req, res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	res.header("Access-Control-Allow-Origin", "*");
 	res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
 	// Check it and send it
@@ -425,6 +493,7 @@ app.get("/api/inventory", function(req, res) {
 		}
 	}
 	res.send(JSON.stringify(inventory));
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 /**
 GET endpoint to read the masters inventory as an object with key:value pairs
@@ -435,10 +504,13 @@ GET endpoint to read the masters inventory as an object with key:value pairs
 @returns {object} JSON {"iron-plate":100, "copper-plate":5}
 */
 app.get("/api/inventoryAsObject", function(req, res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	res.header("Access-Control-Allow-Origin", "*");
 	res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
 	// Check it and send it
 	res.send(JSON.stringify(db.items));
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 
 // post flowstats here for production graphs
@@ -455,6 +527,8 @@ course the timeSeries data.
 @returns {string} failure
 */
 app.post("/api/logStats", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	if(typeof req.body == "object" && req.body.instanceID && req.body.timestamp && req.body.data) {
 		if(Number(req.body.timestamp) != NaN){
 			req.body.timestamp = Number(req.body.timestamp);
@@ -471,6 +545,7 @@ app.post("/api/logStats", function(req,res) {
 	} else {
 		res.send("failure");
 	}
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 // {instanceID: string, fromTime: Date, toTime, Date}
 /**
@@ -484,6 +559,8 @@ graphs and other IO statistics.
 @returns {object} - with statistics
 */
 app.post("/api/getStats", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	if(typeof req.body == "string"){
 		req.body = JSON.parse(req.body);
 	}
@@ -542,6 +619,7 @@ app.post("/api/getStats", function(req,res) {
 			}
 		}
 	}
+	httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 });
 
 /**
@@ -557,6 +635,8 @@ making up about 92% of the response body weight.)
 @returns {object[]} timeseries where each entry is a set point in time.
 */
 app.post("/api/getTimelineStats", function(req,res) {
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
 	console.log(req.body);
 	if(typeof req.body == "object" && req.body.instanceID) {
 		// if not specified, get stats for last 24 hours
@@ -595,6 +675,7 @@ app.post("/api/getTimelineStats", function(req,res) {
 			});
 			
 			res.send(docs);
+			httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
 		});
 	}
 });
@@ -607,9 +688,13 @@ GET endpoint. Returns factorio's base locale as a JSON object.
 @returns {object{}} 2 deep nested object with base game factorio locale as key:value pairs
 */
 app.get("/api/getFactorioLocale", function(req,res){
-	getFactorioLocale.asObject(config.factorioDirectory, "en", (err, factorioLocale) => res.send(factorioLocale));
+	endpointHitCounter.labels(req.route.path).inc();
+	let reqStartTime = Date.now();
+	getFactorioLocale.asObject(config.factorioDirectory, "en", (err, factorioLocale) => {
+		res.send(factorioLocale);
+		httpRequestDurationMilliseconds.labels(req.route.path).observe(Date.now()-reqStartTime);
+	});
 });
-
 var server = require("http").Server(app);
 server.listen(config.masterPort || 8080, function () {
 	console.log("Listening on port %s...", server.address().port);

package.json

@@ -43,6 +43,7 @@
     "needle": "^1.1.0",
     "node-factorio-api": "^0.2.2",
     "node-forge": "^0.7.1",
+    "prom-client": "^10.2.3",
     "request": "^2.83.0",
     "right-pad": "^1.0.1",
     "rmdir-sync": "^1.0.1",