Support to configure logging levels for sqltools services (#2731)

* Adding support for configuring SqlTools log levels from user configuration. This also adds changes to see the tail of the sqltoolsservicelayer log file in the newly created 'Output->Log (SqlTools)' channel

* Three new user settings control how logging happens. tracingLevel, logRetentionMinutes & logFilesRemovalLimit. Default tracingLevel is set to 'Critical'. 

* The logfiles include ui Extension host process id in their log file names. This ensures that filenames from multiple instances of Azure Data Studio running do not collide with each other. Furthermore log directory for  being used for the tools service backend processes. This ensures that there is no name conflict when multiple instances of azuredatastudio are running on the same box. Also when azuredatastudio is started from vscode under debugger the log directory is set to %APPDATA%\Code\mssql while the official location is %APPDATA%\azuredatastudio\mssql. So dev environment should not affect other running instances. Kindly note that all debug runs of azuredatastudio share the same directory and all non debug runs share a directory different from those running under debugger. 

* Log files older than a week get cleaned up upon start-up. The log file cleanup behavior can be controlled at user level by  logRetentionMinutes & logFilesRemovalLimit settings.

.vscode/launch.json

@@ -90,7 +90,7 @@
 				"**/winjs*.js"
 			],
 			"webRoot": "${workspaceFolder}",
-			"timeout": 15000
+			"timeout": 45000
 		},
 		{
 			"type": "node",
@@ -153,4 +153,4 @@
 			]
 		}
 	]
-}
+}

ThirdPartyNotices.txt

@@ -21,6 +21,7 @@ expressly granted herein, whether by implication, estoppel or otherwise.
     error-ex: https://github.com/Qix-/node-error-ex
     escape-string-regexp: https://github.com/sindresorhus/escape-string-regexp
     fast-plist: https://github.com/Microsoft/node-fast-plist
+    find-remove: https://www.npmjs.com/package/find-remove
     fs-extra: https://github.com/jprichardson/node-fs-extra
     gc-signals: https://github.com/Microsoft/node-gc-signals
     getmac: https://github.com/bevry/getmac

extensions/mssql/package.json

@@ -93,7 +93,31 @@
         "mssql.logDebugInfo": {
           "type": "boolean",
           "default": false,
-          "description": "[Optional] Log debug output to the VS Code console (Help -> Toggle Developer Tools)"
+          "description": "[Optional] Log debug output to the console (View -> Output) and then select appropriate output channel from the dropdown"
+        },
+        "mssql.tracingLevel": {
+          "type": "string",
+          "description": "[Optional] Log level for backend services. Azure Data Studio generates a file name every time it starts and if the file already exists the logs entries are appended to that file. For cleanup of old log files see logRetentionMinutes and logFilesRemovalLimit settings. The default tracingLevel does not log much. Changing verbosity could lead to extensive logging and disk space requirements for the logs. Error includes Critical, Warning includes Error, Information includes Warning and Verbose includes Information",
+          "default": "Critical",
+          "enum": [
+            "All",
+            "Off",
+            "Critical",
+            "Error",
+            "Warning",
+            "Information",
+            "Verbose"
+          ]
+        },
+        "mssql.logRetentionMinutes": {
+          "type": "number",
+          "default": 10080,
+          "description": "Number of minutes to retain log files for backend services. Default is 1 week."
+        },
+        "mssql.logFilesRemovalLimit": {
+          "type": "number",
+          "default": 100,
+          "description": "Maximum number of old files to remove upon startup that have expired mssql.logRetentionMinutes. Files that do not get cleaned up due to this limitation get cleaned up next time Azure Data Studio starts up."
         },
         "ignorePlatformWarning": {
           "type": "boolean",

extensions/mssql/src/constants.ts

@@ -9,5 +9,4 @@ export const providerId = 'MSSQL';
 export const serviceCrashMessage = 'SQL Tools Service component exited unexpectedly. Please restart Azure Data Studio.';
 export const serviceCrashButton = 'View Known Issues';
 export const serviceCrashLink = 'https://github.com/Microsoft/vscode-mssql/wiki/SqlToolsService-Known-Issues';
-export const configLogDebugInfo = 'logDebugInfo';
+export const extensionConfigSectionName = 'mssql';
-export const extensionConfigSectionName = 'mssql';

extensions/mssql/src/credentialstore/credentialstore.ts

@@ -10,7 +10,6 @@ import { IConfig, ServerProvider } from 'service-downloader';
 import { ServerOptions, RPCMessageType, ClientCapabilities, ServerCapabilities, TransportKind } from 'vscode-languageclient';
 import { Disposable } from 'vscode';
 import * as UUID from 'vscode-languageclient/lib/utils/uuid';
-
 import * as sqlops from 'sqlops';
 
 import * as Contracts from './contracts';
@@ -100,11 +99,7 @@ export class CredentialStore {
 	}
 
 	private generateServerOptions(executablePath: string): ServerOptions {
-		let launchArgs = [];
+		let launchArgs = Utils.getCommonLaunchArgsAndCleanupOldLogFiles('credentialstore', executablePath);
-		launchArgs.push('--log-dir');
-		let logFileLocation = path.join(Utils.getDefaultLogLocation(), 'mssql');
-		launchArgs.push(logFileLocation);
-
 		return { command: executablePath, args: launchArgs, transport: TransportKind.stdio };
 	}
 }

