Add debug logging

Author: Sander Ronde

client/src/extension.ts

@@ -18,6 +18,7 @@ import type {
 	ServerOptions,
 } from 'vscode-languageclient/node';
 import { LanguageClient, TransportKind } from 'vscode-languageclient/node';
+import { debug, initDebugReceiver } from './notificationReceivers/debug';
 import { DocumentManager } from './notificationSenders/documentManager';
 import { ErrorManager } from './notificationReceivers/errorManager';
 import { ZombieKiller } from './notificationReceivers/zombieKiller';
@@ -85,11 +86,13 @@ async function startLanguageServer(
 
 export async function activate(context: ExtensionContext): Promise<void> {
 	log(context, CLIENT_PREFIX, 'Initializing PHPStan extension');
+	debug('lifecycle', 'Initializing PHPStan extension');
 	const outputChannel = createOutputChannel();
 
 	const telemetry = new Telemetry();
 	telemetry.report(context);
 	const client = await startLanguageServer(context, outputChannel);
+	initDebugReceiver(client);
 	const statusBar = new StatusBar(context, client);
 	const watcher = new DocumentManager(client);
 	const errorManager = new ErrorManager(client);

client/src/lib/commands.ts

@@ -8,8 +8,10 @@ import { commands, Commands } from '../../../shared/commands/defs';
 // eslint-disable-next-line node/no-extraneous-import
 import { autoRegisterCommand } from 'vscode-generate-package-json';
 import type { LanguageClient } from 'vscode-languageclient/node';
+import { getDebugData } from '../notificationReceivers/debug';
 import { getEditorConfiguration } from './editorConfig';
 import { showError } from './errorUtil';
+
 import { launchSetup } from './setup';
 import * as vscode from 'vscode';
 
@@ -151,4 +153,24 @@ export function registerListeners(
 			}
 		)
 	);
+
+	context.subscriptions.push(
+		autoRegisterCommand(
+			Commands.DOWNLOAD_DEBUG_DATA,
+			async () => {
+				const debugData = getDebugData();
+				const json = JSON.stringify(debugData, null, '\t');
+				const timestamp = Date.now();
+				const uri = vscode.Uri.joinPath(
+					vscode.workspace.workspaceFolders?.[0]?.uri ??
+						vscode.Uri.file(''),
+					`phpstan-vscode-debug-${timestamp}.json`
+				);
+				await vscode.workspace.fs.writeFile(uri, Buffer.from(json));
+
+				await vscode.commands.executeCommand('vscode.open', uri);
+			},
+			commands
+		)
+	);
 }

client/src/lib/notificationChannels.ts

