From d33e88dac5955071e7f6c2934cf0faf3c21598f9 Mon Sep 17 00:00:00 2001 From: Richard Moulton Date: Thu, 30 Oct 2025 15:51:30 +0000 Subject: [PATCH 1/4] Add debouncing to document change handler to fix offset issues Prevents multiple concurrent parse operations during live editing that were causing duplicate definitions with incorrect offsets, resulting in false linter errors about variable name casing. --- extension/server/src/server.ts | 41 +++++++++++++++++++++++----------- 1 file changed, 28 insertions(+), 13 deletions(-) diff --git a/extension/server/src/server.ts b/extension/server/src/server.ts index 8809ab44..d6893d55 100644 --- a/extension/server/src/server.ts +++ b/extension/server/src/server.ts @@ -323,21 +323,36 @@ if (languageToolsEnabled) { if (isLinterEnabled()) Linter.initialise(connection); +// Debounce timers for document changes +const documentChangeTimers: { [uri: string]: NodeJS.Timeout } = {}; + // Always get latest stuff documents.onDidChangeContent(handler => { - parser.getDocs( - handler.document.uri, - handler.document.getText(), - { - withIncludes: true, - ignoreCache: true, - collectReferences: true - } - ).then(cache => { - if (cache) { - Linter.refreshLinterDiagnostics(handler.document, cache); - } - }); + const uri = handler.document.uri; + + // Clear any existing timer for this document + if (documentChangeTimers[uri]) { + clearTimeout(documentChangeTimers[uri]); + } + + // Set a new timer to parse after a short delay (500ms) + documentChangeTimers[uri] = setTimeout(() => { + delete documentChangeTimers[uri]; + + parser.getDocs( + uri, + handler.document.getText(), + { + withIncludes: true, + ignoreCache: true, + collectReferences: true + } + ).then(cache => { + if (cache) { + Linter.refreshLinterDiagnostics(handler.document, cache); + } + }); + }, 500); }); // Make the text document manager listen on the connection From 6b6624ab1185e3f7053ceb6adde533a501689481 Mon Sep 17 00:00:00 2001 From: Richard Moulton Date: Fri, 31 Oct 2025 17:24:39 +0000 Subject: [PATCH 2/4] Enhance debouncing with parse state tracking and validation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Improves the offset issue fix by adding parse ID tracking to invalidate stale parse operations, a parsing flag to prevent concurrent parses, error handling, and reduces debounce time from 500ms to 300ms for better responsiveness. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- extension/server/src/server.ts | 56 ++++++++++++++++++++++++++-------- 1 file changed, 43 insertions(+), 13 deletions(-) diff --git a/extension/server/src/server.ts b/extension/server/src/server.ts index d6893d55..b38eea42 100644 --- a/extension/server/src/server.ts +++ b/extension/server/src/server.ts @@ -203,7 +203,7 @@ parser.setIncludeFileFetch(async (stringUri: string, includeString: string) => { // Resolving IFS path from member or streamfile // IFS fetch - + if (cleanString.startsWith(`/`)) { // Path from root validUri = URI.from({ @@ -217,7 +217,7 @@ parser.setIncludeFileFetch(async (stringUri: string, includeString: string) => { // - `${cleanString}.rpgleinc` // - `${cleanString}.rpgle` const possibleFiles = [cleanString, `${cleanString}.rpgleinc`, `${cleanString}.rpgle`]; - + // Path from home directory? const foundStreamfile = await streamfileResolve(stringUri, possibleFiles); @@ -295,7 +295,7 @@ parser.setIncludeFileFetch(async (stringUri: string, includeString: string) => { } } - + fetchingInProgress[includeString] = false; return { @@ -323,21 +323,45 @@ if (languageToolsEnabled) { if (isLinterEnabled()) Linter.initialise(connection); -// Debounce timers for document changes -const documentChangeTimers: { [uri: string]: NodeJS.Timeout } = {}; +// Track parsing state for each document +const documentParseState: { + [uri: string]: { + timer?: NodeJS.Timeout, + parseId: number, + parsing: boolean + } +} = {}; // Always get latest stuff documents.onDidChangeContent(handler => { const uri = handler.document.uri; - // Clear any existing timer for this document - if (documentChangeTimers[uri]) { - clearTimeout(documentChangeTimers[uri]); + // Initialize state if needed + if (!documentParseState[uri]) { + documentParseState[uri] = { parseId: 0, parsing: false }; + } + + const state = documentParseState[uri]; + + // Clear any existing timer + if (state.timer) { + clearTimeout(state.timer); } - // Set a new timer to parse after a short delay (500ms) - documentChangeTimers[uri] = setTimeout(() => { - delete documentChangeTimers[uri]; + // Increment parse ID to invalidate any in-flight parses + state.parseId++; + const currentParseId = state.parseId; + + // Set a new timer to parse after a short delay + state.timer = setTimeout(() => { + delete state.timer; + + // Skip if already parsing this document + if (state.parsing) { + return; + } + + state.parsing = true; parser.getDocs( uri, @@ -348,11 +372,17 @@ documents.onDidChangeContent(handler => { collectReferences: true } ).then(cache => { - if (cache) { + state.parsing = false; + + // Only update diagnostics if this is still the latest parse + if (cache && currentParseId === state.parseId) { Linter.refreshLinterDiagnostics(handler.document, cache); } + }).catch(err => { + state.parsing = false; + console.error(`Error parsing ${uri}:`, err); }); - }, 500); + }, 300); // Reduced to 300ms for better responsiveness }); // Make the text document manager listen on the connection From 2610e8fbad90be397dc2530923cae1b14663708a Mon Sep 17 00:00:00 2001 From: Richard Moulton Date: Wed, 12 Nov 2025 18:49:17 +0000 Subject: [PATCH 3/4] Simplify concurrent parse handling by removing parsing flag MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Removes the `parsing` state flag that was preventing concurrent parses. The new approach allows up to 2 concurrent parses per document, with automatic invalidation of stale results via the parseId mechanism. This fixes the issue where document changes during an active parse would not trigger a new parse, leaving the latest changes unparsed. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- extension/server/src/server.ts | 17 +++++------------ 1 file changed, 5 insertions(+), 12 deletions(-) diff --git a/extension/server/src/server.ts b/extension/server/src/server.ts index b38eea42..f0431637 100644 --- a/extension/server/src/server.ts +++ b/extension/server/src/server.ts @@ -327,8 +327,7 @@ if (isLinterEnabled()) Linter.initialise(connection); const documentParseState: { [uri: string]: { timer?: NodeJS.Timeout, - parseId: number, - parsing: boolean + parseId: number } } = {}; @@ -338,7 +337,7 @@ documents.onDidChangeContent(handler => { // Initialize state if needed if (!documentParseState[uri]) { - documentParseState[uri] = { parseId: 0, parsing: false }; + documentParseState[uri] = { parseId: 0 }; } const state = documentParseState[uri]; @@ -356,12 +355,9 @@ documents.onDidChangeContent(handler => { state.timer = setTimeout(() => { delete state.timer; - // Skip if already parsing this document - if (state.parsing) { - return; - } - - state.parsing = true; + // Always start a new parse - don't wait for old ones to finish + // Old parses will be invalidated by the parseId check + // This allows max 2 concurrent parses per document parser.getDocs( uri, @@ -372,14 +368,11 @@ documents.onDidChangeContent(handler => { collectReferences: true } ).then(cache => { - state.parsing = false; - // Only update diagnostics if this is still the latest parse if (cache && currentParseId === state.parseId) { Linter.refreshLinterDiagnostics(handler.document, cache); } }).catch(err => { - state.parsing = false; console.error(`Error parsing ${uri}:`, err); }); }, 300); // Reduced to 300ms for better responsiveness From 1ef9081778c6fa7d8c0e04695dc4862cb823a408 Mon Sep 17 00:00:00 2001 From: Richard Moulton Date: Wed, 12 Nov 2025 19:52:42 +0000 Subject: [PATCH 4/4] Add enhanced logging and fix include fetch deduplication MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds comprehensive timestamped logging for debugging parse operations: - Parse lifecycle tracking (start, completion, duration, parseId) - Include file fetch operations with timing and cache status - URI validation with timing - File fetch operations with cache hits/misses - Clean filename extraction (strips query parameters) Fixes include fetch deduplication bug where fetchingInProgress flag was cleared too early, before async getFileRequest() completed. This caused duplicate server requests for the same include file during a single parse operation. Now the flag is only cleared after all async work completes, properly preventing duplicate fetches. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- extension/server/src/connection.ts | 41 ++++++++++++++++++--- extension/server/src/server.ts | 59 ++++++++++++++++++++++++------ 2 files changed, 83 insertions(+), 17 deletions(-) diff --git a/extension/server/src/connection.ts b/extension/server/src/connection.ts index 37549187..7ff1f602 100644 --- a/extension/server/src/connection.ts +++ b/extension/server/src/connection.ts @@ -24,34 +24,63 @@ connection.onDidChangeWatchedFiles((params: DidChangeWatchedFilesParams) => { watchedFilesChangeEvent.forEach(editEvent => editEvent(params)); }) +function logWithTimestamp(message: string) { + const now = new Date(); + const timestamp = now.toTimeString().split(' ')[0] + '.' + now.getMilliseconds().toString().padStart(3, '0'); + console.log(`[${timestamp}] ${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)`); + return possibleCachedFile; + } - console.log(`Validating file from server: ${stringUri}`); + logWithTimestamp(`URI validation: ${stringUri} (requesting from server...)`); // 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)`); + return uri; + } + + logWithTimestamp(`URI validation: ${stringUri} (${duration}ms, NOT FOUND)`); return; } export async function getFileRequest(uri: string) { + const startTime = Date.now(); + const fileName = uri.split('/').pop() || 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)`); + return localCacheDoc.getText(); + } - console.log(`Fetching file from server: ${uri}`); + logWithTimestamp(`File fetch: ${fileName} (requesting from server...)`); // 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)`); // TODO.. cache it? - return body; + return body; } + logWithTimestamp(`File fetch: ${fileName} (${duration}ms, NOT FOUND)`); return; } diff --git a/extension/server/src/server.ts b/extension/server/src/server.ts index f0431637..e0c41499 100644 --- a/extension/server/src/server.ts +++ b/extension/server/src/server.ts @@ -141,12 +141,16 @@ let fetchingInProgress: { [fetchKey: string]: boolean } = {}; parser.setIncludeFileFetch(async (stringUri: string, includeString: string) => { const currentUri = URI.parse(stringUri); const uriPath = currentUri.path; + // Extract clean filename without query parameters + const parentFileName = (uriPath.split('/').pop() || stringUri).split('?')[0]; + const fetchStartTime = Date.now(); let cleanString: string | undefined; let validUri: string | undefined; if (!fetchingInProgress[includeString]) { fetchingInProgress[includeString] = true; + logWithTimestamp(`Include fetch started: ${includeString} (from ${parentFileName})`); // Right now we are resolving based on the base file schema. // This is likely bad since you can include across file systems. @@ -281,11 +285,13 @@ parser.setIncludeFileFetch(async (stringUri: string, includeString: string) => { } } - fetchingInProgress[includeString] = false; - if (validUri) { const validSource = await getFileRequest(validUri); if (validSource) { + const duration = Date.now() - fetchStartTime; + const fileName = validUri.split('/').pop() || validUri; + logWithTimestamp(`Include fetch completed: ${includeString} -> ${fileName} (${duration}ms, found)`); + fetchingInProgress[includeString] = false; return { found: true, uri: validUri, @@ -294,14 +300,20 @@ parser.setIncludeFileFetch(async (stringUri: string, includeString: string) => { } } + const duration = Date.now() - fetchStartTime; + logWithTimestamp(`Include fetch completed: ${includeString} (${duration}ms, NOT FOUND)`); + fetchingInProgress[includeString] = false; + return { + found: false, + uri: validUri + }; + } else { + logWithTimestamp(`Include fetch skipped: ${includeString} (already fetching)`); + return { + found: false, + uri: validUri + }; } - - fetchingInProgress[includeString] = false; - - return { - found: false, - uri: validUri - }; }); if (languageToolsEnabled) { @@ -323,17 +335,27 @@ if (languageToolsEnabled) { if (isLinterEnabled()) Linter.initialise(connection); +// Helper function for timestamped logging +function logWithTimestamp(message: string) { + const now = new Date(); + const timestamp = now.toTimeString().split(' ')[0] + '.' + now.getMilliseconds().toString().padStart(3, '0'); + console.log(`[${timestamp}] ${message}`); +} + // Track parsing state for each document const documentParseState: { [uri: string]: { timer?: NodeJS.Timeout, - parseId: number + parseId: number, + parseStartTime?: number } } = {}; // Always get latest stuff documents.onDidChangeContent(handler => { const uri = handler.document.uri; + // Extract clean filename without query parameters + const fileName = (uri.split('/').pop() || uri).split('?')[0]; // Initialize state if needed if (!documentParseState[uri]) { @@ -345,6 +367,7 @@ documents.onDidChangeContent(handler => { // Clear any existing timer if (state.timer) { clearTimeout(state.timer); + logWithTimestamp(`Parse timer reset: ${fileName} (parseId: ${state.parseId + 1})`); } // Increment parse ID to invalidate any in-flight parses @@ -359,6 +382,10 @@ documents.onDidChangeContent(handler => { // Old parses will be invalidated by the parseId check // This allows max 2 concurrent parses per document + const parseStartTime = Date.now(); + state.parseStartTime = parseStartTime; + logWithTimestamp(`Parse started: ${fileName} (parseId: ${currentParseId})`); + parser.getDocs( uri, handler.document.getText(), @@ -368,11 +395,21 @@ documents.onDidChangeContent(handler => { collectReferences: true } ).then(cache => { + const duration = Date.now() - parseStartTime; + const isLatest = currentParseId === state.parseId; + // Only update diagnostics if this is still the latest parse - if (cache && currentParseId === state.parseId) { + if (cache && isLatest) { Linter.refreshLinterDiagnostics(handler.document, cache); + logWithTimestamp(`Parse completed: ${fileName} (parseId: ${currentParseId}, ${duration}ms, diagnostics updated)`); + } else if (cache) { + logWithTimestamp(`Parse completed: ${fileName} (parseId: ${currentParseId}, ${duration}ms, STALE - ignored)`); + } else { + logWithTimestamp(`Parse completed: ${fileName} (parseId: ${currentParseId}, ${duration}ms, no cache)`); } }).catch(err => { + const duration = Date.now() - parseStartTime; + logWithTimestamp(`Parse error: ${fileName} (parseId: ${currentParseId}, ${duration}ms)`); console.error(`Error parsing ${uri}:`, err); }); }, 300); // Reduced to 300ms for better responsiveness