Add logging to try and find a possible connection race condition (#5813)

* Add logging to try and find a possible connection race condition

* Fix tests

* More test fixes

* Update error message and use error level

src/sql/platform/connection/common/connectionManagementService.ts

@@ -51,6 +51,8 @@ import { ILogService } from 'vs/platform/log/common/log';
 import * as interfaces from './interfaces';
 import { IStorageService, StorageScope } from 'vs/platform/storage/common/storage';
 import { Memento } from 'vs/workbench/common/memento';
+import { IEnvironmentService } from 'vs/platform/environment/common/environment';
+import { INotificationService } from 'vs/platform/notification/common/notification';
 
 export class ConnectionManagementService extends Disposable implements IConnectionManagementService {
 
@@ -61,7 +63,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 
 	private _uriToProvider: { [uri: string]: string; } = Object.create(null);
 
-	private _connectionStatusManager = new ConnectionStatusManager(this._capabilitiesService);
+	private _connectionStatusManager = new ConnectionStatusManager(this._capabilitiesService, this._logService, this._environmentService, this._notificationService);
 
 	private _onAddConnectionProfile = new Emitter<IConnectionProfile>();
 	private _onDeleteConnectionProfile = new Emitter<void>();
@@ -90,8 +92,10 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 		@IResourceProviderService private _resourceProviderService: IResourceProviderService,
 		@IAngularEventingService private _angularEventing: IAngularEventingService,
 		@IAccountManagementService private _accountManagementService: IAccountManagementService,
-		@ILogService private logService: ILogService,
+		@ILogService private _logService: ILogService,
-		@IStorageService private _storageService: IStorageService
+		@IStorageService private _storageService: IStorageService,
+		@IEnvironmentService private _environmentService: IEnvironmentService,
+		@INotificationService private _notificationService: INotificationService
 	) {
 		super();
 
@@ -194,7 +198,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 			self._connectionDialogService.showDialog(self, params, model, connectionResult, options).then(() => {
 				resolve();
 			}, dialogError => {
-				this.logService.warn('failed to open the connection dialog. error: ' + dialogError);
+				this._logService.warn('failed to open the connection dialog. error: ' + dialogError);
 				reject(dialogError);
 			});
 		});
@@ -353,7 +357,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 
 		if (uri !== input.uri) {
 			//TODO: this should never happen. If the input is already passed, it should have the uri
-			this.logService.warn(`the given uri is different that the input uri. ${uri}|${input.uri}`);
+			this._logService.warn(`the given uri is different that the input uri. ${uri}|${input.uri}`);
 		}
 		return this.tryConnect(connection, input, options);
 	}
