Adding logging for loading Object Explorer nodes (#18884)

* Adding logging to connection load and OE load paths

* adding a little more logging to OE

* updating tests

* fixing missing mock arg

* improving log message

src/connectionconfig/connectionconfig.ts

@@ -11,72 +11,117 @@ import { IConnectionConfig } from "./iconnectionconfig";
 import VscodeWrapper from "../controllers/vscodeWrapper";
 import { Deferred } from "../protocol";
 import { ConnectionProfile } from "../models/connectionProfile";
+import { Logger } from "../models/logger";
+import { getConnectionDisplayName } from "../models/connectionInfo";
 
 /**
  * Implements connection profile file storage.
  */
 export class ConnectionConfig implements IConnectionConfig {
-    initialized: Deferred<void> = new Deferred<void>();
+    private logger: Logger;
 
+    initialized: Deferred<void> = new Deferred<void>();
     RootGroupName: string = "ROOT";
 
     /**
      * Constructor.
      */
     public constructor(private _vscodeWrapper?: VscodeWrapper) {
-        if (!this.vscodeWrapper) {
-            this.vscodeWrapper = new VscodeWrapper();
+        if (!this._vscodeWrapper) {
+            this._vscodeWrapper = new VscodeWrapper();
         }
-        void this.assignMissingIds();
-    }
 
-    private get vscodeWrapper(): VscodeWrapper {
-        return this._vscodeWrapper;
+        this.logger = Logger.create(
+            this._vscodeWrapper.outputChannel,
+            "ConnectionConfig",
+        );
+
+        void this.assignMissingIds();
     }
 
-    private set vscodeWrapper(value: VscodeWrapper) {
-        this._vscodeWrapper = value;
+    private getRootGroup(): IConnectionGroup | undefined {
+        const groups: IConnectionGroup[] = this.getGroupsFromSettings();
+        return groups.find((group) => group.name === this.RootGroupName);
     }
 
     private async assignMissingIds(): Promise<void> {
+        let madeChanges = false;
+
         // Connection groups
         const groups: IConnectionGroup[] = this.getGroupsFromSettings();
 
-        // ensure each group has an id
-        groups.forEach((group) => {
-            if (!group.id) {
-                group.id = Utils.generateGuid();
-            }
-        });
-
         // ensure ROOT group exists
-        let rootGroup = groups.find(
-            (group) => group.name === this.RootGroupName,
-        );
+        let rootGroup = this.getRootGroup();
+
         if (!rootGroup) {
             rootGroup = {
                 name: this.RootGroupName,
                 id: Utils.generateGuid(),
             };
+
+            this.logger.logDebug(
+                `Adding missing ROOT group to connection groups`,
+            );
+            madeChanges = true;
             groups.push(rootGroup);
         }
 
+        // Clean up connection groups
+        for (const group of groups) {
+            if (group.id === rootGroup.id) {
+                continue;
+            }
+
+            // ensure each group has an ID
+            if (!group.id) {
+                group.id = Utils.generateGuid();
+                madeChanges = true;
+                this.logger.logDebug(
+                    `Adding missing ID to connection group '${group.name}'`,
+                );
+            }
+
+            // ensure each group is in a group
+            if (!group.groupId) {
+                group.groupId = rootGroup.id;
+                madeChanges = true;
+                this.logger.logDebug(
+                    `Adding missing parentId to connection '${group.name}'`,
+                );
+            }
+        }
+
         // Clean up connection profiles
         const profiles: IConnectionProfile[] = this.getProfilesFromSettings();
 
-        profiles.forEach((profile) => {
-            // ensure each profile has an id
-            ConnectionProfile.addIdIfMissing(profile);
+        for (const profile of profiles) {
+            // ensure each profile has an ID
+            if (ConnectionProfile.addIdIfMissing(profile)) {
+                madeChanges = true;
+                this.logger.logDebug(
+                    `Adding missing ID to connection '${getConnectionDisplayName(profile)}'`,
+                );
+            }
 
             // ensure each profile is in a group
             if (!profile.groupId) {
                 profile.groupId = rootGroup.id;
+                madeChanges = true;
+                this.logger.logDebug(
+                    `Adding missing groupId to connection '${getConnectionDisplayName(profile)}'`,
+                );
             }
-        });
+        }
 
         // Save the changes to settings
-        await this.writeConnectionGroupsToSettings(groups);
-        await this.writeProfilesToSettings(profiles);
+        if (madeChanges) {
+            this.logger.logDebug(
+                `Updates made to connection profiles and groups.  Writing all ${groups.length} group(s) and ${profiles.length} profile(s) to settings.`,
+            );
+
+            await this.writeConnectionGroupsToSettings(groups);
+            await this.writeProfilesToSettings(profiles);
+        }
 
         this.initialized.resolve();
     }
@@ -85,6 +130,13 @@ export class ConnectionConfig implements IConnectionConfig {
      * Add a new connection to the connection config.
      */
     public async addConnection(profile: IConnectionProfile): Promise<void> {
+        if (profile.groupId === undefined) {
+            const rootGroup = this.getRootGroup();
+            if (rootGroup) {
+                profile.groupId = rootGroup.id;
+            }
+        }
+
         let profiles = this.getProfilesFromSettings();
 
         // Remove the profile if already set

src/controllers/mainController.ts

@@ -738,6 +738,7 @@ export default class MainController implements vscode.Disposable {
         const self = this;
         // Register the object explorer tree provider
         this._objectExplorerProvider = new ObjectExplorerProvider(
+            this._vscodeWrapper,
             this._connectionMgr,
         );
         this.objectExplorerTree = vscode.window.createTreeView(

src/models/connectionProfile.ts

@@ -62,6 +62,7 @@ export class ConnectionProfile
             this.server = connectionCredentials.server;
         }
     }
+
     /**
      * Creates a new profile by prompting the user for information.
      * @param prompter that asks user the questions needed to complete a profile
@@ -219,10 +220,13 @@ export class ConnectionProfile
         return undefined;
     }
 
-    public static addIdIfMissing(profile: IConnectionProfile): void {
+    public static addIdIfMissing(profile: IConnectionProfile): boolean {
         if (profile && profile.id === undefined) {
             profile.id = utils.generateGuid();
+            return true;
         }
+
+        return false;
     }
 
     // Assumption: having connection string or server + profile name indicates all requirements were met

src/models/connectionStore.ts

@@ -643,6 +643,10 @@ export class ConnectionStore {
 
         // TODO re-add deduplication logic from old method
 
+        this._logger.logDebug(
+            `readAllConnections: ${connResults.length} connections${includeRecentConnections ? ` (${configConnections.length} from config, ${connResults.length - configConnections.length} from recent)` : "; excluded recent"})`,
+        );
+
         return connResults;
     }
 

src/models/interfaces.ts

@@ -73,7 +73,7 @@ export interface IConnectionProfile extends vscodeMssql.IConnectionInfo {
 export interface IConnectionGroup {
     id: string;
     name: string;
-    parentId?: string;
+    groupId?: string;
     color?: string;
     description?: string;
 }

src/models/logger.ts

@@ -95,9 +95,13 @@ export class Logger implements ILogger {
         return this._piiLogging;
     }
 
-    /** If `mssql.logDebug` is enabled, prints the message to the developer console */
+    /**
+     * Prints at the `verbose` level.
+     * If `mssql.logDebug` is enabled, prints the message to the developer console.
+     **/
     public logDebug(message: string): void {
         Utils.logDebug(message);
+        this.write(LogLevel.Verbose, message);
     }
 
     public critical(msg: any, ...vals: any[]): void {

src/objectExplorer/objectExplorerProvider.ts

@@ -9,6 +9,7 @@ import { ObjectExplorerService } from "./objectExplorerService";
 import { TreeNodeInfo } from "./treeNodeInfo";
 import { Deferred } from "../protocol";
 import { IConnectionInfo } from "vscode-mssql";
+import VscodeWrapper from "../controllers/vscodeWrapper";
 
 export class ObjectExplorerProvider implements vscode.TreeDataProvider<any> {
     private _onDidChangeTreeData: vscode.EventEmitter<any | undefined> =
@@ -19,8 +20,16 @@ export class ObjectExplorerProvider implements vscode.TreeDataProvider<any> {
     private _objectExplorerExists: boolean;
     private _objectExplorerService: ObjectExplorerService;
 
-    constructor(connectionManager: ConnectionManager) {
+    constructor(
+        private _vscodeWrapper: VscodeWrapper,
+        connectionManager: ConnectionManager,
+    ) {
+        if (!_vscodeWrapper) {
+            this._vscodeWrapper = new VscodeWrapper();
+        }
+
         this._objectExplorerService = new ObjectExplorerService(
+            this._vscodeWrapper,
             connectionManager,
             this,
         );

src/objectExplorer/objectExplorerService.ts

@@ -56,6 +56,8 @@ import {
     GetSessionIdRequest,
     GetSessionIdResponse,
 } from "../models/contracts/objectExplorer/getSessionIdRequest";
+import { Logger } from "../models/logger";
+import VscodeWrapper from "../controllers/vscodeWrapper";
 
 function getParentNode(node: TreeNodeType): TreeNodeInfo {
     node = node.parentNode;
@@ -68,6 +70,7 @@ function getParentNode(node: TreeNodeType): TreeNodeInfo {
 
 export class ObjectExplorerService {
     private _client: SqlToolsServiceClient;
+    private _logger: Logger;
     private _currentNode: TreeNodeInfo;
     private _treeNodeToChildrenMap: Map<vscode.TreeItem, vscode.TreeItem[]>;
     private _sessionIdToNodeLabelMap: Map<string, string>;
@@ -83,10 +86,21 @@ export class ObjectExplorerService {
     >;
 
     constructor(
+        private _vscodeWrapper: VscodeWrapper,
         private _connectionManager: ConnectionManager,
         private _objectExplorerProvider: ObjectExplorerProvider,
     ) {
+        if (!_vscodeWrapper) {
+            this._vscodeWrapper = new VscodeWrapper();
+        }
+
         this._client = this._connectionManager.client;
+
+        this._logger = Logger.create(
+            this._vscodeWrapper.outputChannel,
+            "ObjectExplorerService",
+        );
+
         this._treeNodeToChildrenMap = new Map<
             vscode.TreeItem,
             vscode.TreeItem[]
@@ -581,7 +595,7 @@ export class ObjectExplorerService {
     }
 
     /**
-     * Helper to show the Add Connection node
+     * Helper to show the Add Connection node; only displayed when there are no saved connections
      */
     private getAddConnectionNode(): AddConnectionTreeNode[] {
         this._rootTreeNodeArray = [];
@@ -611,6 +625,10 @@ export class ObjectExplorerService {
 
     async getChildren(element?: TreeNodeInfo): Promise<vscode.TreeItem[]> {
         if (element) {
+            this._logger.logDebug(
+                `Getting children for node '${element.nodePath}'`,
+            );
+
             // set current node for very first expansion of disconnected node
             if (this._currentNode !== element) {
                 this._currentNode = element;
@@ -668,24 +686,34 @@ export class ObjectExplorerService {
                 }
             }
         } else {
-            // retrieve saved connections first when opening object explorer
-            // for the first time
+            this._logger.logDebug("Getting root OE nodes");
+
+            // retrieve saved connections first when opening object explorer for the first time
             let savedConnections =
                 this._connectionManager.connectionStore.readAllConnections();
-            // if there are no saved connections
-            // show the add connection node
+
+            // if there are no saved connections, show the add connection node
             if (savedConnections.length === 0) {
+                this._logger.logDebug(
+                    "No saved connections found; displaying 'Add Connection' node",
+                );
                 return this.getAddConnectionNode();
             }
-            // if OE doesn't exist the first time
-            // then build the nodes off of saved connections
+
+            // if OE doesn't exist the first time, then build the nodes off of saved connections
             if (!this._objectExplorerProvider.objectExplorerExists) {
                 // if there are actually saved connections
                 this._rootTreeNodeArray = [];
                 await this.addSavedNodesConnectionsToRoot();
+                this._logger.logDebug(
+                    `No current OE; added ${this._rootTreeNodeArray.length} nodes to OE root`,
+                );
                 this._objectExplorerProvider.objectExplorerExists = true;
                 return this.sortByServerName(this._rootTreeNodeArray);
             } else {
+                this._logger.logDebug(
+                    `Returning cached OE root nodes (${this._rootTreeNodeArray.length})`,
+                );
                 // otherwise returned the cached nodes
                 return this.sortByServerName(this._rootTreeNodeArray);
             }
@@ -1085,7 +1113,8 @@ export class ObjectExplorerService {
         }
     }
 
-    /** Getters */
+    //#region Getters and Setters
+
     public get currentNode(): TreeNodeInfo {
         return this._currentNode;
     }
@@ -1101,10 +1130,9 @@ export class ObjectExplorerService {
         return connections;
     }
 
-    /**
-     * Setters
-     */
     public set currentNode(node: TreeNodeInfo) {
         this._currentNode = node;
     }
+
+    //#endregion
 }