Improve ext host logging

src/vs/workbench/services/extensions/electron-browser/extensionService.ts

@@ -39,7 +39,7 @@ import { Event, Emitter } from 'vs/base/common/event';
 import { ExtensionHostProfiler } from 'vs/workbench/services/extensions/electron-browser/extensionHostProfiler';
 import product from 'vs/platform/node/product';
 import * as strings from 'vs/base/common/strings';
-import { RPCProtocol, IRPCProtocolLogger } from 'vs/workbench/services/extensions/node/rpcProtocol';
+import { RPCProtocol, IRPCProtocolLogger, RequestInitiator } from 'vs/workbench/services/extensions/node/rpcProtocol';
 import { INotificationService, Severity } from 'vs/platform/notification/common/notification';
 import { isFalsyOrEmpty } from 'vs/base/common/arrays';
 import { Schemas } from 'vs/base/common/network';
@@ -48,6 +48,7 @@ import { isEqualOrParent } from 'vs/base/common/resources';
 
 // Enable to see detailed message communication between window and extension host
 const LOG_EXTENSION_HOST_COMMUNICATION = false;
+const LOG_USE_COLORS = true;
 
 let _SystemExtensionsRoot: string = null;
 function getSystemExtensionsRoot(): string {
@@ -955,19 +956,59 @@ export class ExtensionService extends Disposable implements IExtensionService {
 	}
 }
 
