Fix offset issue

extension/server/src/connection.ts

@@ -24,57 +24,171 @@ connection.onDidChangeWatchedFiles((params: DidChangeWatchedFilesParams) => {
 	watchedFilesChangeEvent.forEach(editEvent => editEvent(params));
 })
 
+/**
+ * Extracts a clean, decoded filename from a URI for display in logs
+ * Handles URL encoding (e.g., %23 -> #) and removes query parameters
+ */
+export function getDisplayName(uri: string): string {
+	const withoutQuery = uri.split('?')[0];
+	const fileName = withoutQuery.split('/').pop() || uri;
+	return decodeURIComponent(fileName);
+}
+
+// Log level constants and names
+export const LogLevel = {
+	NONE: 0,
+	ERROR: 1,
+	WARN: 2,
+	INFO: 3,
+	DEBUG: 4
+};
+
+const LOG_LEVEL_NAMES = ['NONE', 'ERROR', 'WARN', 'INFO', 'DEBUG'];
+
+let logLevel: number = LogLevel.INFO; // Default to INFO
+
+export function setLogLevel(level: number) {
+	logLevel = Math.max(LogLevel.NONE, Math.min(LogLevel.DEBUG, level)); // Clamp between 0-4
+	const levelName = LOG_LEVEL_NAMES[logLevel] || 'UNKNOWN';
+	logWithTimestamp(`Log level set to ${logLevel} (${levelName})`, LogLevel.NONE);
+}
+
+export async function initializeLogLevel() {
+	try {
+		const config = await connection.workspace.getConfiguration('vscode-rpgle');
+		const logLevelString = config?.logLevel || 'info';
+
+		// Map string to numeric level using LOG_LEVEL_NAMES
+		const levelIndex = LOG_LEVEL_NAMES.findIndex(name => name.toLowerCase() === logLevelString.toLowerCase());
+		const level = levelIndex !== -1 ? levelIndex : LogLevel.INFO;
+
+		setLogLevel(level);
+	} catch (e) {
+		logWithTimestamp(`Failed to read log level setting, using default of INFO`, LogLevel.WARN);
+		setLogLevel(LogLevel.INFO);
+	}
+}
+
+export function logWithTimestamp(message: string, level: number = LogLevel.INFO) {
+	if (level > logLevel) return;
+
+	const now = new Date();
+	const timestamp = now.toTimeString().split(' ')[0] + '.' + now.getMilliseconds().toString().padStart(3, '0');
+	const levelName = LOG_LEVEL_NAMES[level] || 'LOG';
+	console.log(`[${timestamp}] [${levelName}] ${message}`);
+}
+
 export async function validateUri(stringUri: string, scheme = ``) {
+	const startTime = Date.now();
+
 	// First, check local cache
 	const possibleCachedFile = findFile(stringUri, scheme);
-	if (possibleCachedFile) return possibleCachedFile;
+	if (possibleCachedFile) {
+		const duration = Date.now() - startTime;
+		logWithTimestamp(`URI validation: ${stringUri} (${duration}ms, local cache)`, LogLevel.DEBUG);
+		return possibleCachedFile;
+	}
 
-	console.log(`Validating file from server: ${stringUri}`);
+	logWithTimestamp(`URI validation: ${stringUri} (requesting from server...)`, LogLevel.DEBUG);
 
 	// Then reach out to the extension to find it
 	const uri: string|undefined = await connection.sendRequest("getUri", stringUri);
-	if (uri) return uri; 
+	const duration = Date.now() - startTime;
 
+	if (uri) {
+		logWithTimestamp(`URI validation: ${stringUri} -> ${uri} (${duration}ms, server)`, LogLevel.INFO);
+		return uri;
+	}
+
+	logWithTimestamp(`URI validation: ${stringUri} (${duration}ms, NOT FOUND)`, LogLevel.WARN);
 	return;
 }
 
