From 62e38199bd98223b1903614db46913e695cfbdc3 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 16:08:13 +0200
Subject: [PATCH 01/20] Rework exit notification for Instances

Pull the exit handler into its own method that's invoked if the startup
fails before the Factorio server is created.  Also move the metrics
clearing to the exit notification method to ensure it's also invoked.
---
 slave.js | 41 +++++++++++++++++++----------------------
 1 file changed, 19 insertions(+), 22 deletions(-)

diff --git a/slave.js b/slave.js
index 8b748680..ce5859e2 100644
--- a/slave.js
+++ b/slave.js
@@ -64,15 +64,25 @@ class Instance extends link.Link{
 		this.server.on("error", err => {
 			console.log(`Error in instance ${this.name}:`, err);
 		});
+	}
 
-		this.server.on("exit", err => {
-			link.messages.instanceStopped.send(this);
+	notifyExit() {
+		link.messages.instanceStopped.send(this);
 
-			// Notify plugins of exit
-			for (let pluginInstance of this.plugins.values()) {
-				pluginInstance.onExit();
+		// Clear metrics this instance is exporting
+		for (let collector of prometheus.defaultRegistry.collectors) {
+			if (
+				collector instanceof prometheus.ValueCollector
+				&& collector.metric.labels.includes('instance_id')
+			) {
+				collector.removeAll({ instance_id: String(this.config.get("instance.id")) });
 			}
-		});
+		}
+
+		// Notify plugins of exit
+		for (let pluginInstance of this.plugins.values()) {
+			pluginInstance.onExit();
+		}
 	}
 
 	async init(pluginInfos, slave) {
@@ -223,6 +233,7 @@ class Instance extends link.Link{
 			console.log("Clusterio | RCON connection established");
 		});
 
+		this.server.on("exit", () => this.notifyExit());
 		await this.server.start(saveName);
 		await this.server.disableAchievements()
 		await this.updateInstanceData();
@@ -254,15 +265,6 @@ class Instance extends link.Link{
 			await this.server.stop();
 		}
 
-		// Clear metrics this instance is exporting
-		for (let collector of prometheus.defaultRegistry.collectors) {
-			if (
-				collector instanceof prometheus.ValueCollector
-				&& collector.metric.labels.includes('instance_id')
-			) {
-				collector.removeAll({ instance_id: String(this.config.get("instance.id")) });
-			}
-		}
 	}
 
 	async getMetricsRequestHandler() {
@@ -300,6 +302,7 @@ class Instance extends link.Link{
 		console.log("Creating save .....");
 		await symlinkMods(this, "sharedMods", console);
 
+		this.server.on("exit", () => this.notifyExit());
 		await this.server.create("world");
 		console.log("Clusterio | Successfully created save");
 	}
@@ -600,13 +603,7 @@ class Slave extends link.Link {
 	async startInstanceRequestHandler(message, request) {
 		let instanceId = message.data.instance_id;
 		let instanceConnection = await this._connectInstance(instanceId);
-		try {
-			return await request.send(instanceConnection, message.data);
-
-		} catch (err) {
-			await this.stopInstance(instanceId);
-			throw err;
-		}
+		return await request.send(instanceConnection, message.data);
 	}
 
 	async createSaveRequestHandler(message, request) {

From 56ee1fe955b0461a48e7029b68f4f5aec2a48f39 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 16:42:27 +0200
Subject: [PATCH 02/20] Rework save logic with regard to start instance

Ensure that notifyExit is called if errors occur during startInstance
and createSave request, and rework startInstance save logic to create
a new savegame if no save is present and allow specifying the save to
load.
---
 README.md            |  6 ++--
 clusterctl.js        |  2 ++
 lib/link/messages.js |  2 +-
 slave.js             | 76 ++++++++++++++++++++++++++++++++++----------
 4 files changed, 64 insertions(+), 22 deletions(-)

diff --git a/README.md b/README.md
index 116f9b94..afdb59cc 100644
--- a/README.md
+++ b/README.md
@@ -243,15 +243,13 @@ The basic operations to start a new instance is the following
 
     node clusterctl create-instance --name "My instance"
     node clusterctl assign-instance --instance "My instance" --slave "Local"
-    node clusterctl create-save --instance "My instance"
     node clusterctl start-instance --instance "My instance"
 
 The first line creates the instance configuration on the master server.
 The second assigns the instance to a slave which creates the instance
 directory and files needed to run the instance on the given slave.  The
-third line creates a new savegame for the instance.  You could also
-upload your own save to the instance directory instead.  And finally the
-fourth line starts the instance.
+third line starts the instance, which creates a new save if there are no
+save games present.
 
 There are many more commands available with clusterctl.  See
 `node clusterctl --help` for a full list of them.
diff --git a/clusterctl.js b/clusterctl.js
index 89a0509a..f3e22c67 100644
--- a/clusterctl.js
+++ b/clusterctl.js
@@ -251,6 +251,7 @@ commands.push(new Command({
 	definition: ['start-instance', "Start instance", (yargs) => {
 		yargs.options({
 			'instance': { describe: "Instance to start", nargs: 1, type: 'string', demandOption: true },
+			'save': { describe: "Save load, defaults to latest", nargs: 1, type: 'string' },
 		});
 	}],
 	handler: async function(args, control) {
@@ -258,6 +259,7 @@ commands.push(new Command({
 		await link.messages.setInstanceOutputSubscriptions.send(control, { instance_ids: [instanceId] });
 		let response = await link.messages.startInstance.send(control, {
 			instance_id: instanceId,
+			save: args.save || null,
 		});
 	},
 }));
diff --git a/lib/link/messages.js b/lib/link/messages.js
index 05305053..dc34b1a0 100644
--- a/lib/link/messages.js
+++ b/lib/link/messages.js
@@ -298,7 +298,7 @@ messages.startInstance = new Request({
 	type: 'start_instance',
 	links: ['control-master', 'master-slave', 'slave-instance'],
 	requestProperties: {
-		"instance_id": { type: "integer" },
+		"save": { type: ["string", "null"] },
 	},
 	forwardTo: 'instance',
 });
diff --git a/slave.js b/slave.js
index ce5859e2..6e466615 100644
--- a/slave.js
+++ b/slave.js
@@ -141,7 +141,6 @@ class Instance extends link.Link{
 	 * @param {String} instanceDir -
 	 *     Directory to create the new instance into.
 	 * @param {String} factorioDir - Path to factorio installation.
-	 * @param {Object} options - Options for new instance.
 	 */
 	static async create(instanceConfig, instanceDir, factorioDir) {
 		console.log(`Clusterio | Creating ${instanceDir}`);
@@ -150,7 +149,18 @@ class Instance extends link.Link{
 		await fs.ensureDir(path.join(instanceDir, "saves"));
 	}
 
-	async start(saveName, slaveConfig, socket) {
+	/**
+	 * Prepare a save for starting
+	 *
+	 * Writes server settings, links mods, creates a new save if no save is
+	 * passed, and patches it with modules.
+	 *
+	 * @param {String|null} saveName -
+	 *     Save to prepare from the instance saves directory.  Creates a new
+	 *     save if null.
+	 * @returns {String} Name of the save prepared.
+	 */
+	async prepare(saveName) {
 		console.log("Clusterio | Writing server-settings.json");
 		await this.writeServerSettings();
 
@@ -168,6 +178,20 @@ class Instance extends link.Link{
 
 		await symlinkMods(this, "sharedMods", console);
 
+		// Use latest save if no save was specified
+		if (saveName === null) {
+			saveName = await fileOps.getNewestFile(
+				this.path("saves"), (name) => !name.endsWith('.tmp.zip')
+			);
+		}
+
+		// Create save if no save was found.
+		if (saveName === null) {
+			console.log("Clusterio | Creating new save")
+			await this.server.create("world.zip");
+			saveName = "world.zip";
+		}
+
 		// Patch save with lua modules from plugins
 		console.log("Clusterio | Patching save");
 
@@ -228,7 +252,17 @@ class Instance extends link.Link{
 		}
 
 		await factorio.patch(this.path("saves", saveName), [...modules.values()]);
+		return saveName;
+	}
 
+	/**
+	 * Start Factorio server
+	 *
+	 * Launches the Factorio server for this instance with the given save.
+	 *
+	 * @param {String} saveName - Name of save game to load.
+	 */
+	async start(saveName) {
 		this.server.on('rcon-ready', () => {
 			console.log("Clusterio | RCON connection established");
 		});
@@ -264,7 +298,6 @@ class Instance extends link.Link{
 
 			await this.server.stop();
 		}
-
 	}
 
 	async getMetricsRequestHandler() {
@@ -281,26 +314,35 @@ class Instance extends link.Link{
 		return { results };
 	}
 
-	async startInstanceRequestHandler() {
-		// Find save to start
-		let latestSave = await fileOps.getNewestFile(
-			this.path("saves"), (name) => !name.endsWith('.tmp.zip')
-		);
-		if (latestSave === null) {
-			throw new errors.RequestError(
-				"No savefile was found to start the instance with."
-			);
+	async startInstanceRequestHandler(message) {
+		let saveName = message.data.save;
+		try {
+			saveName = await this.prepare(saveName)
+		} catch (err) {
+			this.notifyExit();
+			throw err;
 		}
 
-		await this.start(latestSave, this.config, this.socket);
+		try {
+			await this.start(saveName, this.config, this.socket);
+		} catch (err) {
+			await this.stop();
+			throw err;
+		}
 	}
 
 	async createSaveRequestHandler() {
-		console.log("Clusterio | Writing server-settings.json");
-		await this.writeServerSettings();
+		try {
+			console.log("Clusterio | Writing server-settings.json");
+			await this.writeServerSettings();
 
-		console.log("Creating save .....");
-		await symlinkMods(this, "sharedMods", console);
+			console.log("Creating save .....");
+			await symlinkMods(this, "sharedMods", console);
+
+		} catch (err) {
+			this.notifyExit();
+			throw err;
+		}
 
 		this.server.on("exit", () => this.notifyExit());
 		await this.server.create("world");

From 6bc07ad1b3ce9c304ac371c2bfb53ecfa9fc6079 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 17:03:19 +0200
Subject: [PATCH 03/20] Add Factorio CPU and Memory usage statistics

Add per instance metrics for CPU and memory usage with the pidusage
library.
---
 CHANGELOG.md           |  1 +
 lib/factorio/server.js | 10 ++++++++++
 package.json           |  1 +
 slave.js               | 23 +++++++++++++++++++++++
 4 files changed, 35 insertions(+)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index b5bbfb88..19f2d8c4 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -37,6 +37,7 @@ Version 2.0.0
   allowing it to be proxied behind web-server.
 - Added WebSocket usage statistics.
 - Added commands sent statistic.
+- Added Factorio server CPU and memory usage statistic.
 
 ### Changes
 
diff --git a/lib/factorio/server.js b/lib/factorio/server.js
index 0a765ddc..e8414fac 100644
--- a/lib/factorio/server.js
+++ b/lib/factorio/server.js
@@ -590,6 +590,16 @@ class FactorioServer extends events.EventEmitter {
 		return this._version;
 	}
 
+	/**
+	 * The pid of the server process, or null if not running
+	 */
+	get pid() {
+		if (!this._server) {
+			return null;
+		}
+		return this._server.pid;
+	}
+
 	_attachStdio() {
 		this._server.stdout.on('data', chunk => { this._stdout.data(chunk); });
 		this._server.stdout.on('close', () => { this._stdout.end(); });
diff --git a/package.json b/package.json
index 8646ff7b..b0693d9a 100644
--- a/package.json
+++ b/package.json
@@ -54,6 +54,7 @@
     "needle": "^2.4.0",
     "node-factorio-api": "^0.3.8",
     "node-forge": "^0.7.1",
+    "pidusage": "^2.0.18",
     "rcon-client": "^4.2.0",
     "request": "^2.83.0",
     "sanitizer": "^0.1.3",
diff --git a/slave.js b/slave.js
index 6e466615..7aee2935 100644
--- a/slave.js
+++ b/slave.js
@@ -2,6 +2,7 @@ const fs = require('fs-extra');
 const path = require('path');
 const yargs = require("yargs");
 const events = require("events");
+const pidusage = require("pidusage");
 const version = require("./package").version;
 
 // internal libraries
@@ -22,6 +23,18 @@ const instanceRconCommandsCounter = new prometheus.Counter(
 	{ labels: ["instance_id"] }
 );
 
+const instanceFactorioCpuTime = new prometheus.Gauge(
+	"clusterio_instance_factorio_cpu_time_total",
+	"Factorio CPU time spent in seconds.",
+	{ labels: ["instance_id"] }
+);
+
+const instanceFactorioMemoryUsage = new prometheus.Gauge(
+	"clusterio_instance_factorio_resident_memory_bytes",
+	"Factorio resident memory size in bytes.",
+	{ labels: ["instance_id"] }
+);
+
 /**
  * Keeps track of the runtime parameters of an instance
  */
@@ -311,6 +324,13 @@ class Instance extends link.Link{
 			}
 		}
 
+		let pid = this.server.pid;
+		if (pid) {
+			let stats = await pidusage(pid);
+			instanceFactorioCpuTime.labels(String(this.config.get("instance.id"))).set(stats.ctime / 1000);
+			instanceFactorioMemoryUsage.labels(String(this.config.get("instance.id"))).set(stats.memory);
+		}
+
 		return { results };
 	}
 
@@ -702,6 +722,9 @@ class Slave extends link.Link {
 		}
 		this.connector.close(1001, "Slave Shutdown");
 		await events.once(this.connector, "close");
+
+		// Clear silly interval in pidfile library.
+		pidusage.clear();
 	}
 }
 

From 139585f8c6b9ba8260d575a773e241067655c15e Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 17:04:11 +0200
Subject: [PATCH 04/20] Prevent metrics being called on createSave

Gate the onMetrics plugin hook behind a boolean that's set only after
the Factorio server has fully started, and reset when it stops.  This
prevents errors due to plugins trying to get metrics while the server
is creating a new save or stopped.
---
 slave.js | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/slave.js b/slave.js
index 7aee2935..1d34b0e3 100644
--- a/slave.js
+++ b/slave.js
@@ -54,6 +54,7 @@ class Instance extends link.Link{
 			rconPassword: this.config.get('factorio.rcon_password'),
 		};
 
+		this._running = false;
 		this.server = new factorio.FactorioServer(
 			factorioDir, this._dir, serverOptions
 		);
@@ -80,6 +81,7 @@ class Instance extends link.Link{
 	}
 
 	notifyExit() {
+		this._running = false;
 		link.messages.instanceStopped.send(this);
 
 		// Clear metrics this instance is exporting
@@ -288,6 +290,8 @@ class Instance extends link.Link{
 		for (let pluginInstance of this.plugins.values()) {
 			await pluginInstance.onStart();
 		}
+
+		this._running = true;
 	}
 
 	/**
@@ -303,6 +307,8 @@ class Instance extends link.Link{
 	 * Stop the instance
 	 */
 	async stop() {
+		this._running = false;
+
 		// XXX this needs more thought to it
 		if (this.server._state === "running") {
 			for (let pluginInstance of this.plugins.values()) {
@@ -315,11 +321,13 @@ class Instance extends link.Link{
 
 	async getMetricsRequestHandler() {
 		let results = []
-		for (let pluginInstance of this.plugins.values()) {
-			let pluginResults = await pluginInstance.onMetrics();
-			if (pluginResults !== undefined) {
-				for await (let result of pluginResults) {
-					results.push(prometheus.serializeResult(result))
+		if (this._running) {
+			for (let pluginInstance of this.plugins.values()) {
+				let pluginResults = await pluginInstance.onMetrics();
+				if (pluginResults !== undefined) {
+					for await (let result of pluginResults) {
+						results.push(prometheus.serializeResult(result))
+					}
 				}
 			}
 		}

From e908c5069b891d550a0334fe2efe04c9a127884f Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 18:56:21 +0200
Subject: [PATCH 05/20] Add autosave tracking and statistics

Detect when autosaves are made and track the size in a Prometheus gague.
---
 CHANGELOG.md               |  1 +
 lib/factorio/server.js     | 29 +++++++++++++++++++++++++++++
 slave.js                   | 17 +++++++++++++++++
 test/lib/factorio/lines.js | 22 ++++++++++++++++++++++
 4 files changed, 69 insertions(+)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 19f2d8c4..59365897 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -38,6 +38,7 @@ Version 2.0.0
 - Added WebSocket usage statistics.
 - Added commands sent statistic.
 - Added Factorio server CPU and memory usage statistic.
+- Added Factorio autosave size statistic.
 
 ### Changes
 
diff --git a/lib/factorio/server.js b/lib/factorio/server.js
index e8414fac..8f7a6540 100644
--- a/lib/factorio/server.js
+++ b/lib/factorio/server.js
@@ -349,6 +349,18 @@ const outputHeuristics = [
 		}
 	},
 
+	// Message indicating the server has started an autosave
+	{
+		filter: {
+			type: 'log',
+			message: /^Saving to _autosave\d+ \((non-)?blocking\)\.$/,
+		},
+		action: function(output) {
+			let name = /^Saving to (_autosave\d+) /.exec(output.message)[1];
+			this.emit('_autosave', name);
+		},
+	},
+
 	// Message indicating the server has finished saving
 	{
 		filter: {
@@ -419,6 +431,8 @@ const outputHeuristics = [
  * output - invoked with parsed output from Factorio
  * rcon-ready - invoked when the RCON client has connected
  * game-ready - invoked when the server is finished starting up
+ * autosave-start - invoked when the server starts an autosave
+ * autosave-fnished - invoked when the autosave finished
  * exit - invoked when the sterver has exited
  */
 class FactorioServer extends events.EventEmitter {
@@ -454,6 +468,20 @@ class FactorioServer extends events.EventEmitter {
 
 		this._stdout = new LineSplitter((line) => { this._handleOutput(line, 'stdout'); });
 		this._stderr = new LineSplitter((line) => { this._handleOutput(line, 'stderr'); });
+
+		// Track autosaving
+		this._runningAutosave = null;
+		this.on("_autosave", function(name) {
+			this.emit("autosave-start", name);
+			this._runningAutosave = name;
+		})
+
+		this.on("_saved", function() {
+			if (this._runningAutosave) {
+				this.emit("autosave-finished", this._runningAutosave);
+				this._runningAutosave = null;
+			}
+		})
 	}
 
 	_check(expectedStates) {
@@ -645,6 +673,7 @@ class FactorioServer extends events.EventEmitter {
 			this._rconReady = false;
 			this._gameReady = false;
 			this._unexpected = [];
+			this._runningAutosave = null;
 
 			this.emit("exit");
 		});
diff --git a/slave.js b/slave.js
index 1d34b0e3..ce9adfc3 100644
--- a/slave.js
+++ b/slave.js
@@ -35,6 +35,12 @@ const instanceFactorioMemoryUsage = new prometheus.Gauge(
 	{ labels: ["instance_id"] }
 );
 
+const instanceFactorioAutosaveSize = new prometheus.Gauge(
+	"clusterio_instance_factorio_autosave_bytes",
+	"Size of Factorio server autosave in bytes.",
+	{ labels: ["instance_id"] }
+);
+
 /**
  * Keeps track of the runtime parameters of an instance
  */
@@ -78,6 +84,17 @@ class Instance extends link.Link{
 		this.server.on("error", err => {
 			console.log(`Error in instance ${this.name}:`, err);
 		});
+
+		this.server.on("autosave-finished", name => {
+			this._autosave(name).catch(err => {
+				console.error("Error handling autosave-finished:", err);
+			});
+		});
+	}
+
+	async _autosave(name) {
+		let stat = await fs.stat(this.path("saves", `${name}.zip`));
+		instanceFactorioAutosaveSize.labels(String(this.config.get("instance.id"))).set(stat.size);
 	}
 
 	notifyExit() {
diff --git a/test/lib/factorio/lines.js b/test/lib/factorio/lines.js
index eb6159ba..2e316ac0 100644
--- a/test/lib/factorio/lines.js
+++ b/test/lib/factorio/lines.js
@@ -109,6 +109,28 @@ let testLines = new Map([
 			message: "Error while running event level::on_nth_tick(1)",
 		}
 	],
+	[
+		"4802.763 Info AppManager.cpp:287: Saving to _autosave4 (blocking).",
+		{
+			format: "seconds",
+			time: "4802.763",
+			type: "log",
+			level: "Info",
+			file: "AppManager.cpp:287",
+			message: "Saving to _autosave4 (blocking).",
+		}
+	],
+	[
+		"4202.780 Info AppManagerStates.cpp:1802: Saving finished",
+		{
+			format: "seconds",
+			time: "4202.780",
+			type: "log",
+			level: "Info",
+			file: "AppManagerStates.cpp:1802",
+			message: "Saving finished",
+		}
+	],
 ])
 
 module.exports = {

From 56488b2c2d1bf89975886711e9549492314ab020 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 18:58:52 +0200
Subject: [PATCH 06/20] Add resident memory and heap size metrics

Implement the default resident memory and heap size metrics.
---
 lib/prometheus.js      | 20 ++++++++++++++++++++
 test/lib/prometheus.js | 40 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 60 insertions(+)

diff --git a/lib/prometheus.js b/lib/prometheus.js
index 2f1386c8..ce0cf0be 100644
--- a/lib/prometheus.js
+++ b/lib/prometheus.js
@@ -409,6 +409,26 @@ defaultCollectors.processCpuSecondsTotal = new Gauge(
 	},
 );
 
+defaultCollectors.processResidentMemoryBytes = new Gauge(
+	'process_resident_memory_bytes',
+	"Resident memory size in bytes.",
+	{
+		callback: function() {
+			this.set(process.memoryUsage().rss);
+		},
+	},
+);
+
+defaultCollectors.processHeapBytes = new Gauge(
+	'process_heap_bytes',
+	"Process heap size in bytes.",
+	{
+		callback: function() {
+			this.set(process.memoryUsage().heapUsed);
+		},
+	},
+);
+
 defaultCollectors.processStartTimeSeconds = new Gauge(
 	'process_start_time_seconds',
 	"Start time of the process since unix epoch in seconds."
diff --git a/test/lib/prometheus.js b/test/lib/prometheus.js
index afecec92..9ea6fb3f 100644
--- a/test/lib/prometheus.js
+++ b/test/lib/prometheus.js
@@ -419,6 +419,46 @@ describe("lib/prometheus", function() {
 				);
 			});
 		});
+		describe("processResidentMemoryBytes", function() {
+			it("should give a low value", async function() {
+				let results = []
+				let collector = prometheus.defaultCollectors.processResidentMemoryBytes;
+				for await (let result of collector.collect()) {
+					results.push(result);
+				}
+
+				assert(
+					results.length == 1,
+					"collector did not give exactly one result"
+				);
+
+				let value = results[0].samples.get('')
+				assert(
+					value < 200e6 && value > 0,
+					`resident memory is not between 0 and 200 MB (${value})`
+				);
+			});
+		});
+		describe("processHeapBytes", function() {
+			it("should give a low value", async function() {
+				let results = []
+				let collector = prometheus.defaultCollectors.processHeapBytes;
+				for await (let result of collector.collect()) {
+					results.push(result);
+				}
+
+				assert(
+					results.length == 1,
+					"collector did not give exactly one result"
+				);
+
+				let value = results[0].samples.get('')
+				assert(
+					value < 200e6 && value > 0,
+					`heap is not between 0 and 200 MB (${value})`
+				);
+			});
+		});
 	});
 
 	describe("exposition()", function() {

From 47c221f6f3bb2a8b39db7bb416cffb5b3398185c Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 18:59:42 +0200
Subject: [PATCH 07/20] Fix typo in test names

Fix the labels function being refered to as the label function in the
test descriptions.
---
 test/lib/prometheus.js | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/test/lib/prometheus.js b/test/lib/prometheus.js
index 9ea6fb3f..28da621b 100644
--- a/test/lib/prometheus.js
+++ b/test/lib/prometheus.js
@@ -312,7 +312,7 @@ describe("lib/prometheus", function() {
 			});
 		});
 		describe(".remove()", function() {
-			it("should remove a label set created with .label()", function() {
+			it("should remove a label set created with .labels()", function() {
 				let gauge = new prometheus.Gauge(
 					'test', "Help", { register: false, labels: ['a', 'b'] }
 				);
@@ -328,7 +328,7 @@ describe("lib/prometheus", function() {
 			});
 		});
 		describe(".removeAll()", function() {
-			it("should remove a label set created with .label()", function() {
+			it("should remove a label set created with .labels()", function() {
 				let gauge = new prometheus.Gauge(
 					'test', "Help", { register: false, labels: ['a', 'b'] }
 				);
@@ -358,7 +358,7 @@ describe("lib/prometheus", function() {
 			});
 		});
 		describe(".clear()", function() {
-			it("should remove all label sets created with .label()", function() {
+			it("should remove all label sets created with .labels()", function() {
 				let gauge = new prometheus.Gauge(
 					'test', "Help", { register: false, labels: ['a', 'b'] }
 				);

From d537e5cf6b3482aab187ed944f2ad86794147b89 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 19:04:08 +0200
Subject: [PATCH 08/20] Fix typo in default cpu metric

Fix proces_cpu_seconds_total being mislabled as process_cpu_seconds.
---
 lib/prometheus.js | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/lib/prometheus.js b/lib/prometheus.js
index ce0cf0be..8913f52a 100644
--- a/lib/prometheus.js
+++ b/lib/prometheus.js
@@ -400,7 +400,8 @@ function deserializeResult(serializedResult) {
 
 let defaultCollectors = {};
 defaultCollectors.processCpuSecondsTotal = new Gauge(
-	'process_cpu_seconds', "Total user and system CPU time spent in seconds.",
+	'process_cpu_seconds_total',
+	"Total user and system CPU time spent in seconds.",
 	{
 		callback: async function() {
 			let usage = process.cpuUsage();

From 59111cc8442f60246f4b197e9387c0934751b147 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 19:05:18 +0200
Subject: [PATCH 09/20] Disable replay in patched save

Ensure that the replay is disabled after the game is patched by calling
game.disable_replay().  It's not possible to replay a patched save, and
it also stores every command sent into save, causing it to quickly grow
into an unplayably large size.
---
 modules/clusterio/impl.lua | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/modules/clusterio/impl.lua b/modules/clusterio/impl.lua
index 3ae9593f..52303963 100644
--- a/modules/clusterio/impl.lua
+++ b/modules/clusterio/impl.lua
@@ -18,6 +18,9 @@ impl.events[api.events.on_server_startup] = function()
             instance_name = nil,
         }
     end
+
+    -- Replay will just desync after the save is patched
+    game.disable_replay()
 end
 
 -- Internal API

From 3dc4bdaab636d843413015aea2beb931e7179f3f Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 19:12:53 +0200
Subject: [PATCH 10/20] Remove debug log

Remove debug log statement annoing events have been broadcast.
---
 slave.js | 1 -
 1 file changed, 1 deletion(-)

diff --git a/slave.js b/slave.js
index ce9adfc3..0940fb6c 100644
--- a/slave.js
+++ b/slave.js
@@ -503,7 +503,6 @@ class InstanceConnection extends link.Link {
 				continue; // Do not broadcast back to the source
 			}
 
-			console.log("Broadcasting event");
 			event.send(instanceConnection, message.data);
 		}
 	}

From fc04fd9ebc26e80a4d3e30386cba615d71e1cd5b Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 20:50:32 +0200
Subject: [PATCH 11/20] Remove master branch warning

Remove warning of master branch being broken now that it's no longer
completely broken.
---
 README.md | 2 --
 1 file changed, 2 deletions(-)

diff --git a/README.md b/README.md
index afdb59cc..9298a408 100644
--- a/README.md
+++ b/README.md
@@ -10,8 +10,6 @@ Discord for development/support/play: https://discord.gg/5XuDkje
 
 ## Important notice
 
-**WARNING: The master branch is currently broken, do not use it!**
-
 This is the development branch for factorioClusterio 2.0 which is currently undergoing heavy
 restructuring and refactoring.  Expect plugins and existing installations to frequently break when
 using this branch.  If you don't want to be an alpha tester for 2.0 please use the stable

From e7d1039942b9abbd2ff51dfbc5f07de38fc23d38 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Mon, 6 Apr 2020 20:52:58 +0200
Subject: [PATCH 12/20] Link to writings plugins document in docs

Replace notice about in development plugin interface with a link to the
writing plugins document in the developing for clusterio document.
---
 docs/developing-for-clusterio.md | 6 ++----
 1 file changed, 2 insertions(+), 4 deletions(-)

diff --git a/docs/developing-for-clusterio.md b/docs/developing-for-clusterio.md
index 5e2273fe..24734fc2 100644
--- a/docs/developing-for-clusterio.md
+++ b/docs/developing-for-clusterio.md
@@ -383,7 +383,5 @@ inventory.
 Clusterio Plugins
 -----------------
 
-The plugin interface is undergoing a major rewrite, and will be
-documented once that is done.  See
-[issue #220](https://github.com/clusterio/factorioClusterio/issues/220)
-for details.
+See the [Writing Plugins](writing-plugins.md) document for details on
+the plugin interface and how to write plugins for Clusterio.

From 47ea8f5477618e658c08d1b4ce6899b062277f7c Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Wed, 8 Apr 2020 21:51:12 +0200
Subject: [PATCH 13/20] Rename connection shutdown to prepare disconnect

Rename the shutdownConnection request to prepareDisconnect to better
reflect its actual purpose.
---
 clusterctl.js            |  2 +-
 docs/socket.md           | 19 ++++++++++---------
 lib/link/link.js         |  4 ++--
 lib/link/messages.js     |  4 ++--
 master.js                |  2 +-
 slave.js                 |  2 +-
 test/integration/link.js |  2 +-
 7 files changed, 18 insertions(+), 17 deletions(-)

diff --git a/clusterctl.js b/clusterctl.js
index f3e22c67..79d9a6b9 100644
--- a/clusterctl.js
+++ b/clusterctl.js
@@ -353,7 +353,7 @@ class Control extends link.Link {
 	}
 
 	async shutdown() {
-		await link.messages.shutdownConnection.send(this);
+		await link.messages.prepareDisconnect.send(this);
 		this.connector.close(1001, "Control Quit")
 		await events.once(this.connector, "close");
 	}
diff --git a/docs/socket.md b/docs/socket.md
index 597ef535..87d4718a 100644
--- a/docs/socket.md
+++ b/docs/socket.md
@@ -253,28 +253,29 @@ requests and their contents.
 - error - string - Human readable text message describing the error.
 
 
-Graceful shutdown
------------------
+Graceful Disconnect
+-------------------
 
 To ensure no data is lost when closing the link it's important to
-send connection shutdown request and wait for it to complete before
+send a prepare disconnect request and wait for it to complete before
 closing the WebSocket.  Either party of the link can send this request
 and the party sending the request should be the one that initates the
 close of the WebSocket.
 
-### `connection_shutdown_request`
+### `prepare_disconnect_request`
 
-Request graceful shutdown of the connection.  The receiving party should
+Request graceful disconnect of the connection.  The receiving party should
 stop tasks that send events and requests over the link and wait for
 pending requests it has over the link to complete, but it should not
 stop responding to requests sent to it.  Only after this process is done
 should the response be sent.
 
-### `connection_shutdown_response`
+### `prepare_disconnect_response`
 
-Signals the shutdown is complete and that the connection can be closed.
-The party that initiatied the shutdown request may still send other
-requests/events over the link to finish its part of the shutdown.
+Signals the preparation for disconnect is complete and that the
+connection can be closed.  The party that initiatied the prepare
+disconnect request may still send other requests/events over the link to
+finish its part of the disconnection proceedure.
 
 If the error response variant is received it should be logged if
 possible and treated as a success.
diff --git a/lib/link/link.js b/lib/link/link.js
index 20377652..f55087ba 100644
--- a/lib/link/link.js
+++ b/lib/link/link.js
@@ -208,14 +208,14 @@ class Link {
 	async pingRequestHandler() { }
 
 	/**
-	 * Prepare connection for close
+	 * Prepare connection for disconnect
 	 *
 	 * Waits for all pending requests on the connection to resolve.
 	 * Sub-classes should implement this handler with code that prevents
 	 * additional requests to be sent out before calling the super class
 	 * method.
 	 */
-	async shutdownConnectionRequestHandler() {
+	async prepareDisconnectRequestHandler() {
 		let promises = [];
 		for (let waiterType of this._waiters.values()) {
 			for (let waiter of waiterType) {
diff --git a/lib/link/messages.js b/lib/link/messages.js
index dc34b1a0..97044ced 100644
--- a/lib/link/messages.js
+++ b/lib/link/messages.js
@@ -185,8 +185,8 @@ let messages = {}
 
 // Connection requests
 let wsLinks = ["master-control", "control-master", "master-slave", "slave-master"];
-messages.shutdownConnection = new Request({
-	type: "shutdown_connection",
+messages.prepareDisconnect = new Request({
+	type: "prepare_disconnect",
 	links: wsLinks,
 });
 
diff --git a/master.js b/master.js
index 876d9bac..62381061 100644
--- a/master.js
+++ b/master.js
@@ -381,7 +381,7 @@ class BaseConnection extends link.Link {
 	}
 
 	async shutdown(code, reason) {
-		await link.messages.shutdownConnection.send(this);
+		await link.messages.prepareDisconnect.send(this);
 		this.connector.close(code, reason);
 		await events.once(this.connector, "close");
 	}
diff --git a/slave.js b/slave.js
index 0940fb6c..18ed831c 100644
--- a/slave.js
+++ b/slave.js
@@ -740,7 +740,7 @@ class Slave extends link.Link {
 	}
 
 	async shutdown() {
-		await link.messages.shutdownConnection.send(this);
+		await link.messages.prepareDisconnect.send(this);
 		for (let instanceId of this.instanceConnections.keys()) {
 			await this.stopInstance(instanceId);
 		}
diff --git a/test/integration/link.js b/test/integration/link.js
index f1b1dba5..d684b09e 100644
--- a/test/integration/link.js
+++ b/test/integration/link.js
@@ -12,7 +12,7 @@ class TestControl extends link.Link {
 		link.attachAllMessages(this);
 	}
 
-	async shutdownConnectionRequestHandler() { }
+	async prepareDisconnectRequestHandler() { }
 	async instanceOutputEventHandler() { }
 }
 

From 9507608e595c04715a58429d98356211fca7d613 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 15:05:08 +0200
Subject: [PATCH 14/20] Rework disconnect logic for connectors

Rework the way disconnection at shutdown is done to properly close
the connections when the master server is shut down.
---
 clusterctl.js             |  24 ++++++--
 lib/config/definitions.js |   7 +++
 lib/errors.js             |   4 ++
 lib/link/connectors.js    |  40 ++++++++++---
 lib/link/link.js          |   3 +-
 master.js                 | 116 +++++++++++++++++++++++++++++---------
 slave.js                  |  18 +++++-
 test/integration/index.js |   6 ++
 8 files changed, 174 insertions(+), 44 deletions(-)

diff --git a/clusterctl.js b/clusterctl.js
index 79d9a6b9..472548ba 100644
--- a/clusterctl.js
+++ b/clusterctl.js
@@ -353,9 +353,17 @@ class Control extends link.Link {
 	}
 
 	async shutdown() {
-		await link.messages.prepareDisconnect.send(this);
-		this.connector.close(1001, "Control Quit")
-		await events.once(this.connector, "close");
+		this.connector.setTimeout(30);
+
+		try {
+			await link.messages.prepareDisconnect.send(this);
+		} catch (err) {
+			if (!(err instanceof SessionLost)) {
+				throw err;
+			}
+		}
+
+		await this.connector.close(1001, "Control Quit")
 	}
 }
 
@@ -501,6 +509,14 @@ async function startControl() {
 		throw err;
 	}
 
+	process.on("SIGINT", () => {
+		console.log("Caught interrupt signal, closing connection");
+		control.shutdown().catch(err => {
+			console.error(err);
+			process.exit(1);
+		});
+	});
+
 	if (commands.has(commandName)) {
 		command = commands.get(commandName);
 
@@ -524,8 +540,6 @@ async function startControl() {
 			await control.shutdown();
 		}
 	}
-
-	//XXX control.close("done");
 }
 
 module.exports = {
diff --git a/lib/config/definitions.js b/lib/config/definitions.js
index 95f3f737..98f36847 100644
--- a/lib/config/definitions.js
+++ b/lib/config/definitions.js
@@ -87,6 +87,13 @@ MasterGroup.define({
 	type: "number",
 	initial_value: 60,
 });
+MasterGroup.define({
+	name: "connector_shutdown_timeout",
+	title: "Connector Shutdown Timeout",
+	description: "Timeout in seconds for connectors to properly disconnect on shutdown",
+	type: "number",
+	initial_value: 30,
+});
 MasterGroup.finalize();
 
 class MasterConfig extends classes.Config { }
diff --git a/lib/errors.js b/lib/errors.js
index 2945d13d..19c9d27f 100644
--- a/lib/errors.js
+++ b/lib/errors.js
@@ -14,6 +14,9 @@ class InvalidMessage extends Error {
 	}
 }
 
+// Thrown from requests when the session it was sent on was lost.
+class SessionLost extends Error { }
+
 // Thrown when WebSocket authentication failed
 class AuthenticationFailed extends Error { }
 
@@ -36,6 +39,7 @@ module.exports = {
 	CommandError,
 	RequestError,
 	InvalidMessage,
+	SessionLost,
 	AuthenticationFailed,
 	StartupError,
 	EnvironmentError,
diff --git a/lib/link/connectors.js b/lib/link/connectors.js
index 276d2922..2b94c0e5 100644
--- a/lib/link/connectors.js
+++ b/lib/link/connectors.js
@@ -129,6 +129,8 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 		this._sessionToken = null;
 		this._connected = false;
 		this._reconnectDelay = reconnectDelay;
+		this._timeout = 15 * 60;
+		this._startedReconnect = null;
 	}
 
 	_check(expectedStates) {
@@ -139,6 +141,15 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 		}
 	}
 
+	setTimeout(timeout) {
+		this._timeout = timeout;
+
+		if (this._reconnectId && this.timeout < this._reconnectDelay / 2) {
+			clearTimeout(this._reconnectId);
+			this.reconnect();
+		}
+	}
+
 	/**
 	 * Send a handshake message over the socket
 	 *
@@ -155,7 +166,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 	 *
 	 * Sends a close frame and disconnects the connector.
 	 */
-	close(code, reason) {
+	async close(code, reason) {
 		if (this._state === "new") {
 			return;
 		}
@@ -168,6 +179,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 		this.stopHeartbeat();
 		this._state = "closing";
 		this._socket.close(code, reason);
+		await events.once(this, "close");
 	}
 
 	/**
@@ -207,6 +219,24 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 			return;
 		}
 
+		if (this._startedReconnect === null) {
+			this._startedReconnect = Date.now();
+		}
+
+		if (this._startedReconnect + this._timeout * 1000 < Date.now()) {
+			console.log("SOCKET | Timed out trying to reconnect");
+			this._heartbeatInterval = null;
+			this._lastReceivedSeq = null;
+			this._sessionToken = null;
+			this._sendBuffer.length = 0;
+			if (this._connected) {
+				this._connected = false;
+				this.emit("close");
+			}
+			this.emit("invalidate");
+			return;
+		}
+
 		let delay = Math.random() * this._reconnectDelay;
 		console.log(`SOCKET | waiting ${delay.toLocaleString("en", { maximumFractionDigits: 2 })} seconds for reconnect`)
 		this._reconnectId = setTimeout(() => {
@@ -231,18 +261,14 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 				this._state = "new";
 
 				if (this._connected) {
-					this.emit("close");
 					this._connected = false;
+					this.emit("close");
 				}
 
 			} else {
 				this._state = "handshake";
 				this.reconnect();
-
-				if (this._connected) {
-					this.emit("dropped");
-					this._connected = false;
-				}
+				this.emit("dropped");
 			}
 
 			this.stopHeartbeat();
diff --git a/lib/link/link.js b/lib/link/link.js
index f55087ba..d36d8b56 100644
--- a/lib/link/link.js
+++ b/lib/link/link.js
@@ -45,7 +45,7 @@ class Link {
 		connector.on("invalidate", () => {
 			for (let waiterType of this._waiters.values()) {
 				for (let waiter of waiterType) {
-					waiter.reject(new Error("Session lost"));
+					waiter.reject(new errors.SessionLost("Session Lost"));
 				}
 			}
 
@@ -224,7 +224,6 @@ class Link {
 		}
 
 		await Promise.all(promises);
-		this.connector.setClosing();
 	}
 }
 
diff --git a/master.js b/master.js
index 62381061..af859fdb 100644
--- a/master.js
+++ b/master.js
@@ -29,6 +29,7 @@ const version = require("./package").version;
 // ugly globals
 let masterConfig;
 let masterConfigPath;
+let stopAcceptingNewSessions = false;
 
 // homebrew modules
 const generateSSLcert = require("lib/generateSSLcert");
@@ -253,27 +254,40 @@ async function shutdown() {
 			console.log(`Plugin ${pluginName} exited in ${Date.now() - startTime}ms`);
 		}
 
+		stopAcceptingNewSessions = true;
+
+		let disconnectTasks = [];
 		for (let controlConnection of controlConnections) {
-			controlConnection.connector.close(1001, "Server Quit");
+			controlConnection.connector.setTimeout(masterConfig.get("master.connector_shutdown_timeout"));
+			disconnectTasks.push(controlConnection.disconnect(1001, "Server Quit"));
 		}
 
 		for (let slaveConnection of slaveConnections.values()) {
-			slaveConnection.connector.close(1001, "Server Quit");
+			slaveConnection.connector.setTimeout(masterConfig.get("master.connector_shutdown_timeout"));
+			disconnectTasks.push(slaveConnection.disconnect(1001, "Server Quit"));
+		}
+
+		console.log(`Waiting for ${disconnectTasks.length} connectors to close`);
+		for (let task of disconnectTasks) {
+			try {
+				await task;
+			} catch (err) {
+				if (!(err instanceof errors.SessionLost)) {
+					console.log("Unexpected error disconnecting connector");
+					console.log(err);
+				}
+			}
 		}
 
 		for (let socket of pendingSockets) {
 			socket.close(1001, "Server Quit");
 		}
 
-		if (httpServer) {
-			console.log("Stopping HTTP server");
-			await new Promise(resolve => httpServer.close(resolve));
-		}
-
-		if (httpsServer) {
-			console.log("Stopping HTTPS server");
-			await new Promise(resolve => httpsServer.close(resolve));
-		}
+		let stopTasks = [];
+		console.log("Stopping HTTP(S) server");
+		if (httpServer) { stopTasks.push(new Promise(resolve => httpServer.close(resolve))); }
+		if (httpsServer) { stopTasks.push(new Promise(resolve => httpsServer.close(resolve))); }
+		await Promise.all(stopTasks);
 
 		console.log(`Clusterio cleanly exited in ${Date.now() - exitStartTime}ms`);
 
@@ -380,10 +394,22 @@ class BaseConnection extends link.Link {
 		}
 	}
 
-	async shutdown(code, reason) {
-		await link.messages.prepareDisconnect.send(this);
-		this.connector.close(code, reason);
-		await events.once(this.connector, "close");
+	async prepareDisconnectRequestHandler(message, request) {
+		this.connector.setClosing();
+		return await super.prepareDisconnectRequestHandler(message, request);
+	}
+
+	async disconnect(code, reason) {
+		try {
+			await link.messages.prepareDisconnect.send(this);
+		} catch (err) {
+			if (!(err instanceof errors.SessionLost)) {
+				console.error("Unexpected error preparing disconnect");
+				console.error(err);
+			}
+		}
+
+		await this.connector.close(code, reason);
 	}
 }
 
@@ -617,12 +643,13 @@ class WebSocketServerConnector extends link.WebSocketBaseConnector {
 		this._sessionId = sessionId;
 
 		// The following states are used in the server connector
-		// handshake: Wating for client to (re)connect.
+		// handshake: Waiting for client to (re)connect.
 		// connected: Connection is online
 		// closing: Connection is in the process of being closed.
 		// closed: Connection has been closed
 		this._state = "handshake";
 		this._connected = false;
+		this._timeout = 15 * 60;
 	}
 
 	_check(expectedStates) {
@@ -665,6 +692,11 @@ class WebSocketServerConnector extends link.WebSocketBaseConnector {
 		this._socket.terminate();
 		this._socket = socket;
 
+		if (this._timeoutId) {
+			clearTimeout(this._timeoutId);
+			this._timeoutId = null;
+		}
+
 		this._heartbeatInterval = masterConfig.get("master.heartbeat_interval")
 		this._socket.send(JSON.stringify({
 			seq: null,
@@ -685,6 +717,26 @@ class WebSocketServerConnector extends link.WebSocketBaseConnector {
 		this.emit("connected");
 	}
 
+	setTimeout(timeout) {
+		if (this._timeoutId) {
+			clearTimeout(this._timeoutId);
+		}
+
+		this._timeoutId = setTimeout(() => { this._timedOut() }, timeout * 1000);
+		this._timeout = timeout;
+	}
+
+	_timedOut() {
+		console.log("SOCKET | Connection timed out");
+		this._timeoutId = null;
+		this._lastReceivedSeq = null;
+		this._sendBuffer.length = 0;
+		this._state = "closed";
+		activeConnectors.delete(this._sessionId);
+		this.emit("close");
+		this.emit("invalidate");
+	}
+
 	_attachSocketHandlers() {
 		this.startHeartbeat();
 
@@ -697,17 +749,19 @@ class WebSocketServerConnector extends link.WebSocketBaseConnector {
 				activeConnectors.delete(this._sessionId);
 
 				if (this._connected) {
-					this.emit("close");
 					this._connected = false;
+					this.emit("close");
+				}
+
+				if (this._timeoutId) {
+					clearTimeout(this._timeoutId);
+					this._timeoutId = null;
 				}
 
 			} else {
 				this._state = "handshake";
-
-				if (this._connected) {
-					this.emit("dropped");
-					this._connected = false;
-				}
+				this.emit("dropped");
+				this._timeoutId = setTimeout(() => { this._timedOut() }, this._timeout * 1000);
 			}
 
 			this.stopHeartbeat();
@@ -754,14 +808,15 @@ class WebSocketServerConnector extends link.WebSocketBaseConnector {
 	 *
 	 * Sends a close frame and disconnects the connector.
 	 */
-	close(code, reason) {
-		if (this._state === "new") {
+	async close(code, reason) {
+		if (this._state === "closed") {
 			return;
 		}
 
 		this.stopHeartbeat();
 		this._state = "closing";
 		this._socket.close(code, reason);
+		await events.once(this, "close")
 	}
 }
 
@@ -827,14 +882,14 @@ async function handleHandshake(message, socket, req, attachHandler) {
 	} catch (err) {
 		console.log(`SOCKET | closing ${req.socket.remoteAddress} after receiving invalid JSON`);
 		wsRejectedConnectionsCounter.inc();
-		socket.close(1001, "Invalid JSON");
+		socket.close(1002, "Invalid JSON");
 		return;
 	}
 
 	if (!schema.clientHandshake(message)) {
 		console.log(`SOCKET | closing ${req.socket.remoteAddress} after receiving invalid handshake:`, message);
 		wsRejectedConnectionsCounter.inc();
-		socket.close(1001, "Bad handshake");
+		socket.close(1002, "Bad handshake");
 		return;
 	}
 
@@ -864,6 +919,13 @@ async function handleHandshake(message, socket, req, attachHandler) {
 		return
 	}
 
+	if (stopAcceptingNewSessions) {
+		console.log(`SOCKET | closing ${req.socket.remoteAddress}, server is shutting down`);
+		wsRejectedConnectionsCounter.inc();
+		socket.close(1001, "Shutting down");
+		return;
+	}
+
 	let result = await authenticate.check(data.token);
 
 	if (!result.ok) {
@@ -882,7 +944,7 @@ async function handleHandshake(message, socket, req, attachHandler) {
 		let connection = slaveConnections.get(data.id);
 		if (connection) {
 			console.log(`SOCKET | disconnecting existing connection for slave ${data.id}`);
-			await connection.shutdown();
+			await connection.disconnect(1008, "Registered from another connection");
 		}
 
 		console.log(`SOCKET | registered slave ${data.id} version ${data.version}`);
diff --git a/slave.js b/slave.js
index 18ed831c..a08d56bd 100644
--- a/slave.js
+++ b/slave.js
@@ -739,13 +739,25 @@ class Slave extends link.Link {
 		await this.updateInstances();
 	}
 
+	/**
+	 * Stops all instances and closes the connection
+	 */
 	async shutdown() {
-		await link.messages.prepareDisconnect.send(this);
+		this.connector.setTimeout(30);
+
+		try {
+			await link.messages.prepareDisconnect.send(this);
+		} catch (err) {
+			if (!(err instanceof errors.SessionLost)) {
+				console.error("Unexpected error preparing disconnect");
+				console.error(err);
+			}
+		}
+
 		for (let instanceId of this.instanceConnections.keys()) {
 			await this.stopInstance(instanceId);
 		}
-		this.connector.close(1001, "Slave Shutdown");
-		await events.once(this.connector, "close");
+		await this.connector.close(1001, "Slave Shutdown");
 
 		// Clear silly interval in pidfile library.
 		pidusage.clear();
diff --git a/test/integration/index.js b/test/integration/index.js
index 8173bf6e..eb658546 100644
--- a/test/integration/index.js
+++ b/test/integration/index.js
@@ -78,6 +78,7 @@ before(async function() {
 	await exec(`node master --config ${masterConfigPath} config set master.http_port 8880`);
 	await exec(`node master --config ${masterConfigPath} config set master.https_port 4443`);
 	await exec(`node master --config ${masterConfigPath} config set master.heartbeat_interval 0.25`);
+	await exec(`node master --config ${masterConfigPath} config set master.connector_shutdown_timeout 2`);
 
 	await exec(`node slave --config ${slaveConfigPath} config set slave.id 4`);
 	await exec(`node slave --config ${slaveConfigPath} config set slave.name slave`);
@@ -106,6 +107,11 @@ after(async function() {
 	}
 });
 
+// Ensure the test processes are stopped.
+process.on("exit", () => {
+	slaveProcess.kill();
+	masterProcess.kill();
+});
 
 
 module.exports = {

From 61d92a6910888829e4f2e35e510d695ca4a438f6 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 15:06:44 +0200
Subject: [PATCH 15/20] Rename master plugin onExit hook to onShutdown

Rename the onExit hook for master plugins to onShutdown to better
reflect when it is invoked.
---
 lib/plugin.js                      | 2 +-
 master.js                          | 4 ++--
 plugins/research_sync/master.js    | 2 +-
 plugins/subspace_storage/master.js | 2 +-
 test/lib/plugin.js                 | 4 +++-
 5 files changed, 8 insertions(+), 6 deletions(-)

diff --git a/lib/plugin.js b/lib/plugin.js
index abd97ad6..41661db3 100644
--- a/lib/plugin.js
+++ b/lib/plugin.js
@@ -127,7 +127,7 @@ class BaseMasterPlugin {
 	/**
 	 * Called when the master server is shutting down
 	 */
-	async onExit() { }
+	async onShutdown() { }
 }
 
 /**
diff --git a/master.js b/master.js
index af859fdb..f35d8427 100644
--- a/master.js
+++ b/master.js
@@ -250,8 +250,8 @@ async function shutdown() {
 
 		for (let [pluginName, masterPlugin] of masterPlugins) {
 			let startTime = Date.now();
-			await masterPlugin.onExit();
-			console.log(`Plugin ${pluginName} exited in ${Date.now() - startTime}ms`);
+			await masterPlugin.onShutdown();
+			console.log(`Plugin ${pluginName} shutdown in ${Date.now() - startTime}ms`);
 		}
 
 		stopAcceptingNewSessions = true;
diff --git a/plugins/research_sync/master.js b/plugins/research_sync/master.js
index deaf10c4..84a00db4 100644
--- a/plugins/research_sync/master.js
+++ b/plugins/research_sync/master.js
@@ -12,7 +12,7 @@ class MasterPlugin extends plugin.BaseMasterPlugin {
 		this.progressToBroadcast = new Set();
 	}
 
-	async onExit() {
+	async onShutdown() {
 		if (this.progressBroadcastId) {
 			clearTimeout(this.progressBroadcastId);
 		}
diff --git a/plugins/subspace_storage/master.js b/plugins/subspace_storage/master.js
index 3170af23..21e44938 100644
--- a/plugins/subspace_storage/master.js
+++ b/plugins/subspace_storage/master.js
@@ -177,7 +177,7 @@ class MasterPlugin extends plugin.BaseMasterPlugin {
 		}
 	}
 
-	async onExit() {
+	async onShutdown() {
 		clearInterval(this.autosaveId);
 		clearInterval(this.doleMagicId);
 		await saveDatabase(this.master.config, this.items);
diff --git a/test/lib/plugin.js b/test/lib/plugin.js
index 4072aebf..92cd772a 100644
--- a/test/lib/plugin.js
+++ b/test/lib/plugin.js
@@ -16,6 +16,7 @@ describe("lib/plugin", function() {
 			await instancePlugin.init();
 		})
 		it("should define defaults for hooks", async function() {
+			await instancePlugin.onMetrics();
 			await instancePlugin.onStart();
 			await instancePlugin.onStop();
 			instancePlugin.onExit();
@@ -30,7 +31,8 @@ describe("lib/plugin", function() {
 			await masterPlugin.init();
 		})
 		it("should define defaults for hooks", async function() {
-			await masterPlugin.onExit();
+			await masterPlugin.onMetrics();
+			await masterPlugin.onShutdown();
 		})
 	});
 

From 2c855a58461831c6d8d32a9d572bb200dca6df1e Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 15:57:13 +0200
Subject: [PATCH 16/20] Add debug-dump-ws command

Add debug command to dump the WebSocket messages being sent and received
by the master server to aid in finding chatty events.
---
 clusterctl.js            | 12 ++++++++++++
 lib/link/messages.js     | 15 +++++++++++++++
 master.js                | 29 ++++++++++++++++++++++++++++-
 test/integration/link.js |  1 +
 4 files changed, 56 insertions(+), 1 deletion(-)

diff --git a/clusterctl.js b/clusterctl.js
index 472548ba..6f38905e 100644
--- a/clusterctl.js
+++ b/clusterctl.js
@@ -310,6 +310,14 @@ commands.push(new Command({
 	},
 }));
 
+commands.push(new Command({
+	definition: ["debug-dump-ws", "Dump WebSocket messages sent and received by master", (yargs) => { }],
+	handler: async function(args, control) {
+		await link.messages.debugDumpWs.send(control);
+		return new Promise(() => {});
+	},
+}));
+
 // Convert to mapping from name to command instance
 commands = new Map([...commands.map(command => [command.name, command])]);
 
@@ -352,6 +360,10 @@ class Control extends link.Link {
 		console.log(formatOutputColored(output));
 	}
 
+	async debugWsMessageEventHandler(message) {
+		console.log("WS", message.data.direction, message.data.content);
+	}
+
 	async shutdown() {
 		this.connector.setTimeout(30);
 
diff --git a/lib/link/messages.js b/lib/link/messages.js
index 97044ced..365bfa6a 100644
--- a/lib/link/messages.js
+++ b/lib/link/messages.js
@@ -195,6 +195,12 @@ messages.ping = new Request({
 	links: wsLinks,
 });
 
+messages.debugDumpWs = new Request({
+	type: "debug_dump_ws",
+	links: ["control-master"],
+});
+
+
 // Management requests
 messages.listSlaves = new Request({
 	type: 'list_slaves',
@@ -484,6 +490,15 @@ class Event {
 	}
 }
 
+messages.debugWsMessage = new Event({
+	type: "debug_ws_message",
+	links: ["master-control"],
+	eventProperties: {
+		"direction": { type: "string" },
+		"content": { type: "string" },
+	},
+});
+
 messages.instanceStopped = new Event({
 	type: 'instance_stopped',
 	links: ['instance-slave'],
diff --git a/master.js b/master.js
index f35d8427..d4640f2c 100644
--- a/master.js
+++ b/master.js
@@ -30,6 +30,7 @@ const version = require("./package").version;
 let masterConfig;
 let masterConfigPath;
 let stopAcceptingNewSessions = false;
+let debugEvents = new events.EventEmitter();
 
 // homebrew modules
 const generateSSLcert = require("lib/generateSSLcert");
@@ -429,6 +430,16 @@ class ControlConnection extends BaseConnection {
 		});
 
 		this.instanceOutputSubscriptions = new Set();
+
+		this.ws_dumper = null;
+		this.connector.on("connected", () => {
+			this.connector._socket.clusterio_ignore_dump = !!this.ws_dumper;
+		});
+		this.connector.on("close", () => {
+			if (this.ws_dumper) {
+				debugEvents.off("message", this.ws_dumper);
+			}
+		});
 	}
 
 	async listSlavesRequestHandler(message) {
@@ -551,6 +562,14 @@ class ControlConnection extends BaseConnection {
 	async setInstanceOutputSubscriptionsRequestHandler(message) {
 		this.instanceOutputSubscriptions = new Set(message.data.instance_ids);
 	}
+
+	async debugDumpWsRequestHandler(message) {
+		this.ws_dumper = data => {
+			link.messages.debugWsMessage.send(this, data);
+		};
+		this.connector._socket.clusterio_ignore_dump = true;
+		debugEvents.on("message", this.ws_dumper)
+	}
 }
 
 var slaveConnections = new Map();
@@ -828,10 +847,18 @@ wss.on("connection", function (socket, req) {
 
 	// Track statistics
 	wsConnectionsCounter.inc();
-	socket.on("message", () => { wsMessageCounter.labels("in").inc(); });
+	socket.on("message", (message) => {
+		wsMessageCounter.labels("in").inc();
+		if (!socket.clusterio_ignore_dump) {
+			debugEvents.emit("message", { direction: "in", content: message });
+		}
+	});
 	let originalSend = socket.send;
 	socket.send = (...args) => {
 		wsMessageCounter.labels("out").inc();
+		if (typeof args[0] === "string" && !socket.clusterio_ignore_dump) {
+			debugEvents.emit("message", { direction: "out", content: args[0] });
+		}
 		return originalSend.call(socket, ...args);
 	};
 
diff --git a/test/integration/link.js b/test/integration/link.js
index d684b09e..5836d507 100644
--- a/test/integration/link.js
+++ b/test/integration/link.js
@@ -12,6 +12,7 @@ class TestControl extends link.Link {
 		link.attachAllMessages(this);
 	}
 
+	async debugWsMessageEventHandler() { }
 	async prepareDisconnectRequestHandler() { }
 	async instanceOutputEventHandler() { }
 }

From 4f463a8180b48d5ea21db9e2a78e0921b903c5fc Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 20:02:29 +0200
Subject: [PATCH 17/20] Reduce number of bits in generated test cert

Add config entry for the number of bits to use in the auto generate TLS
certificate for the master server and reduce it to 512 for the
integration test.  This reduces the time needed to generate the
certificate in the integration test.
---
 lib/config/definitions.js | 7 +++++++
 master.js                 | 1 +
 test/integration/index.js | 1 +
 3 files changed, 9 insertions(+)

diff --git a/lib/config/definitions.js b/lib/config/definitions.js
index 98f36847..9c1dbc14 100644
--- a/lib/config/definitions.js
+++ b/lib/config/definitions.js
@@ -65,6 +65,13 @@ MasterGroup.define({
 	optional: true,
 	initial_value: "database/certificates/cert.key",
 });
+MasterGroup.define({
+	name: "tls_bits",
+	title: "TLS Bits",
+	description: "Number of bits to use for auto generated TLS certificate.",
+	type: "number",
+	initial_value: 2048,
+});
 MasterGroup.define({
 	name: "auth_secret",
 	title: "Master Authentication Secret",
diff --git a/master.js b/master.js
index d4640f2c..a144945f 100644
--- a/master.js
+++ b/master.js
@@ -1155,6 +1155,7 @@ async function startServer() {
 	// Create a self signed certificate if the certificate files doesn't exist
 	if (httpsPort && !await fs.exists(tls_cert) && !await fs.exists(tls_key)) {
 		await generateSSLcert({
+			bits: masterConfig.get("master.tls_bits"),
 			sslCertPath: tls_cert,
 			sslPrivKeyPath: tls_key,
 			doLogging: true,
diff --git a/test/integration/index.js b/test/integration/index.js
index eb658546..a861b09a 100644
--- a/test/integration/index.js
+++ b/test/integration/index.js
@@ -77,6 +77,7 @@ before(async function() {
 	await exec(`node master --config ${masterConfigPath} config set master.auth_secret TestSecretDoNotUse`);
 	await exec(`node master --config ${masterConfigPath} config set master.http_port 8880`);
 	await exec(`node master --config ${masterConfigPath} config set master.https_port 4443`);
+	await exec(`node master --config ${masterConfigPath} config set master.tls_bits 512`);
 	await exec(`node master --config ${masterConfigPath} config set master.heartbeat_interval 0.25`);
 	await exec(`node master --config ${masterConfigPath} config set master.connector_shutdown_timeout 2`);
 

From 38c392ff6dd8c62199fd2583f3e5b43c8e9922b1 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 20:08:04 +0200
Subject: [PATCH 18/20] Fix kill logic of integration test

Test if the process variable exists before trying to call kill on it, as
in certain failure situations it is not set.
---
 test/integration/index.js | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/test/integration/index.js b/test/integration/index.js
index a861b09a..046e7a65 100644
--- a/test/integration/index.js
+++ b/test/integration/index.js
@@ -110,8 +110,8 @@ after(async function() {
 
 // Ensure the test processes are stopped.
 process.on("exit", () => {
-	slaveProcess.kill();
-	masterProcess.kill();
+	if (slaveProcess) { slaveProcess.kill(); }
+	if (masterProcess) { masterProcess.kill(); }
 });
 
 

From 00d1d304d22422d4ea76c1bc1a05cb9f8a3f6199 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 20:35:51 +0200
Subject: [PATCH 19/20] Fix integration test certificate path

Fix integration tests using the default certificate paths instead of
having them located in the dedicated test database directory.  Also
increment key size to the minimum allowed of 1024.
---
 test/integration/index.js | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/test/integration/index.js b/test/integration/index.js
index 046e7a65..49546554 100644
--- a/test/integration/index.js
+++ b/test/integration/index.js
@@ -77,7 +77,9 @@ before(async function() {
 	await exec(`node master --config ${masterConfigPath} config set master.auth_secret TestSecretDoNotUse`);
 	await exec(`node master --config ${masterConfigPath} config set master.http_port 8880`);
 	await exec(`node master --config ${masterConfigPath} config set master.https_port 4443`);
-	await exec(`node master --config ${masterConfigPath} config set master.tls_bits 512`);
+	await exec(`node master --config ${masterConfigPath} config set master.tls_certificate ${path.join(databaseDir, "cert.crt")}`);
+	await exec(`node master --config ${masterConfigPath} config set master.tls_private_key ${path.join(databaseDir, "cert.key")}`);
+	await exec(`node master --config ${masterConfigPath} config set master.tls_bits 1024`);
 	await exec(`node master --config ${masterConfigPath} config set master.heartbeat_interval 0.25`);
 	await exec(`node master --config ${masterConfigPath} config set master.connector_shutdown_timeout 2`);
 

From 430aa6d207044c385ce3bba7f43fb39289ee0918 Mon Sep 17 00:00:00 2001
From: Hornwitser <github@hornwitser.no>
Date: Thu, 9 Apr 2020 20:44:06 +0200
Subject: [PATCH 20/20] Disable heap and memory size tests

Disable the tests for the memory and heap size metrics as the travis
environment is apparently using 3x as much memory as locally.
---
 test/lib/prometheus.js | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/test/lib/prometheus.js b/test/lib/prometheus.js
index 28da621b..f959556b 100644
--- a/test/lib/prometheus.js
+++ b/test/lib/prometheus.js
@@ -421,6 +421,7 @@ describe("lib/prometheus", function() {
 		});
 		describe("processResidentMemoryBytes", function() {
 			it("should give a low value", async function() {
+				this.skip(); // XXX Doesn't work in Clusterio's shared testing env
 				let results = []
 				let collector = prometheus.defaultCollectors.processResidentMemoryBytes;
 				for await (let result of collector.collect()) {
@@ -441,6 +442,7 @@ describe("lib/prometheus", function() {
 		});
 		describe("processHeapBytes", function() {
 			it("should give a low value", async function() {
+				this.skip(); // XXX Doesn't work in Clusterio's shared testing env
 				let results = []
 				let collector = prometheus.defaultCollectors.processHeapBytes;
 				for await (let result of collector.collect()) {