extensions/mssql/src/main.ts

@@ -97,18 +97,7 @@ export async function activate(context: vscode.ExtensionContext) {
 }
 
 function generateServerOptions(executablePath: string): ServerOptions {
-	let launchArgs = [];
+	let launchArgs = Utils.getCommonLaunchArgsAndCleanupOldLogFiles('sqltools', executablePath);
-	launchArgs.push('--log-dir');
-	let logFileLocation = path.join(Utils.getDefaultLogLocation(), 'mssql');
-	launchArgs.push(logFileLocation);
-	let config = vscode.workspace.getConfiguration(Constants.extensionConfigSectionName);
-	if (config) {
-		let logDebugInfo = config[Constants.configLogDebugInfo];
-		if (logDebugInfo) {
-			launchArgs.push('--enable-logging');
-		}
-	}
-
 	return { command: executablePath, args: launchArgs, transport: TransportKind.stdio };
 }
 

extensions/mssql/src/resourceProvider/resourceProvider.ts

@@ -105,11 +105,7 @@ export class AzureResourceProvider {
 	}
 
 	private generateServerOptions(executablePath: string): ServerOptions {
-		let launchArgs = [];
+		let launchArgs = Utils.getCommonLaunchArgsAndCleanupOldLogFiles('resourceprovider', executablePath);
-		launchArgs.push('--log-dir');
-		let logFileLocation = path.join(Utils.getDefaultLogLocation(), 'mssql');
-		launchArgs.push(logFileLocation);
-
 		return { command: executablePath, args: launchArgs, transport: TransportKind.stdio };
 	}
 }

extensions/mssql/src/utils.ts

@@ -7,6 +7,13 @@
 import * as path from 'path';
 import * as crypto from 'crypto';
 import * as os from 'os';
+import {workspace, WorkspaceConfiguration} from 'vscode';
+import * as findRemoveSync from 'find-remove';
+
+const configTracingLevel = 'tracingLevel';
+const configLogRetentionMinutes = 'logRetentionMinutes';
+const configLogFilesRemovalLimit = 'logFilesRemovalLimit';
+const extensionConfigSectionName = 'mssql';
 
 // The function is a duplicate of \src\paths.js. IT would be better to import path.js but it doesn't
 // work for now because the extension is running in different process.
@@ -20,8 +27,69 @@ export function getAppDataPath() {
 	}
 }
 