+const colorTables = [
+	['#2977B1', '#FC802D', '#34A13A', '#D3282F', '#9366BA'],
+	['#8B564C', '#E177C0', '#7F7F7F', '#BBBE3D', '#2EBECD']
+];
+
+function prettyWithoutArrays(data: any): any {
+	if (Array.isArray(data)) {
+		return data;
+	}
+	if (data && typeof data === 'object' && typeof data.toString === 'function') {
+		let result = data.toString();
+		if (result !== '[object Object]') {
+			return result;
+		}
+	}
+	return data;
+}
+
+function pretty(data: any): any {
+	if (Array.isArray(data)) {
+		return data.map(prettyWithoutArrays);
+	}
+	return prettyWithoutArrays(data);
+}
+
 class RPCLogger implements IRPCProtocolLogger {
 
 	private _totalIncoming = 0;
 	private _totalOutgoing = 0;
 
-	logIncoming(msgLength: number, str: string, data?: any): void {
+	private _log(direction: string, totalLength, msgLength: number, req: number, initiator: RequestInitiator, str: string, data: any): void {
+		data = pretty(data);
+
+		const colorTable = colorTables[initiator];
+		const color = LOG_USE_COLORS ? colorTable[req % colorTable.length] : '#000000';
+		let args = [`%c[${direction}]%c[${strings.pad(totalLength, 7, ' ')}]%c[len: ${strings.pad(msgLength, 5, ' ')}]%c${strings.pad(req, 5, ' ')} - ${str}`, 'color: darkgreen', 'color: grey', 'color: grey', `color: ${color}`];
+		if (/\($/.test(str)) {
+			args = args.concat(data);
+			args.push(')');
+		} else {
+			args.push(data);
+		}
+		console.log.apply(console, args);
+	}
+
+	logIncoming(msgLength: number, req: number, initiator: RequestInitiator, str: string, data?: any): void {
 		this._totalIncoming += msgLength;
-		console.log(`%c[Extension \u2192 Window]%c[${strings.pad(this._totalIncoming, 7, ' ')}]%c[len: ${strings.pad(msgLength, 5, ' ')}]`, 'color: darkgreen', 'color: grey', 'color: grey', str, data);
+		this._log('Ext \u2192 Win', this._totalIncoming, msgLength, req, initiator, str, data);
 	}
 
-	logOutgoing(msgLength: number, str: string, data?: any): void {
+	logOutgoing(msgLength: number, req: number, initiator: RequestInitiator, str: string, data?: any): void {
 		this._totalOutgoing += msgLength;
-		console.log(`%c[Window \u2192 Extension]%c[${strings.pad(this._totalOutgoing, 7, ' ')}]%c[len: ${strings.pad(msgLength, 5, ' ')}]`, 'color: darkgreen', 'color: grey', 'color: grey', str, data);
+		this._log('Win \u2192 Ext', this._totalOutgoing, msgLength, req, initiator, str, data);
 	}
 }
 

src/vs/workbench/services/extensions/node/rpcProtocol.ts

@@ -85,9 +85,14 @@ function transformIncomingURIs(obj: any, transformer: IURITransformer): any {
 	return result;
 }
 
+export const enum RequestInitiator {
+	LocalSide = 0,
+	OtherSide = 1
+}
+
 export interface IRPCProtocolLogger {
-	logIncoming(msgLength: number, str: string, data?: any): void;
-	logOutgoing(msgLength: number, str: string, data?: any): void;
+	logIncoming(msgLength: number, req: number, initiator: RequestInitiator, str: string, data?: any): void;
+	logOutgoing(msgLength: number, req: number, initiator: RequestInitiator, str: string, data?: any): void;
 }
 
 export class RPCProtocol implements IRPCProtocol {
@@ -225,11 +230,11 @@ export class RPCProtocol implements IRPCProtocol {
 				if (this._uriTransformer) {
 					err = transformIncomingURIs(err, this._uriTransformer);
 				}
-				this._receiveReplyErr(req, err);
+				this._receiveReplyErr(msgLength, req, err);
 				break;
 			}
 			case MessageType.ReplyErrEmpty: {
-				this._receiveReplyErr(req, undefined);
+				this._receiveReplyErr(msgLength, req, undefined);
 				break;
 			}
 		}
@@ -237,7 +242,7 @@ export class RPCProtocol implements IRPCProtocol {
 
 	private _receiveRequest(msgLength: number, req: number, rpcId: number, method: string, args: any[]): void {
 		if (this._logger) {
-			this._logger.logIncoming(msgLength, `receiveRequest ${req}, ${getStringIdentifierForProxy(rpcId)}.${method}:`, args);
+			this._logger.logIncoming(msgLength, req, RequestInitiator.OtherSide, `receiveRequest ${getStringIdentifierForProxy(rpcId)}.${method}(`, args);
 		}
 		const callId = String(req);
 
@@ -250,14 +255,14 @@ export class RPCProtocol implements IRPCProtocol {
 			}
 			const msg = MessageIO.serializeReplyOK(req, r);
 			if (this._logger) {
-				this._logger.logOutgoing(msg.byteLength, `replyOK ${req}:`, r);
+				this._logger.logOutgoing(msg.byteLength, req, RequestInitiator.OtherSide, `reply:`, r);
 			}
 			this._protocol.send(msg);
 		}, (err) => {
 			delete this._invokedHandlers[callId];
 			const msg = MessageIO.serializeReplyErr(req, err);
 			if (this._logger) {
-				this._logger.logOutgoing(msg.byteLength, `replyErr ${req}:`, err);
+				this._logger.logOutgoing(msg.byteLength, req, RequestInitiator.OtherSide, `replyErr:`, err);
 			}
 			this._protocol.send(msg);
 		});
@@ -265,7 +270,7 @@ export class RPCProtocol implements IRPCProtocol {
 
 	private _receiveCancel(msgLength: number, req: number): void {
 		if (this._logger) {
-			this._logger.logIncoming(msgLength, `receiveCancel ${req}`);
+			this._logger.logIncoming(msgLength, req, RequestInitiator.OtherSide, `receiveCancel`);
 		}
 		const callId = String(req);
 		if (this._invokedHandlers[callId]) {
@@ -275,7 +280,7 @@ export class RPCProtocol implements IRPCProtocol {
 
 	private _receiveReply(msgLength: number, req: number, value: any): void {
 		if (this._logger) {
-			this._logger.logIncoming(msgLength, `receiveReply ${req}:`, value);
+			this._logger.logIncoming(msgLength, req, RequestInitiator.LocalSide, `receiveReply:`, value);
 		}
 		const callId = String(req);
 		if (!this._pendingRPCReplies.hasOwnProperty(callId)) {
@@ -288,7 +293,11 @@ export class RPCProtocol implements IRPCProtocol {
 		pendingReply.resolveOk(value);
 	}
 
-	private _receiveReplyErr(req: number, value: any): void {
+	private _receiveReplyErr(msgLength: number, req: number, value: any): void {
+		if (this._logger) {
+			this._logger.logIncoming(msgLength, req, RequestInitiator.LocalSide, `receiveReplyErr:`, value);
+		}
+
 		const callId = String(req);
 		if (!this._pendingRPCReplies.hasOwnProperty(callId)) {
 			return;
@@ -337,7 +346,7 @@ export class RPCProtocol implements IRPCProtocol {
 		const result = new LazyPromise(() => {
 			const msg = MessageIO.serializeCancel(req);
 			if (this._logger) {
-				this._logger.logOutgoing(msg.byteLength, `cancel ${req}`);
+				this._logger.logOutgoing(msg.byteLength, req, RequestInitiator.LocalSide, `cancel`);
 			}
 			this._protocol.send(MessageIO.serializeCancel(req));
 		});
@@ -348,7 +357,7 @@ export class RPCProtocol implements IRPCProtocol {
 		}
 		const msg = MessageIO.serializeRequest(req, rpcId, methodName, args);
 		if (this._logger) {
-			this._logger.logOutgoing(msg.byteLength, `request ${req}: ${getStringIdentifierForProxy(rpcId)}.${methodName}:`, args);
+			this._logger.logOutgoing(msg.byteLength, req, RequestInitiator.LocalSide, `request: ${getStringIdentifierForProxy(rpcId)}.${methodName}(`, args);
 		}
 		this._protocol.send(msg);
 		return result;