Add some debug logging

packages/protocol/src/node/command.ts

@@ -198,7 +198,7 @@ export const handleNewServer = (connection: SendableConnection, newServer: NewSe
 		const sm = new ServerMessage();
 		sm.setServerFailure(sf);
 		connection.send(sm.serializeBinary());
-	
+
 		onExit();
 	}
 

packages/protocol/src/node/server.ts

@@ -4,7 +4,7 @@ import * as path from "path";
 import { mkdir, WriteStream } from "fs";
 import { promisify } from "util";
 import { TextDecoder } from "text-encoding";
-import { logger, field } from "@coder/logger";
+import { Logger, logger, field } from "@coder/logger";
 import { ClientMessage, WorkingInitMessage, ServerMessage, NewSessionMessage, WriteToSessionMessage } from "../proto";
 import { evaluate } from "./evaluate";
 import { ReadWriteConnection } from "../common/connection";
@@ -95,8 +95,12 @@ export class Server {
 		if (message.hasNewEval()) {
 			evaluate(this.connection, message.getNewEval()!);
 		} else if (message.hasNewSession()) {
-			const session = handleNewSession(this.connection, message.getNewSession()!, this.options, () => {
+			const sessionMessage = message.getNewSession()!;
-				this.sessions.delete(message.getNewSession()!.getId());
+			const childLogger = this.getChildLogger(sessionMessage.getCommand());
+			childLogger.debug(sessionMessage.getIsFork() ? "Forking" : "Spawning", field("args", sessionMessage.getArgsList()));
+			const session = handleNewSession(this.connection, sessionMessage, this.options, () => {
+				childLogger.debug("Exited");
+				this.sessions.delete(sessionMessage.getId());
 			});
 			this.sessions.set(message.getNewSession()!.getId(), session);
 		} else if (message.hasCloseSessionInput()) {
@@ -134,10 +138,15 @@ export class Server {
 				s.write(data);
 			}
 		} else if (message.hasNewConnection()) {
-			const socket = handleNewConnection(this.connection, message.getNewConnection()!, () => {
+			const connectionMessage = message.getNewConnection()!;
-				this.connections.delete(message.getNewConnection()!.getId());
+			const name = connectionMessage.getPath() || `${connectionMessage.getPort()}`;
+			const childLogger = this.getChildLogger(name, ">");
+			childLogger.debug("Connecting", field("path", connectionMessage.getPath()), field("port", connectionMessage.getPort()));
+			const socket = handleNewConnection(this.connection, connectionMessage, () => {
+				childLogger.debug("Disconnected");
+				this.connections.delete(connectionMessage.getId());
 			});
-			this.connections.set(message.getNewConnection()!.getId(), socket);
+			this.connections.set(connectionMessage.getId(), socket);
 		} else if (message.hasConnectionOutput()) {
 			const c = this.getConnection(message.getConnectionOutput()!.getId());
 			if (!c) {
@@ -151,14 +160,21 @@ export class Server {
 			}
 			c.end();
 		} else if (message.hasNewServer()) {
-			const s = handleNewServer(this.connection, message.getNewServer()!, (socket) => {
+			const serverMessage = message.getNewServer()!;
+			const name = serverMessage.getPath() || `${serverMessage.getPort()}`;
+			const childLogger = this.getChildLogger(name);
+			childLogger.debug("Listening", field("path", serverMessage.getPath()), field("port", serverMessage.getPort()));
+			const s = handleNewServer(this.connection, serverMessage, (socket) => {
 				const id = this.connectionId--;
 				this.connections.set(id, socket);
+				childLogger.debug("Got connection", field("id", id));
+
 				return id;
 			}, () => {
-				this.connections.delete(message.getNewServer()!.getId());
+				childLogger.debug("Stopped");
+				this.connections.delete(serverMessage.getId());
 			});
-			this.servers.set(message.getNewServer()!.getId(), s);
+			this.servers.set(serverMessage.getId(), s);
 		} else if (message.hasServerClose()) {
 			const s = this.getServer(message.getServerClose()!.getId());
 			if (!s) {
@@ -180,4 +196,26 @@ export class Server {
 		return this.sessions.get(id);
 	}
 
+	private getChildLogger(command: string, prefix: string = ""): Logger {
+		// TODO: Temporary, for debugging. Should probably ask for a name?
+		let name: string;
+		if (command.includes("vscode-ipc")) {
+			name = "exthost";
+		} else if (command.includes("vscode-online")) {
+			name = "shared";
+		} else {
+			const basename = command.split("/").pop()!;
+			let i = 0;
+			for (; i < basename.length; i++) {
+				const character = basename.charAt(i);
+				if (character === character.toUpperCase()) {
+					break;
+				}
+			}
+			name = basename.substring(0, i);
+		}
+
+		return logger.named(prefix + name);
+	}
+
 }

packages/server/src/vscode/bootstrapFork.ts

@@ -2,20 +2,6 @@ import * as cp from "child_process";
 import * as fs from "fs";
 import * as net from "net";
 import * as path from "path";
-import { Logger, logger, field } from "@coder/logger/src";
-
-const getChildLogger = (modulePath: string): Logger => {
-	const basename = modulePath.split("/").pop()!;
-	let i = 0;
-	for (; i < basename.length; i++) {
-		const character = basename.charAt(i);
-		if (character === character.toUpperCase()) {
-			break;
-		}
-	}
-
-	return  logger.named(basename.substring(0, i));
-};
 
 export const requireModule = (modulePath: string): void => {
 	process.env.AMD_ENTRYPOINT = modulePath;
@@ -46,9 +32,6 @@ export const requireModule = (modulePath: string): void => {
  * @param modulePath Path of the VS Code module to load.
  */
 export const forkModule = (modulePath: string): cp.ChildProcess => {
-	const childLogger = getChildLogger(modulePath);
-	childLogger.debug("Forking...", field("module", modulePath));
-
 	let proc: cp.ChildProcess | undefined;
 
 	const args = ["--bootstrap-fork", modulePath];
@@ -61,9 +44,5 @@ export const forkModule = (modulePath: string): cp.ChildProcess => {
 		proc = cp.spawn(process.execArgv[0], ["-r", "tsconfig-paths/register", process.argv[1], ...args], options);
 	}
 
-	proc.on("exit", (exitCode) => {
-		childLogger.debug(`Exited with ${exitCode}`);
-	});
-
 	return proc;
 };