-export function getDefaultLogLocation() {
+export function removeOldLogFiles(prefix: string) : JSON {
-	return path.join(getAppDataPath(), 'azuredatastudio');
+	return findRemoveSync(getDefaultLogDir(), {prefix: `${prefix}_`,  age: {seconds: getConfigLogRetentionSeconds()}, limit: getConfigLogFilesRemovalLimit()});
+}
+
+export function getConfiguration(config: string = extensionConfigSectionName) : WorkspaceConfiguration {
+	return workspace.getConfiguration(extensionConfigSectionName);
+}
+
+export function getConfigLogFilesRemovalLimit() : number {
+	let config = getConfiguration();
+	if (config) {
+		return Number((config[configLogFilesRemovalLimit]).toFixed(0));
+	}
+	else
+	{
+		return undefined;
+	}
+}
+
+export function getConfigLogRetentionSeconds() : number {
+	let config = getConfiguration();
+	if (config) {
+		return Number((config[configLogRetentionMinutes] * 60).toFixed(0));
+	}
+	else
+	{
+		return undefined;
+	}
+}
+
+export function getConfigTracingLevel() : string {
+	let config = getConfiguration();
+	if (config) {
+		return config[configTracingLevel];
+	}
+	else
+	{
+		return undefined;
+	}
+}
+
+export function getDefaultLogDir() : string {
+	return path.join(process.env['VSCODE_LOGS'], '..', '..','mssql');
+}
+
+export function getDefaultLogFile(prefix: string, pid: number) : string {
+	return path.join(getDefaultLogDir(), `${prefix}_${pid}.log`);
+}
+
+export function getCommonLaunchArgsAndCleanupOldLogFiles(prefix: string, executablePath: string) : string [] {
+	let launchArgs = [];
+	launchArgs.push('--log-file');
+	let logFile = getDefaultLogFile(prefix, process.pid);
+	launchArgs.push(logFile);
+
+	console.log(`logFile for ${path.basename(executablePath)} is ${logFile}`);
+	console.log(`This process (ui Extenstion Host) is pid: ${process.pid}`);
+	// Delete old log files
+	let deletedLogFiles = removeOldLogFiles(prefix);
+	console.log(`Old log files deletion report: ${JSON.stringify(deletedLogFiles)}`);
+	launchArgs.push('--tracing-level');
+	launchArgs.push(getConfigTracingLevel());
+	return launchArgs;
 }
 
 export function ensure(target: object, key: string): any {

package.json

@@ -42,6 +42,7 @@
     "applicationinsights": "0.18.0",
     "chart.js": "^2.6.0",
     "fast-plist": "0.1.2",
+    "find-remove": "1.2.1",
     "fs-extra": "^3.0.1",
     "gc-signals": "^0.0.1",
     "getmac": "1.4.1",

src/vs/workbench/parts/logs/common/logConstants.ts

@@ -6,4 +6,6 @@
 export const mainLogChannelId = 'mainLog';
 export const sharedLogChannelId = 'sharedLog';
 export const rendererLogChannelId = 'rendererLog';
-export const extHostLogChannelId = 'extHostLog';
+export const extHostLogChannelId = 'extHostLog';
+// {{SQL CARBON EDIT}}
+export const sqlToolsLogChannellId = 'sqlToolsLog';

src/vs/workbench/parts/logs/electron-browser/logs.contribution.ts

@@ -18,14 +18,18 @@ import * as Constants from 'vs/workbench/parts/logs/common/logConstants';
 import { IWorkbenchActionRegistry, Extensions as WorkbenchActionExtensions } from 'vs/workbench/common/actions';
 import { SyncActionDescriptor } from 'vs/platform/actions/common/actions';
 import { ShowLogsAction, OpenLogsFolderAction, SetLogLevelAction, OpenLogFileAction } from 'vs/workbench/parts/logs/electron-browser/logsActions';
-
+// {{SQL CARBON EDIT}}
+import { IExtensionService } from 'vs/workbench/services/extensions/common/extensions';
+import { ExtensionService } from 'vs/workbench/services/extensions/electron-browser/extensionService';
 
 class LogOutputChannels extends Disposable implements IWorkbenchContribution {
 
 	constructor(
 		@IWindowService private windowService: IWindowService,
 		@IEnvironmentService private environmentService: IEnvironmentService,
-		@IInstantiationService instantiationService: IInstantiationService
+		@IInstantiationService instantiationService: IInstantiationService,
+		// {{SQL CARBON EDIT}}
+		@IExtensionService private extensionService: ExtensionService
 	) {
 		super();
 		let outputChannelRegistry = Registry.as<IOutputChannelRegistry>(OutputExt.OutputChannels);
@@ -33,6 +37,12 @@ class LogOutputChannels extends Disposable implements IWorkbenchContribution {
 		outputChannelRegistry.registerChannel(Constants.sharedLogChannelId, nls.localize('sharedLog', "Log (Shared)"), URI.file(join(this.environmentService.logsPath, `sharedprocess.log`)));
 		outputChannelRegistry.registerChannel(Constants.rendererLogChannelId, nls.localize('rendererLog', "Log (Window)"), URI.file(join(this.environmentService.logsPath, `renderer${this.windowService.getCurrentWindowId()}.log`)));
 		outputChannelRegistry.registerChannel(Constants.extHostLogChannelId, nls.localize('extensionsLog', "Log (Extension Host)"), URI.file(join(this.environmentService.logsPath, `exthost${this.windowService.getCurrentWindowId()}.log`)));
+		// {{SQL CARBON EDIT}}
+		let extHostPid : number = extensionService.getExtenstionHostProcessId();
+		console.log(`extensionHost process id is ${extHostPid}`);
+		let toolsServiceLogFile : string = join(this.environmentService.logsPath, '..', '..', 'mssql', `sqltools_${extHostPid}.log`);
+		console.log(`SqlTools Log file is: ${toolsServiceLogFile}`);
+		outputChannelRegistry.registerChannel(Constants.sqlToolsLogChannellId, nls.localize('sqlToolsLog', "Log (SqlTools)"), URI.file(toolsServiceLogFile));
 
 		const workbenchActionsRegistry = Registry.as<IWorkbenchActionRegistry>(WorkbenchActionExtensions.WorkbenchActions);
 		const devCategory = nls.localize('developer', "Developer");

src/vs/workbench/parts/logs/electron-browser/logsActions.ts

@@ -52,7 +52,9 @@ export class ShowLogsAction extends Action {
 			{ id: Constants.rendererLogChannelId, label: this.contextService.getWorkspace().name ? nls.localize('rendererProcess', "Window ({0})", this.contextService.getWorkspace().name) : nls.localize('emptyWindow', "Window") },
 			{ id: Constants.extHostLogChannelId, label: nls.localize('extensionHost', "Extension Host") },
 			{ id: Constants.sharedLogChannelId, label: nls.localize('sharedProcess', "Shared") },
-			{ id: Constants.mainLogChannelId, label: nls.localize('mainProcess', "Main") }
+			{ id: Constants.mainLogChannelId, label: nls.localize('mainProcess', "Main") },
+			// {{SQL CARBON EDIT}}
+			{ id: Constants.sqlToolsLogChannellId, label: nls.localize('sqlToolsHost', "SqlTools") }
 		];
 
 		return this.quickOpenService.pick(entries, { placeHolder: nls.localize('selectProcess', "Select Log for Process") })

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

@@ -101,6 +101,11 @@ export class ExtensionHostProcessWorker {
 		}));
 	}
 
+	// {{SQL CARBON EDIT}}
+	public getExtenstionHostProcess(): ChildProcess {
+		return this._extensionHostProcess;
+	}
+
 	public dispose(): void {
 		this.terminate();
 	}

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

@@ -152,6 +152,11 @@ export class ExtensionHostProcessManager extends Disposable {
 		});
 	}
 