-export async function getFileRequest(uri: string) {
+// Track include files being fetched (to skip debounce on open)
+export const filesBeingFetchedForIncludes = new Set<string>();
+
+export async function getFileRequest(uri: string, skipDebounce: boolean = false) {
+	const startTime = Date.now();
+	const fileName = getDisplayName(uri);
+
 	// First, check if it's local
 	const localCacheDoc = documents.get(uri);
-	if (localCacheDoc) return localCacheDoc.getText();
+	if (localCacheDoc) {
+		const duration = Date.now() - startTime;
+		logWithTimestamp(`File fetch: ${fileName} (${duration}ms, local documents cache)`, LogLevel.DEBUG);
+		return localCacheDoc.getText();
+	}
 
-	console.log(`Fetching file from server: ${uri}`);
+	logWithTimestamp(`File fetch: ${fileName} (requesting from server...)`, LogLevel.DEBUG);
 
-	// If not, then grab it from remote
-	const body: string|undefined = await connection.sendRequest("getFile", uri);
-	if (body) {
-		// TODO.. cache it?
-		return body; 
+	// If this is an include file fetch, track it to skip debounce
+	if (skipDebounce) {
+		filesBeingFetchedForIncludes.add(uri);
 	}
 
-	return;
+	try {
+		// If not, then grab it from remote
+		const body: string|undefined = await connection.sendRequest("getFile", uri);
+		const duration = Date.now() - startTime;
+
+		if (body) {
+			logWithTimestamp(`File fetch: ${fileName} (${duration}ms, ${body.length} bytes from server)`, LogLevel.INFO);
+			// TODO.. cache it?
+			return body;
+		}
+
+		logWithTimestamp(`File fetch: ${fileName} (${duration}ms, NOT FOUND)`, LogLevel.WARN);
+		return;
+	} catch (error) {
+		const duration = Date.now() - startTime;
+		logWithTimestamp(`File fetch: ${fileName} (${duration}ms, ERROR: ${error})`, LogLevel.ERROR);
+		console.error(`File fetch error details for ${uri}:`, error);
+		return;
+	} finally {
+		// Always clean up tracking
+		if (skipDebounce) {
+			filesBeingFetchedForIncludes.delete(uri);
+		}
+	}
 }
 
 export let resolvedMembers: {[baseUri: string]: {[fileKey: string]: IBMiMember}} = {};
 export let resolvedStreamfiles: {[baseUri: string]: {[fileKey: string]: string}} = {};
 
 export async function memberResolve(baseUri: string, member: string, file: string): Promise<IBMiMember|undefined> {
+	// Normalize baseUri by removing query parameters to ensure consistent cache keys
+	const normalizedBaseUri = baseUri.split('?')[0];
 	const fileKey = file+member;
+	const startTime = Date.now();
+
+	// Check cache
+	if (resolvedMembers[normalizedBaseUri] && resolvedMembers[normalizedBaseUri][fileKey]) {
+		const cached = resolvedMembers[normalizedBaseUri][fileKey];
+		const duration = Date.now() - startTime;
+		logWithTimestamp(`Member resolve CACHE HIT: ${file}/${member} -> ${cached.library}/${cached.file}/${cached.name} (${duration}ms)`, LogLevel.DEBUG);
+		return cached;
+	}
 
-	if (resolvedMembers[baseUri] && resolvedMembers[baseUri][fileKey]) return resolvedMembers[baseUri][fileKey];
+	const baseFileName = getDisplayName(normalizedBaseUri);
+	logWithTimestamp(`Member resolve CACHE MISS: ${file}/${member} (baseUri=${baseFileName})`, LogLevel.DEBUG);
 
 	try {
 		const resolvedMember = await queue.add(() => {return connection.sendRequest("memberResolve", [member, file])}) as IBMiMember|undefined;
-		// const resolvedMember = await connection.sendRequest("memberResolve", [member, file]) as IBMiMember|undefined;
+		const duration = Date.now() - startTime;
 
 		if (resolvedMember) {
-			if (!resolvedMembers[baseUri]) resolvedMembers[baseUri] = {};
-			resolvedMembers[baseUri][fileKey] = resolvedMember;
+			logWithTimestamp(`Member resolve SUCCESS: ${file}/${member} -> ${resolvedMember.library}/${resolvedMember.file}/${resolvedMember.name} (${duration}ms)`, LogLevel.DEBUG);
+
+			if (!resolvedMembers[normalizedBaseUri]) resolvedMembers[normalizedBaseUri] = {};
+			resolvedMembers[normalizedBaseUri][fileKey] = resolvedMember;
+		} else {
+			logWithTimestamp(`Member resolve NOT FOUND: ${file}/${member} (${duration}ms)`, LogLevel.WARN);
 		}
 
 		return resolvedMember;
 	} catch (e) {
-		console.log(`Member resolve failed.`);
+		const duration = Date.now() - startTime;
+		logWithTimestamp(`Member resolve ERROR: ${file}/${member} (${duration}ms)`, LogLevel.ERROR);
 		console.log(JSON.stringify({baseUri, member, file}));
 		console.log(e);
 	}
@@ -83,25 +197,44 @@ export async function memberResolve(baseUri: string, member: string, file: strin
 }
 
 export async function streamfileResolve(baseUri: string, base: string[]): Promise<string|undefined> {
+	// Normalize baseUri by removing query parameters to ensure consistent cache keys
+	const normalizedBaseUri = baseUri.split('?')[0];
 	const baseString = base.join(`-`);
-	if (resolvedStreamfiles[baseUri] && resolvedStreamfiles[baseUri][baseString]) return resolvedStreamfiles[baseUri][baseString];
+	const startTime = Date.now();
+
+	// Check cache
+	if (resolvedStreamfiles[normalizedBaseUri] && resolvedStreamfiles[normalizedBaseUri][baseString]) {
+		const cached = resolvedStreamfiles[normalizedBaseUri][baseString];
+		const duration = Date.now() - startTime;
+		const requestingFile = getDisplayName(normalizedBaseUri);
+		logWithTimestamp(`Streamfile resolve CACHE HIT: ${base[0]} (requesting: ${requestingFile}) -> ${cached} (${duration}ms)`, LogLevel.DEBUG);
+		return cached;
+	}
+
+	const requestingFile = getDisplayName(normalizedBaseUri);
+	logWithTimestamp(`Streamfile resolve CACHE MISS: ${base[0]} (requesting: ${requestingFile})`, LogLevel.DEBUG);
 
 	const workspace = await getWorkspaceFolder(baseUri);
 
 	const paths = (workspace ? includePath[workspace.uri] : []) || [];
 
 	try {
 		const resolvedPath = await queue.add(() => {return connection.sendRequest("streamfileResolve", [base, paths])}) as string|undefined;
-		//  const resolvedPath = await connection.sendRequest("streamfileResolve", [base, paths]) as string|undefined;
+		const duration = Date.now() - startTime;
 
 		if (resolvedPath) {
-			if (!resolvedStreamfiles[baseUri]) resolvedStreamfiles[baseUri] = {};
-			resolvedStreamfiles[baseUri][baseString] = resolvedPath;
+			logWithTimestamp(`Streamfile resolve SUCCESS: ${base[0]} (requesting: ${requestingFile}) -> ${resolvedPath} (${duration}ms)`, LogLevel.DEBUG);
+
+			if (!resolvedStreamfiles[normalizedBaseUri]) resolvedStreamfiles[normalizedBaseUri] = {};
+			resolvedStreamfiles[normalizedBaseUri][baseString] = resolvedPath;
+		} else {
+			logWithTimestamp(`Streamfile resolve NOT FOUND: ${base[0]} (requesting: ${requestingFile}) (${duration}ms)`, LogLevel.WARN);
 		}
 
 		return resolvedPath;
 	} catch (e) {
-		console.log(`Streamfile resolve failed.`);
+		const duration = Date.now() - startTime;
+		logWithTimestamp(`Streamfile resolve ERROR: ${base[0]} (requesting: ${requestingFile}) (${duration}ms)`, LogLevel.ERROR);
 		console.log(JSON.stringify({baseUri, base, paths}));
 		console.log(e);
 	}

extension/server/src/providers/linter/index.ts

@@ -9,7 +9,7 @@ import Cache from '../../../../../language/models/cache';
 import documentFormattingProvider from './documentFormatting';
 
 import * as Project from "../project";
-import { connection, getFileRequest, getWorkingDirectory, resolvedMembers, resolvedStreamfiles, validateUri, watchedFilesChangeEvent } from '../../connection';
+import { connection, getDisplayName, getFileRequest, getWorkingDirectory, resolvedMembers, resolvedStreamfiles, validateUri, watchedFilesChangeEvent } from '../../connection';
 import { parseMemberUri } from '../../data';
 
 export let jsonCache: { [uri: string]: string } = {};