Merge pull request #994 from bbassie/fix/log-invalid-message-errors

Include schema validation errors in InvalidMessage stack

packages/lib/src/errors.ts

@@ -58,6 +58,10 @@ export class InvalidMessage extends Error {
 		public errors?: object | null,
 	) {
 		super(message);
+		// Include the errors in the stack so generic handlers logging it show what failed
+		if (errors) {
+			this.stack += `\n${JSON.stringify(errors, null, "\t")}`;
+		}
 	}
 }
 

packages/lib/src/link/link.ts

@@ -213,7 +213,7 @@ export class Link {
 			let handler = this._eventSnoopers.get((entry as EventEntry).Event)!;
 			let event = message as libData.MessageEvent;
 			handler((entry as EventEntry).eventFromJSON(event.data), event.src, event.dst).catch((err: Error) => {
-				logger.error(`Unexpected error snooping ${event.name}:\n${err.stack}`);
+				logger.error(`Unexpected error snooping ${event.name}:\n${err.stack ?? err.message}`);
 			});
 		}
 
@@ -482,7 +482,7 @@ export class Link {
 		handler(
 			entry.eventFromJSON(message.data), message.src, message.dst
 		).catch((err: Error) => {
-			logger.error(`Unexpected error handling ${message.name}:\n${err.stack}`);
+			logger.error(`Unexpected error handling ${message.name}:\n${err.stack ?? err.message}`);
 		});
 	}
 

test/host/server.js

@@ -311,6 +311,32 @@ describe("host/server", function() {
 			});
 		});
 