+	// {{SQL CARBON EDIT}}
+	public getExtenstionHostProcessWorker(): ExtensionHostProcessWorker {
+		return this._extensionHostProcessWorker;
+	}
+
 	public dispose(): void {
 		if (this._extensionHostProcessWorker) {
 			this._extensionHostProcessWorker.dispose();
@@ -296,6 +301,14 @@ export class ExtensionService extends Disposable implements IExtensionService {
 		}
 	}
 
+	// {{SQL CARBON EDIT}}
+	public getExtenstionHostProcessId(): number {
+		if (this._extensionHostProcessManagers.length !== 1)
+		{
+			this._logOrShowMessage(Severity.Warning, 'Exactly one Extension Host Process Manager was expected');
+		}
+		return this._extensionHostProcessManagers[0].getExtenstionHostProcessWorker().getExtenstionHostProcess().pid;
+	}
 	private startDelayed(lifecycleService: ILifecycleService): void {
 		let started = false;
 		const startOnce = () => {

yarn.lock

@@ -2159,6 +2159,13 @@ find-parent-dir@^0.3.0:
   version "0.3.0"
   resolved "https://registry.yarnpkg.com/find-parent-dir/-/find-parent-dir-0.3.0.tgz#33c44b429ab2b2f0646299c5f9f718f376ff8d54"
 
+find-remove@1.2.1:
+  version "1.2.1"
+  resolved "https://registry.yarnpkg.com/find-remove/-/find-remove-1.2.1.tgz#afd93400d23890e018ea197591e9d850d3d049a2"
+  dependencies:
+    fmerge "1.2.0"
+    rimraf "2.6.2"
+
 find-up@^1.0.0:
   version "1.1.2"
   resolved "https://registry.yarnpkg.com/find-up/-/find-up-1.1.2.tgz#6b2e9822b1a2ce0a60ab64d610eccad53cb24d0f"
@@ -2225,6 +2232,10 @@ flatten@^1.0.2:
   version "1.0.2"
   resolved "https://registry.yarnpkg.com/flatten/-/flatten-1.0.2.tgz#dae46a9d78fbe25292258cc1e780a41d95c03782"
 
+fmerge@1.2.0:
+  version "1.2.0"
+  resolved "https://registry.yarnpkg.com/fmerge/-/fmerge-1.2.0.tgz#36e99d2ae255e3ee1af666b4df780553671cf692"
+
 for-in@^0.1.5:
   version "0.1.5"
   resolved "https://registry.yarnpkg.com/for-in/-/for-in-0.1.5.tgz#007374e2b6d5c67420a1479bdb75a04872b738c4"
@@ -5892,15 +5903,15 @@ right-align@^0.1.1:
   dependencies:
     align-text "^0.1.1"
 
-rimraf@^2.2.8:
+rimraf@2.6.2, rimraf@^2.4.2:
-  version "2.6.1"
+  version "2.6.2"
-  resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.6.1.tgz#c2338ec643df7a1b7fe5c54fa86f57428a55f33d"
+  resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.6.2.tgz#2ed8150d24a16ea8651e6d6ef0f47c4158ce7a36"
   dependencies:
     glob "^7.0.5"
 
-rimraf@^2.4.2:
+rimraf@^2.2.8:
-  version "2.6.2"
+  version "2.6.1"
-  resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.6.2.tgz#2ed8150d24a16ea8651e6d6ef0f47c4158ce7a36"
+  resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-2.6.1.tgz#c2338ec643df7a1b7fe5c54fa86f57428a55f33d"
   dependencies:
     glob "^7.0.5"