show console.log from extension host top frame in dev tools (#34936)

src/bootstrap.js

@@ -14,10 +14,11 @@ process.noAsar = true;
 if (!!process.send && process.env.PIPE_LOGGING === 'true') {
 	var MAX_LENGTH = 100000;
 
-	// Prevent circular stringify
-	function safeStringify(args) {
+	// Prevent circular stringify and convert arguments to real array
+	function safeToArray(args) {
 		var seen = [];
 		var res;
+		var argsArray = [];
 
 		// Massage some arguments with special treatment
 		if (args.length) {
@@ -40,11 +41,20 @@ if (!!process.send && process.env.PIPE_LOGGING === 'true') {
 						args[i] = errorObj.toString();
 					}
 				}
+
+				argsArray.push(args[i]);
 			}
 		}
 
+		// Add the stack trace as payload if we are told so. We remove the message and the 2 top frames
+		// to start the stacktrace where the console message was being written
+		if (process.env.VSCODE_LOG_STACK === 'true') {
+			const stack = new Error().stack;
+			argsArray.push({ __$stack: stack.split('\n').slice(3).join('\n') });
+		}
+
 		try {
-			res = JSON.stringify(args, function (key, value) {
+			res = JSON.stringify(argsArray, function (key, value) {
 
 				// Objects get special treatment to prevent circles
 				if (value && Object.prototype.toString.call(value) === '[object Object]') {
@@ -78,16 +88,16 @@ if (!!process.send && process.env.PIPE_LOGGING === 'true') {
 
 	// Pass console logging to the outside so that we have it in the main side if told so
 	if (process.env.VERBOSE_LOGGING === 'true') {
-		console.log = function () { safeSend({ type: '__$console', severity: 'log', arguments: safeStringify(arguments) }); };
-		console.info = function () { safeSend({ type: '__$console', severity: 'log', arguments: safeStringify(arguments) }); };
-		console.warn = function () { safeSend({ type: '__$console', severity: 'warn', arguments: safeStringify(arguments) }); };
+		console.log = function () { safeSend({ type: '__$console', severity: 'log', arguments: safeToArray(arguments) }); };
+		console.info = function () { safeSend({ type: '__$console', severity: 'log', arguments: safeToArray(arguments) }); };
+		console.warn = function () { safeSend({ type: '__$console', severity: 'warn', arguments: safeToArray(arguments) }); };
 	} else {
 		console.log = function () { /* ignore */ };
 		console.warn = function () { /* ignore */ };
 		console.info = function () { /* ignore */ };
 	}
 
-	console.error = function () { safeSend({ type: '__$console', severity: 'error', arguments: safeStringify(arguments) }); };
+	console.error = function () { safeSend({ type: '__$console', severity: 'error', arguments: safeToArray(arguments) }); };
 }
 
 if (!process.env['VSCODE_ALLOW_IO']) {

src/vs/base/node/console.ts

@@ -0,0 +1,125 @@
+/*---------------------------------------------------------------------------------------------
+ *  Copyright (c) Microsoft Corporation. All rights reserved.
+ *  Licensed under the MIT License. See License.txt in the project root for license information.
+ *--------------------------------------------------------------------------------------------*/
+
+'use strict';
+
+import URI from 'vs/base/common/uri';
+
+export interface IRemoteConsoleLog {
+	type: string;
+	severity: string;
+	arguments: string;
+}
+
+interface IStackArgument {
+	__$stack: string;
+}
+
+export interface IStackFrame {
+	uri: URI;
+	line: number;
+	column: number;
+}
+
+export function isRemoteConsoleLog(obj: any): obj is IRemoteConsoleLog {
+	const entry = obj as IRemoteConsoleLog;
+
+	return entry && typeof entry.type === 'string' && typeof entry.severity === 'string';
+}
+
+export function parse(entry: IRemoteConsoleLog): { args: any[], stack?: string } {
+	const args: any[] = [];
+	let stack: string;
+
+	// Parse Entry
+	try {
+		const parsedArguments: any[] = JSON.parse(entry.arguments);
+
+		// Check for special stack entry as last entry
+		const stackArgument = parsedArguments[parsedArguments.length - 1] as IStackArgument;
+		if (stackArgument && stackArgument.__$stack) {
+			parsedArguments.pop(); // stack is handled specially
+			stack = stackArgument.__$stack;
+		}
+
+		args.push(...parsedArguments);
+	} catch (error) {
+		args.push('Unable to log remote console arguments', entry.arguments);
+	}
+
+	return { args, stack };
+}
+
+export function getFirstFrame(entry: IRemoteConsoleLog): IStackFrame;
+export function getFirstFrame(stack: string): IStackFrame;
+export function getFirstFrame(arg0: IRemoteConsoleLog | string): IStackFrame {
+	if (typeof arg0 !== 'string') {
+		return getFirstFrame(parse(arg0).stack);
+	}
+
+	// Parse a source information out of the stack if we have one. Format:
+	// at vscode.commands.registerCommand (/Users/someone/Desktop/test-ts/out/src/extension.js:18:17)
+	const stack = arg0;
+	if (stack) {
+		const matches = /.+\((.+):(\d+):(\d+)\)/.exec(stack);
+		if (matches.length === 4) {
+			return {
+				uri: URI.file(matches[1]),
+				line: Number(matches[2]),
+				column: Number(matches[3])
+			} as IStackFrame;
+		}
+	}
+
+	return void 0;
+}
+
+export function log(entry: IRemoteConsoleLog, label: string): void {
+	const { args, stack } = parse(entry);
+
+	// Determine suffix based on severity of log entry if we have a stack
+	let suffixColor = 'blue';
+	let suffix = '';
+	if (stack) {
+		switch (entry.severity) {
+			case 'warn':
+				suffixColor = 'goldenrod';
+				suffix = ' WARNING:';
+				break;
+			case 'error':
+				suffixColor = 'darkred';
+				suffix = ' ERROR:';
+				break;
+		}
+	}
+
+	let consoleArgs = [];
+
+	// First arg is a string
+	if (typeof args[0] === 'string') {
+		consoleArgs = [`%c[${label}]%c${suffix} %c${args[0]}`, color('blue'), color(suffixColor), color('black'), ...args.slice(1)];
+	}
+
+	// First arg is something else, just apply all
+	else {
+		consoleArgs = [`%c[${label}]%c${suffix}`, color('blue'), color(suffixColor), ...args];
+	}
+
+	// Stack: use console group
+	if (stack) {
+		console.groupCollapsed.apply(console, consoleArgs);
+		console.log(stack);
+		console.groupEnd();
+	}
+
+	// No stack: just log message
+	else {
+		console[entry.severity].apply(console, consoleArgs);
+	}
+}
+
+function color(color: string): string {
+	return `color: ${color}; font-weight: normal;`;
+}

src/vs/base/parts/ipc/node/ipc.cp.ts

@@ -12,6 +12,7 @@ import { Emitter } from 'vs/base/common/event';
 import { fromEventEmitter } from 'vs/base/node/event';
 import { createQueuedSender } from 'vs/base/node/processes';
 import { ChannelServer as IPCServer, ChannelClient as IPCClient, IChannelClient, IChannel } from 'vs/base/parts/ipc/common/ipc';
+import { isRemoteConsoleLog, log } from 'vs/base/node/console';
 
 export class Server extends IPCServer {
 	constructor() {
@@ -151,24 +152,15 @@ export class Client implements IChannelClient, IDisposable {
 			const onRawMessage = fromEventEmitter(this.child, 'message', msg => msg);
 
 			onRawMessage(msg => {
-				// Handle console logs specially
-				if (msg && msg.type === '__$console') {
-					let args = ['%c[IPC Library: ' + this.options.serverName + ']', 'color: darkgreen'];
-					try {
-						const parsed = JSON.parse(msg.arguments);
-						args = args.concat(Object.getOwnPropertyNames(parsed).map(o => parsed[o]));
-					} catch (error) {
-						args.push(msg.arguments);
-					}
 
-					console[msg.severity].apply(console, args);
+				// Handle remote console logs specially
+				if (isRemoteConsoleLog(msg)) {
+					log(msg, `IPC Library: ${this.options.serverName}`);
 					return null;
 				}
 
 				// Anything else goes to the outside
-				else {
-					onMessageEmitter.fire(msg);
-				}
+				onMessageEmitter.fire(msg);
 			});
 
 			const sender = this.options.useQueue ? createQueuedSender(this.child) : this.child;

src/vs/platform/extensions/common/extensionHost.ts

@@ -11,10 +11,4 @@ export const EXTENSION_LOG_BROADCAST_CHANNEL = 'vscode:extensionLog';
 export const EXTENSION_ATTACH_BROADCAST_CHANNEL = 'vscode:extensionAttach';
 export const EXTENSION_TERMINATE_BROADCAST_CHANNEL = 'vscode:extensionTerminate';
 export const EXTENSION_RELOAD_BROADCAST_CHANNEL = 'vscode:extensionReload';
-export const EXTENSION_CLOSE_EXTHOST_BROADCAST_CHANNEL = 'vscode:extensionCloseExtensionHost';
-
-export interface ILogEntry {
-	type: string;
-	severity: string;
-	arguments: any;
-}
+export const EXTENSION_CLOSE_EXTHOST_BROADCAST_CHANNEL = 'vscode:extensionCloseExtensionHost';

src/vs/workbench/parts/debug/electron-browser/debugService.ts

@@ -49,8 +49,9 @@ import { ITextFileService } from 'vs/workbench/services/textfile/common/textfile
 import { IConfigurationService } from 'vs/platform/configuration/common/configuration';
 import { IWorkspaceContextService, WorkbenchState, IWorkspaceFolder } from 'vs/platform/workspace/common/workspace';
 import { IWorkbenchEditorService } from 'vs/workbench/services/editor/common/editorService';
-import { ILogEntry, EXTENSION_LOG_BROADCAST_CHANNEL, EXTENSION_ATTACH_BROADCAST_CHANNEL, EXTENSION_TERMINATE_BROADCAST_CHANNEL, EXTENSION_CLOSE_EXTHOST_BROADCAST_CHANNEL, EXTENSION_RELOAD_BROADCAST_CHANNEL } from 'vs/platform/extensions/common/extensionHost';
+import { EXTENSION_LOG_BROADCAST_CHANNEL, EXTENSION_ATTACH_BROADCAST_CHANNEL, EXTENSION_TERMINATE_BROADCAST_CHANNEL, EXTENSION_CLOSE_EXTHOST_BROADCAST_CHANNEL, EXTENSION_RELOAD_BROADCAST_CHANNEL } from 'vs/platform/extensions/common/extensionHost';
 import { IBroadcastService, IBroadcast } from 'vs/platform/broadcast/electron-browser/broadcastService';
+import { IRemoteConsoleLog, parse } from 'vs/base/node/console';
 
 const DEBUG_BREAKPOINTS_KEY = 'debug.breakpoint';
 const DEBUG_BREAKPOINTS_ACTIVATED_KEY = 'debug.breakpointactivated';
@@ -163,16 +164,10 @@ export class DebugService implements debug.IDebugService {
 
 		// an extension logged output, show it inside the REPL
 		if (broadcast.channel === EXTENSION_LOG_BROADCAST_CHANNEL) {
-			let extensionOutput: ILogEntry = broadcast.payload.logEntry;
+			let extensionOutput: IRemoteConsoleLog = broadcast.payload.logEntry;
 			let sev = extensionOutput.severity === 'warn' ? severity.Warning : extensionOutput.severity === 'error' ? severity.Error : severity.Info;
 
-			let args: any[] = [];
-			try {
-				let parsed = JSON.parse(extensionOutput.arguments);
-				args.push(...Object.getOwnPropertyNames(parsed).map(o => parsed[o]));
-			} catch (error) {
-				args.push(extensionOutput.arguments);
-			}
+			const { args } = parse(extensionOutput);
 
 			// add output for each argument logged
 			let simpleVals: any[] = [];

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

@@ -33,8 +33,9 @@ import { IWorkspaceConfigurationService } from 'vs/workbench/services/configurat
 import { ICrashReporterService } from 'vs/workbench/services/crashReporter/common/crashReporterService';
 import { IBroadcastService, IBroadcast } from 'vs/platform/broadcast/electron-browser/broadcastService';
 import { isEqual } from 'vs/base/common/paths';
-import { EXTENSION_CLOSE_EXTHOST_BROADCAST_CHANNEL, EXTENSION_RELOAD_BROADCAST_CHANNEL, ILogEntry, EXTENSION_ATTACH_BROADCAST_CHANNEL, EXTENSION_LOG_BROADCAST_CHANNEL, EXTENSION_TERMINATE_BROADCAST_CHANNEL } from 'vs/platform/extensions/common/extensionHost';
+import { EXTENSION_CLOSE_EXTHOST_BROADCAST_CHANNEL, EXTENSION_RELOAD_BROADCAST_CHANNEL, EXTENSION_ATTACH_BROADCAST_CHANNEL, EXTENSION_LOG_BROADCAST_CHANNEL, EXTENSION_TERMINATE_BROADCAST_CHANNEL } from 'vs/platform/extensions/common/extensionHost';
 import { IDisposable, dispose } from 'vs/base/common/lifecycle';
+import { IRemoteConsoleLog, log, parse } from 'vs/base/node/console';
 
 export class ExtensionHostProcessWorker {
 
@@ -142,7 +143,8 @@ export class ExtensionHostProcessWorker {
 						VSCODE_WINDOW_ID: String(this._windowService.getCurrentWindowId()),
 						VSCODE_IPC_HOOK_EXTHOST: pipeName,
 						VSCODE_HANDLES_UNCAUGHT_ERRORS: true,
-						ELECTRON_NO_ASAR: '1'
+						ELECTRON_NO_ASAR: '1',
+						VSCODE_LOG_STACK: !this._isExtensionDevTestFromCli && (this._isExtensionDevHost || !this._environmentService.isBuilt || product.quality !== 'stable' || this._environmentService.verbose)
 					}),
 					// We only detach the extension host on windows. Linux and Mac orphan by default
 					// and detach under Linux and Mac create another process group.
@@ -195,8 +197,8 @@ export class ExtensionHostProcessWorker {
 
 				// Support logging from extension host
 				this._extensionHostProcess.on('message', msg => {
-					if (msg && (<ILogEntry>msg).type === '__$console') {
-						this._logExtensionHostMessage(<ILogEntry>msg);
+					if (msg && (<IRemoteConsoleLog>msg).type === '__$console') {
+						this._logExtensionHostMessage(<IRemoteConsoleLog>msg);
 					}
 				});
 
@@ -365,33 +367,16 @@ export class ExtensionHostProcessWorker {
 		});
 	}
 
-	private _logExtensionHostMessage(logEntry: ILogEntry) {
-		let args = [];
-		try {
-			let parsed = JSON.parse(logEntry.arguments);
-			args.push(...Object.getOwnPropertyNames(parsed).map(o => parsed[o]));
-		} catch (error) {
-			args.push(logEntry.arguments);
-		}
-
-		// If the first argument is a string, check for % which indicates that the message
-		// uses substitution for variables. In this case, we cannot just inject our colored
-		// [Extension Host] to the front because it breaks substitution.
-		let consoleArgs = [];
-		if (typeof args[0] === 'string' && args[0].indexOf('%') >= 0) {
-			consoleArgs = [`%c[Extension Host]%c ${args[0]}`, 'color: blue', 'color: black', ...args.slice(1)];
-		} else {
-			consoleArgs = ['%c[Extension Host]', 'color: blue', ...args];
-		}
+	private _logExtensionHostMessage(entry: IRemoteConsoleLog) {
 
 		// Send to local console unless we run tests from cli
 		if (!this._isExtensionDevTestFromCli) {
-			console[logEntry.severity].apply(console, consoleArgs);
+			log(entry, 'Extension Host');
 		}
 
 		// Log on main side if running tests from cli
 		if (this._isExtensionDevTestFromCli) {
-			this._windowsService.log(logEntry.severity, ...args);
+			this._windowsService.log(entry.severity, ...parse(entry).args);
 		}
 
 		// Broadcast to other windows if we are in development mode
@@ -399,7 +384,7 @@ export class ExtensionHostProcessWorker {
 			this._broadcastService.broadcast({
 				channel: EXTENSION_LOG_BROADCAST_CHANNEL,
 				payload: {
-					logEntry,
+					logEntry: entry,
 					debugId: this._environmentService.debugExtensionHost.debugId
 				}
 			});