+		describe(".handle()", function() {
+			it("should log validation errors from ipc handlers", async function() {
+				let logged = [];
+				let ipcServer = new hostServer.FactorioServer(
+					path.join("test", "file", "factorio"), writePath,
+					{ logger: { error: msg => { logged.push(msg); } } }
+				);
+				class NumberEvent {
+					static type = "event";
+					static src = "instance";
+					static dst = "controller";
+					constructor(value) { this.value = value; }
+					static jsonSchema = { type: "number" };
+					static fromJSON(json) { return new this(json); }
+				}
+				let eventFromJSON = lib.Link.eventFromJSON(NumberEvent, "NumberEvent");
+				ipcServer.handle("bad_event", async () => { eventFromJSON("not a number"); });
+				ipcServer.emit("ipc-bad_event", {});
+				await new Promise(resolve => setImmediate(resolve));
+
+				assert.equal(logged.length, 1);
+				assert(logged[0].startsWith("Error handling ipc event:\nError: Event NumberEvent failed validation\n"));
+				assert(logged[0].includes('"message": "must be number"'));
+			});
+		});
+
 		describe(".stop()", function() {
 			it("should handle server quitting on its own during stop", async function() {
 				server.shutdownTimeoutMs = 20;

test/lib/errors.js

@@ -0,0 +1,24 @@
+"use strict";
+const assert = require("assert").strict;
+
+const lib = require("@clusterio/lib");
+
+describe("lib/errors", function() {
+	describe("class InvalidMessage", function() {
+		it("should include validation errors in the stack", function() {
+			let errors = [{ instancePath: "/value", message: "must be number" }];
+			let err = new lib.InvalidMessage("Request Test failed validation", errors);
+			assert.equal(err.message, "Request Test failed validation");
+			assert.equal(err.errors, errors);
+			assert(err.stack.startsWith("Error: Request Test failed validation\n"));
+			assert(err.stack.endsWith(`\n${JSON.stringify(errors, null, "\t")}`));
+		});
+		it("should leave the stack alone without errors", function() {
+			let err = new lib.InvalidMessage("Unrecognized request Test");
+			assert.equal(err.errors, undefined);
+			assert(!err.stack.includes("\n["));
+			let nullErr = new lib.InvalidMessage("Unrecognized request Test", null);
+			assert.equal(nullErr.errors, null);
+		});
+	});
+});

test/lib/link/link.js

@@ -413,6 +413,42 @@ describe("lib/link/link", function() {
 				testLink.handle(SimpleEvent, async () => { throwSimple("Error"); });
 				testConnector.emit("message", new lib.MessageEvent(1, dst, src, "SimpleEvent"));
 			});
+			it("should log validation errors from event handler", async function() {
+				let logged = [];
+				const originalError = lib.logger.error;
+				lib.logger.error = msg => { logged.push(msg); };
+				try {
+					testLink.handle(SimpleEvent, async () => {
+						testLink.sendEvent(new NumberEvent("not a number"), dst);
+					});
+					testConnector.emit("message", new lib.MessageEvent(1, dst, src, "SimpleEvent"));
+					await new Promise(resolve => setImmediate(resolve));
+				} finally {
+					lib.logger.error = originalError;
+				}
+				assert.equal(logged.length, 1);
+				assert(logged[0].startsWith(
+					"Unexpected error handling SimpleEvent:\nError: Event NumberEvent failed validation\n"
+				));
+				assert(logged[0].includes('"message": "must be number"'));
+			});
+			it("should fall back to message when event handler error has no stack", async function() {
+				let logged = [];
+				const originalError = lib.logger.error;
+				lib.logger.error = msg => { logged.push(msg); };
+				try {
+					testLink.handle(SimpleEvent, async () => {
+						let err = new Error("no stack");
+						err.stack = undefined;
+						throw err;
+					});
+					testConnector.emit("message", new lib.MessageEvent(1, dst, src, "SimpleEvent"));
+					await new Promise(resolve => setImmediate(resolve));
+				} finally {
+					lib.logger.error = originalError;
+				}
+				assert.deepEqual(logged, ["Unexpected error handling SimpleEvent:\nno stack"]);
+			});
 			it("should throw on unknown type", function() {
 				assert.throws(
 					() => testLink.handle({ name: "Bad", type: "bad" }),
@@ -595,6 +631,44 @@ describe("lib/link/link", function() {
 				testLink.snoopEvent(SimpleEvent, async () => { throwSimple("Error"); });
 				testConnector.emit("message", new lib.MessageEvent(1, dst, src, "SimpleEvent"));
 			});
+			it("should log validation errors from snoop handler", async function() {
+				let logged = [];
+				const originalError = lib.logger.error;
+				lib.logger.error = msg => { logged.push(msg); };
+				try {
+					testLink.handle(SimpleEvent, async () => {});
+					testLink.snoopEvent(SimpleEvent, async () => {
+						testLink.sendEvent(new NumberEvent("not a number"), dst);
+					});
+					testConnector.emit("message", new lib.MessageEvent(1, dst, src, "SimpleEvent"));
+					await new Promise(resolve => setImmediate(resolve));
+				} finally {
+					lib.logger.error = originalError;
+				}
+				assert.equal(logged.length, 1);
+				assert(logged[0].startsWith(
+					"Unexpected error snooping SimpleEvent:\nError: Event NumberEvent failed validation\n"
+				));
+				assert(logged[0].includes('"message": "must be number"'));
+			});
+			it("should fall back to message when snoop handler error has no stack", async function() {
+				let logged = [];
+				const originalError = lib.logger.error;
+				lib.logger.error = msg => { logged.push(msg); };
+				try {
+					testLink.handle(SimpleEvent, async () => {});
+					testLink.snoopEvent(SimpleEvent, async () => {
+						let err = new Error("no stack");
+						err.stack = undefined;
+						throw err;
+					});
+					testConnector.emit("message", new lib.MessageEvent(1, dst, src, "SimpleEvent"));
+					await new Promise(resolve => setImmediate(resolve));
+				} finally {
+					lib.logger.error = originalError;
+				}
+				assert.deepEqual(logged, ["Unexpected error snooping SimpleEvent:\nno stack"]);
+			});
 			it("should throw on double registration", function() {
 				testLink.snoopEvent(SimpleEvent);
 				assert.throws(