@@ -1,5 +1,6 @@
 import type {
 	CommandNotificationType,
+	DebugNotificationType,
 	ErrorNotificationType,
 	LogNotificationType,
 	PHPStanProNotificationType,
@@ -36,3 +37,6 @@ export const phpstanProNotification =
 	new NotificationType<PHPStanProNotificationType>(
 		NotificationChannel.PHPSTAN_PRO
 	);
+export const debugNotification = new NotificationType<DebugNotificationType>(
+	NotificationChannel.DEBUG
+);

client/src/notificationReceivers/debug.ts

@@ -0,0 +1,38 @@
+import type { LanguageClient } from 'vscode-languageclient/node';
+
+import { debugNotification } from '../lib/notificationChannels';
+import type { Disposable } from 'vscode';
+
+const sessionDebugData: {
+	type: string;
+	data: unknown[];
+	timestamp: string;
+	timestampMs: number;
+}[] = [];
+
+export function debug(type: string, ...data: unknown[]): void {
+	const now = new Date();
+	sessionDebugData.push({
+		type,
+		data,
+		timestamp: now.toISOString(),
+		timestampMs: now.getTime(),
+	});
+}
+
+export function initDebugReceiver(client: LanguageClient): Disposable {
+	return client.onNotification(debugNotification, (params) => {
+		debug(params.debugData.type, ...params.debugData.data);
+	});
+}
+
+export function getDebugData(): {
+	type: string;
+	data: unknown[];
+	timestamp: string;
+	timestampMs: number;
+}[] {
+	return sessionDebugData;
+}
+
+export * from '../../../shared/debug';

client/src/notificationReceivers/statusBar.ts

@@ -8,6 +8,7 @@ import { assertUnreachable } from '../../../shared/util';
 import { log, STATUS_BAR_PREFIX } from '../lib/log';
 import type { Disposable } from 'vscode';
 import * as vscode from 'vscode';
+import { debug } from './debug';
 
 export class StatusBar implements Disposable {
 	private _runningOperation: {
@@ -36,6 +37,9 @@ export class StatusBar implements Disposable {
 					"notification:'",
 					JSON.stringify(params)
 				);
+				debug('statusBar', {
+					params,
+				});
 
 				if (!getEditorConfiguration().get('phpstan.enableStatusBar')) {
 					return;

client/src/notificationSenders/documentManager.ts

@@ -1,10 +1,12 @@
 import type { WatcherNotificationFileData } from '../../../shared/notificationChannels';
+import { debug, sanitizeFilePath } from '../notificationReceivers/debug';
 import { watcherNotification } from '../lib/notificationChannels';
 import type { LanguageClient } from 'vscode-languageclient/node';
 import { getEditorConfiguration } from '../lib/editorConfig';
 import type { Disposable } from 'vscode';
+import { createHash } from 'crypto';
+import * as fs from 'fs/promises';
 import * as vscode from 'vscode';
-
 type PartialDocument = Pick<
 	vscode.TextDocument,
 	'uri' | 'getText' | 'isDirty' | 'languageId'
@@ -54,11 +56,18 @@ export class DocumentManager implements Disposable {
 
 	private async _onDocumentChange(e: vscode.TextDocument): Promise<void> {
 		if (this._isConfigFile(e)) {
+			debug('configChange', {
+				filePath: sanitizeFilePath(e.uri.fsPath),
+			});
 			await this._client.sendNotification(watcherNotification, {
 				operation: 'onConfigChange',
 			});
 		}
 		if (this._shouldSyncDocument(e)) {
+			debug('documentChange', {
+				checking: true,
+				filePath: sanitizeFilePath(e.uri.fsPath),
+			});
 			await this._client.sendNotification(watcherNotification, {
 				operation: 'change',
 				file: this._toSendData(e),
@@ -67,16 +76,40 @@ export class DocumentManager implements Disposable {
 	}
 
 	private async _onDocumentSave(e: vscode.TextDocument): Promise<void> {
-		if (this._shouldSyncDocument(e)) {
+		const fileContents = e.getText();
+		const fileContentsHash = createHash('sha256')
+			.update(fileContents)
+			.digest('hex');
+		const onDiskContents = await fs.readFile(e.uri.fsPath, 'utf-8');
+		const onDiskContentsHash = createHash('sha256')
+			.update(onDiskContents)
+			.digest('hex');
+		if (fileContentsHash !== onDiskContentsHash) {
+			debug('documentSave', {
+				filePath: sanitizeFilePath(e.uri.fsPath),
+			});
 			await this._client.sendNotification(watcherNotification, {
 				operation: 'save',
 				file: this._toSendData(e),
 			});
+			const postSaveContents = await fs.readFile(e.uri.fsPath, 'utf-8');
+			const postSaveContentsHash = createHash('sha256')
+				.update(postSaveContents)
+				.digest('hex');
+			debug('documentSave', {
+				filePath: sanitizeFilePath(e.uri.fsPath),
+				postSaveContentsHash,
+				fileContentsHash,
+				onDiskContentsHash,
+			});
 		}
 	}
 
 	private async _onDocumentActive(e: vscode.TextDocument): Promise<void> {
 		if (this._shouldSyncDocument(e)) {
+			debug('documentActive', {
+				filePath: sanitizeFilePath(e.uri.fsPath),
+			});
 			await this._client.sendNotification(watcherNotification, {
 				operation: 'setActive',
 				file: this._toSendData(e),
@@ -89,6 +122,10 @@ export class DocumentManager implements Disposable {
 		check: boolean
 	): Promise<void> {
 		if (this._shouldSyncDocument(e)) {
+			debug('documentOpen', {
+				filePath: sanitizeFilePath(e.uri.fsPath),
+				check,
+			});
 			await this._client.sendNotification(watcherNotification, {
 				operation: 'open',
 				file: this._toSendData(e),
@@ -99,6 +136,9 @@ export class DocumentManager implements Disposable {
 
 	private async _onDocumentClose(e: PartialDocument): Promise<void> {
 		if (this._shouldSyncDocument(e)) {
+			debug('documentClose', {
+				filePath: sanitizeFilePath(e.uri.fsPath),
+			});
 			await this._client.sendNotification(watcherNotification, {
 				operation: 'close',
 				file: this._toSendData(e),
@@ -107,6 +147,7 @@ export class DocumentManager implements Disposable {
 	}
 
 	public async watch(): Promise<void> {
+		debug('watch', 'Starting document watch');
 		await Promise.all(
 			vscode.workspace.textDocuments.map((doc) => {
 				return this._onDocumentOpen(doc, false);
@@ -153,6 +194,7 @@ export class DocumentManager implements Disposable {
 	}
 
 	public dispose(): void {
+		debug('dispose', 'Disposing document manager');
 		this._disposables.forEach((d) => void d.dispose());
 		this._disposables = [];
 	}

package.json

@@ -207,6 +207,10 @@
 				"command": "phpstan.launchSetup",
 				"title": "Launch setup"
 			},
+			{
+				"command": "phpstan.downloadDebugData",
+				"title": "Download debug data"
+			},
 			{
 				"command": "cmd.phpstan.scanFileForErrors",
 				"title": "PHPStan: Scan current file for errors"
@@ -234,6 +238,10 @@
 			{
 				"command": "cmd.phpstan.launchSetup",
 				"title": "PHPStan: Launch setup"
+			},
+			{
+				"command": "cmd.phpstan.downloadDebugData",
+				"title": "PHPStan: Download debug data"
 			}
 		],
 		"menus": {
@@ -266,6 +274,10 @@
 					"command": "phpstan.launchSetup",
 					"when": "false"
 				},
+				{
+					"command": "phpstan.downloadDebugData",
+					"when": "false"
+				},
 				{
 					"command": "cmd.phpstan.scanFileForErrors",
 					"when": "true"
@@ -293,6 +305,10 @@
 				{
 					"command": "cmd.phpstan.launchSetup",
 					"when": "true"
+				},
+				{
+					"command": "cmd.phpstan.downloadDebugData",
+					"when": "true"
 				}
 			]
 		},

server/src/lib/debug.ts

@@ -0,0 +1,17 @@
+import { debugNotification } from './notificationChannels';
+import type { _Connection } from 'vscode-languageserver';
+
+export function debug(
+	connection: _Connection,
+	type: string,
+	...data: unknown[]
+): void {
+	void connection.sendNotification(debugNotification, {
+		debugData: {
+			type,
+			data,
+		},
+	});
+}
+
+export * from '../../../shared/debug';

server/src/lib/documentManager.ts

@@ -8,6 +8,7 @@ import type { Disposable } from 'vscode-languageserver';
 import { getEditorConfiguration } from './editorConfig';
 import type { Watcher } from './watcher';
 import * as phpParser from 'php-parser';
+import { debug } from '../lib/debug';
 import { URI } from 'vscode-uri';
 
 class DocumentManagerFileData implements WatcherNotificationFileData {
@@ -98,6 +99,9 @@ export class DocumentManager implements AsyncDisposable {
 					watcherNotification,
 					// eslint-disable-next-line @typescript-eslint/no-misused-promises
 					async (data) => {
+						debug(this._classConfig.connection, 'documentManager', {
+							data,
+						});
 						switch (data.operation) {
 							case 'close':
 								this._documents.delete(data.file.uri);

server/src/lib/notificationChannels.ts

@@ -1,5 +1,6 @@
 import type {
 	CommandNotificationType,
+	DebugNotificationType,
 	ErrorNotificationType,
 	LogNotificationType,
 	PHPStanProNotificationType,
@@ -36,3 +37,7 @@ export const phpstanProNotification =
 	new NotificationType<PHPStanProNotificationType>(
 		NotificationChannel.PHPSTAN_PRO
 	);
+
+export const debugNotification = new NotificationType<DebugNotificationType>(
+	NotificationChannel.DEBUG
+);