@@ -662,7 +666,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	}
 
 	public saveProfileGroup(profile: IConnectionProfileGroup): Promise<string> {
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.AddServerGroup);
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.AddServerGroup);
 		return new Promise<string>((resolve, reject) => {
 			this._connectionStore.saveProfileGroup(profile).then(groupId => {
 				this._onAddConnectionProfile.fire(undefined);
@@ -896,7 +900,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	}
 
 	private addTelemetryForConnection(connection: ConnectionManagementInfo): void {
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.DatabaseConnected, {
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.DatabaseConnected, {
 			connectionType: connection.serverInfo ? (connection.serverInfo.isCloud ? 'Azure' : 'Standalone') : '',
 			provider: connection.connectionProfile.providerName,
 			serverVersion: connection.serverInfo ? connection.serverInfo.serverVersion : '',
@@ -908,7 +912,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	}
 
 	private addTelemetryForConnectionDisconnected(connection: IConnectionProfile): void {
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.DatabaseDisconnected, {
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.DatabaseDisconnected, {
 			provider: connection.providerName
 		});
 	}
@@ -953,13 +957,13 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	}
 
 	public changeGroupIdForConnectionGroup(source: ConnectionProfileGroup, target: ConnectionProfileGroup): Promise<void> {
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.MoveServerConnection);
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.MoveServerConnection);
 		return this._connectionStore.changeGroupIdForConnectionGroup(source, target);
 	}
 
 	public changeGroupIdForConnection(source: ConnectionProfile, targetGroupId: string): Promise<void> {
 		let id = Utils.generateUri(source);
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.MoveServerGroup);
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.MoveServerGroup);
 		return this._connectionStore.changeGroupIdForConnection(source, targetGroupId).then(result => {
 			if (id && targetGroupId) {
 				source.groupId = targetGroupId;
@@ -1024,7 +1028,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	// Connect an open URI to a connection profile
 	private createNewConnection(uri: string, connection: IConnectionProfile): Promise<IConnectionResult> {
 		const self = this;
-
+		this._logService.info(`Creating new connection ${uri}`);
 		return new Promise<IConnectionResult>((resolve, reject) => {
 			let connectionInfo = this._connectionStatusManager.addConnection(connection, uri);
 			// Setup the handler for the connection complete notification to call
@@ -1242,7 +1246,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	 */
 	public deleteConnection(connection: ConnectionProfile): Promise<boolean> {
 
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.DeleteConnection, {}, connection);
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.DeleteConnection, {}, connection);
 		// Disconnect if connected
 		let uri = Utils.generateUri(connection);
 		if (this.isConnected(uri) || this.isConnecting(uri)) {
@@ -1280,7 +1284,7 @@ export class ConnectionManagementService extends Disposable implements IConnecti
 	 * Disconnects a connection before removing from config. If disconnect fails, settings is not modified.
 	 */
 	public deleteConnectionGroup(group: ConnectionProfileGroup): Promise<boolean> {
-		TelemetryUtils.addTelemetry(this._telemetryService, this.logService, TelemetryKeys.DeleteServerGroup);
+		TelemetryUtils.addTelemetry(this._telemetryService, this._logService, TelemetryKeys.DeleteServerGroup);
 		// Get all connections for this group
 		let connections = ConnectionProfileGroup.getConnectionsInGroup(group);
 

src/sql/platform/connection/common/connectionStatusManager.ts

@@ -7,15 +7,23 @@ import { ConnectionManagementInfo } from 'sql/platform/connection/common/connect
 import { ICapabilitiesService } from 'sql/platform/capabilities/common/capabilitiesService';
 import { ConnectionProfile } from 'sql/platform/connection/common/connectionProfile';
 import { IConnectionProfile } from 'sql/platform/connection/common/interfaces';
+import { StopWatch } from 'vs/base/common/stopwatch';
+import { ILogService } from 'vs/platform/log/common/log';
+import { IEnvironmentService } from 'vs/platform/environment/common/environment';
+import { join } from 'vs/base/common/path';
 import * as Utils from 'sql/platform/connection/common/utils';
 import * as azdata from 'azdata';
-import { StopWatch } from 'vs/base/common/stopwatch';
+import { INotificationService, Severity } from 'vs/platform/notification/common/notification';
 
 export class ConnectionStatusManager {
 
 	private _connections: { [id: string]: ConnectionManagementInfo };
 
-	constructor(@ICapabilitiesService private _capabilitiesService: ICapabilitiesService) {
+	constructor(
+		@ICapabilitiesService private _capabilitiesService: ICapabilitiesService,
+		@ILogService private _logService: ILogService,
+		@IEnvironmentService private _environmentService: IEnvironmentService,
+		@INotificationService private _notificationService: INotificationService) {
 		this._connections = {};
 	}
 
@@ -46,8 +54,10 @@ export class ConnectionStatusManager {
 			for (let key in this._connections) {
 				if (this._connections[key].connectionId === info.connectionId) {
 					if (this._connections[key].connecting) {
+						this._logService.info(`Deleting connection ${id} (connecting)`);
 						this._connections[key].deleted = true;
 					} else {
+						this._logService.info(`Deleting connection ${id}`);
 						delete this._connections[key];
 					}
 				}
@@ -61,6 +71,7 @@ export class ConnectionStatusManager {
 	}
 
 	public addConnection(connection: IConnectionProfile, id: string): ConnectionManagementInfo {
+		this._logService.info(`Adding connection ${id}`);
 		// Always create a copy and save that in the list
 		let connectionProfile = new ConnectionProfile(this._capabilitiesService, connection);
 		let connectionInfo: ConnectionManagementInfo = new ConnectionManagementInfo();
@@ -72,7 +83,7 @@ export class ConnectionStatusManager {
 		this._connections[id] = connectionInfo;
 		connectionInfo.serviceTimer = StopWatch.create();
 		connectionInfo.ownerUri = id;
-
+		this._logService.info(`Successfully added connection ${id}`);
 		return connectionInfo;
 	}
 
@@ -81,6 +92,7 @@ export class ConnectionStatusManager {
 	 * @param uri Remove connection from list of active connections
 	 */
 	public removeConnection(uri: string) {
+		this._logService.info(`Removing connection ${uri}`);
 		delete this._connections[uri];
 	}
 
@@ -99,6 +111,7 @@ export class ConnectionStatusManager {
 				newId = Utils.generateUri(connection);
 				if (newId !== id) {
 					this.deleteConnection(id);
+					this._logService.info(`Adding connection (update) ${newId} (old=${id})`);
 					this._connections[newId] = connectionInfo;
 				}
 			}
@@ -109,6 +122,15 @@ export class ConnectionStatusManager {
 
 	public onConnectionComplete(summary: azdata.ConnectionInfoSummary): ConnectionManagementInfo {
 		let connection = this._connections[summary.ownerUri];
+		if (!connection) {
+			this._logService.error(`OnConnectionComplete but no connection found '${summary.ownerUri}' Connections = [${Object.keys(this._connections)}]`);
+			this._notificationService.notify({
+				severity: Severity.Error,
+				message: `An unexpected error occurred while connecting. Please [file an issue](command:workbench.action.openIssueReporter) with the title 'Unexpected Error Occurred while Connecting' and include the log file [${join(this._environmentService.logsPath, 'renderer1.log')}](command:workbench.action.openLogsFolder)`
+			});
+			// Bail out at this point - there's nothing else we can do since this is an unexpected state.
+			throw new Error('Unexpected error occurred while connecting.');
+		}
 		connection.serviceTimer.stop();
 		connection.connecting = false;
 		connection.connectionId = summary.connectionId;
@@ -130,6 +152,7 @@ export class ConnectionStatusManager {
 			let prefix = Utils.getUriPrefix(summary.ownerUri);
 			let ownerUriWithDbName = Utils.generateUriWithPrefix(connection.connectionProfile, prefix);
 			if (!(ownerUriWithDbName in this._connections)) {
+				this._logService.info(`Adding connection with DB name ${ownerUriWithDbName}`);
 				this._connections[ownerUriWithDbName] = connection;
 			}
 		}

src/sqltest/parts/connection/connectionManagementService.test.ts

@@ -32,7 +32,8 @@ import * as TypeMoq from 'typemoq';
 import { IConnectionProfileGroup, ConnectionProfileGroup } from 'sql/platform/connection/common/connectionProfileGroup';
 import { ConnectionProfile } from 'sql/platform/connection/common/connectionProfile';
 import { AccountManagementTestService } from 'sqltest/stubs/accountManagementStubs';
-import { TestStorageService } from 'vs/workbench/test/workbenchTestServices';
+import { TestStorageService, TestEnvironmentService, TestLogService } from 'vs/workbench/test/workbenchTestServices';
+import { TestNotificationService } from 'vs/platform/notification/test/common/testNotificationService';
 
 suite('SQL ConnectionManagementService tests', () => {
 
@@ -85,7 +86,7 @@ suite('SQL ConnectionManagementService tests', () => {
 		connectionStore = TypeMoq.Mock.ofType(ConnectionStore, TypeMoq.MockBehavior.Loose, new TestStorageService());
 		workbenchEditorService = TypeMoq.Mock.ofType(WorkbenchEditorTestService);
 		editorGroupService = TypeMoq.Mock.ofType(EditorGroupTestService);
-		connectionStatusManager = new ConnectionStatusManager(capabilitiesService);
+		connectionStatusManager = new ConnectionStatusManager(capabilitiesService, new TestLogService(), TestEnvironmentService, new TestNotificationService());
 		mssqlConnectionProvider = TypeMoq.Mock.ofType(ConnectionProviderStub);
 		let resourceProviderStub = new ResourceProviderStub();
 		resourceProviderStubMock = TypeMoq.Mock.ofInstance(resourceProviderStub);
@@ -151,19 +152,21 @@ suite('SQL ConnectionManagementService tests', () => {
 		let connectionManagementService = new ConnectionManagementService(
 			connectionStore.object,
 			connectionDialogService.object,
-			undefined,
+			undefined, // IServerGroupController
-			undefined,
+			undefined, // IInstantiationService
 			workbenchEditorService.object,
-			undefined,
+			undefined, // ITelemetryService
 			workspaceConfigurationServiceMock.object,
 			capabilitiesService,
-			undefined,
+			undefined, // IQuickInputService
-			undefined,
+			undefined, // IStatusbarService
 			resourceProviderStubMock.object,
-			undefined,
+			undefined, // IAngularEventingService
 			accountManagementService.object,
-			undefined,
+			new TestLogService(), // ILogService
-			undefined
+			undefined, // IStorageService
+			TestEnvironmentService,
+			new TestNotificationService()
 		);
 		return connectionManagementService;
 	}

src/sqltest/parts/connection/connectionStatusManager.test.ts

@@ -10,6 +10,8 @@ import * as Utils from 'sql/platform/connection/common/utils';
 import { IConnectionProfile } from 'sql/platform/connection/common/interfaces';
 import { CapabilitiesTestService } from 'sqltest/stubs/capabilitiesTestService';
 import { ConnectionProfile } from 'sql/platform/connection/common/connectionProfile';
+import { TestEnvironmentService, TestLogService } from 'vs/workbench/test/workbenchTestServices';
+import { TestNotificationService } from 'vs/platform/notification/test/common/testNotificationService';
 import { mssqlProviderName } from 'sql/platform/connection/common/constants';
 
 let connections: ConnectionStatusManager;
@@ -75,7 +77,7 @@ suite('SQL ConnectionStatusManager tests', () => {
 	setup(() => {
 		capabilitiesService = new CapabilitiesTestService();
 		connectionProfileObject = new ConnectionProfile(capabilitiesService, connectionProfile);
-		connections = new ConnectionStatusManager(capabilitiesService);
+		connections = new ConnectionStatusManager(capabilitiesService, new TestLogService(), TestEnvironmentService, new TestNotificationService());
 		connection1Id = Utils.generateUri(connectionProfile);
 		connection2Id = 'connection2Id';
 		connection3Id = 'connection3Id';