Merge pull request #16 from Acumatica/logging-and-bugfixes

Logging and bugfixes

Author: anesvijskij

acumate-plugin/readme.md

@@ -62,7 +62,9 @@ The **AcuMate** extension for Visual Studio Code offers a range of powerful feat
    - Verifies `<field name="...">` entries against the PXView resolved from the surrounding markup and ignores deliberate `unbound replace-content` placeholders.
    - Validates `state.bind` attributes point to PXAction members, and `qp-field control-state.bind` values follow the `<view>.<field>` format with existing fields.
    - Enforces `<qp-panel id="...">` bindings by making sure the id maps to an existing PXView, and reuses that view context when checking footer `<qp-button state.bind="...">` actions so dialogs only reference actions exposed by their owning view.
+   - Requires `qp-panel` nodes and all `qp-*` controls to define `id` attributes (except for `qp-field`, `qp-label`, and `qp-include`) so missing identifiers and misbound panels are caught before packaging.
    - Enforces Acumatica-specific constructs: required qp-include parameters, rejection of undeclared include attributes, and qp-template name checks sourced from ScreenTemplates metadata.
+   - Guards `<qp-template name="record-*">` usages so record templates only validate when the markup sits inside a `<qp-data-feed>` container, matching runtime restrictions.
    - Leverages client-controls config schemas to inspect `config.bind` JSON on qp-* controls, reporting malformed JSON, missing required properties, and unknown keys before runtime.
    - Parses customization attributes such as `before`, `after`, `append`, `prepend`, `move`, and ensures their CSS selectors resolve against the base screen HTML so misplaced selectors surface immediately instead of at publish time.
    - Integrates these diagnostics with ESLint + VS Code so warnings surface consistently in editors and CI.
@@ -76,6 +78,13 @@ The **AcuMate** extension for Visual Studio Code offers a range of powerful feat
    - Offers IntelliSense suggestions for available `view.bind` values sourced from the PXScreen metadata.  
    - Provides field name suggestions that automatically scope to the closest parent view binding, so only valid fields appear.  
    - Attribute parsing tolerates empty values (`view.bind=""`) to keep suggestions responsive while editing.
+   - Template name completions automatically filter out `record-*` entries unless the caret is inside a `<qp-data-feed>`, keeping suggestions aligned with validation rules.
+
+   ### Logging & Observability
+
+   - All extension subsystems log to a single **AcuMate** output channel, making it easy to trace backend requests, caching behavior, and command execution without hunting through multiple panes.
+   - Every AcuMate command writes a structured log entry (arguments + timing) so build/validation flows can be audited when integrating with CI or troubleshooting user reports.
+   - Backend API calls, cache hits/misses, and configuration reloads emit detailed log lines, giving immediate visibility into why a control lookup or metadata request might have failed.
 
 4. **Backend Field Hovers**  
    - Hovering over `<field name="...">` or `<qp-field name="...">` immediately shows backend metadata (display name, type, default control type, originating view) sourced from the same data that powers TypeScript hovers.

acumate-plugin/snippets.json

@@ -3,8 +3,8 @@
 		"prefix": ["hook", "handleEvent", "currentRowChanged"],
 		"body": [
 			"@handleEvent(CustomEventType.CurrentRowChanged, { view: \"${1:ViewName}\" })",
-			"on${2:Row}Changed(args: CurrentRowChangedHandlerArgs<${3:ViewType}>) {",
-            "   $4",
+			"on${1:ViewName}Changed(args: CurrentRowChangedHandlerArgs<${2:ViewType}>) {",
+            "   $3",
             "}"
 		],
 		"description": "CurrentRowChanged event hook"
@@ -13,18 +13,18 @@
 		"prefix": ["hook", "handleEvent", "rowSelected"],
 		"body": [
 			"@handleEvent(CustomEventType.RowSelected, { view: \"${1:ViewName}\" })",
-			"on${2:Row}Changed(args: RowSelectedHandlerArgs<${3:ViewType}>) {",
-            "   $4",
+			"on${1:ViewName}Changed(args: RowSelectedHandlerArgs<${2:ViewType}>) {",
+            "   $3",
             "}"
 		],
 		"description": "RowSelected event hook"
 	},
     "ValueChanged": {
 		"prefix": ["hook", "handleEvent", "valueChanged"],
 		"body": [
-			"@handleEvent(CustomEventType.ValueChanged, { view: \"${1:ViewName}\" })",
-			"on${1:ViewName}Changed(args: ValueChangedHandlerArgs<${2:ViewType}>) {",
-            "   $3",
+			"@handleEvent(CustomEventType.ValueChanged, { view: \"${1:ViewName}\", field: \"${2:FieldName}\" })",
+			"on${2:FieldName}Changed(args: ValueChangedHandlerArgs<${3:ViewType}>) {",
+            "   $4",
             "}"
 		],
 		"description": "ValueChanged event hook"
@@ -43,8 +43,8 @@
 		"prefix": ["hook", "handleEvent", "getRowCss"],
 		"body": [
 			"@handleEvent(CustomEventType.GetRowCss, { view: \"${1:ViewName}\" })",
-			"get${2:Row}RowCss(args: RowCssHandlerArgs): string | undefined {",
-            "   $3",
+			"get${1:ViewName}RowCss(args: RowCssHandlerArgs): string | undefined {",
+            "   $2",
             "}"
 		],
 		"description": "GetRowCss event hook"
@@ -53,8 +53,8 @@
 		"prefix": ["hook", "handleEvent", "getCellCss"],
 		"body": [
 			"@handleEvent(CustomEventType.GetCellCss, { view: \"${1:ViewName}\", allColumns: true })",
-			"get${2:Cell}CellCss(args: CellCssHandlerArgs): string | undefined {",
-            "   $3",
+			"get${1:ViewName}CellCss(args: CellCssHandlerArgs): string | undefined {",
+            "   $2",
             "}"
 		],
 		"description": "GetCellCss event hook"

acumate-plugin/src/api/api-service.ts

@@ -4,6 +4,7 @@ import { GraphAPIRoute, GraphAPIStructureRoute, AuthEndpoint, LogoutEndpoint, Fe
 import { IAcuMateApiClient } from "./acu-mate-api-client";
 import { AcuMateContext } from "../plugin-context";
 import { FeatureModel } from "../model/FeatureModel";
+import { logError, logInfo } from "../logging/logger";
 
 interface FeatureSetsResponse {
     sets?: FeatureSetEntry[];
@@ -63,6 +64,7 @@ export class AcuMateApiClient implements IAcuMateApiClient {
             return;
         }
 
+        logInfo('Logging out from AcuMate backend.');
         const response = await fetch(AcuMateContext.ConfigurationService.backedUrl!+LogoutEndpoint, {
             method:'POST',
             headers: {
@@ -74,24 +76,26 @@ export class AcuMateApiClient implements IAcuMateApiClient {
         this.sessionCookieHeader = undefined;
 
         if (response.ok) {
-            console.log('Logged out successfully.');
+            logInfo('Backend session closed successfully.');
         } else {
             const errorBody = await response.text().catch(() => "");
-            console.error(`Authentication failed with status ${response.status}: ${errorBody}`);
+            logError('Backend logout failed.', { status: response.status, errorBody });
         }
     }
 
     private async makeGetRequest<T>(route: string): Promise<T | undefined> {
         if (!AcuMateContext.ConfigurationService.useBackend) {
+            logInfo('Skipped backend request because acuMate.useBackend is disabled.', { route });
             return undefined;
         }
 
         try {
+            logInfo('Authenticating before backend request.', { route });
             const authResponse = await this.auth();
 
             if (authResponse.status !== 200 && authResponse.status !== 204) {
                 const errorBody = await authResponse.text().catch(() => "");
-                console.error(`Authentication failed with status ${authResponse.status}: ${errorBody}`);
+                logError('AcuMate backend authentication failed.', { status: authResponse.status, errorBody });
                 return undefined;
             }
 
@@ -106,29 +110,33 @@ export class AcuMateApiClient implements IAcuMateApiClient {
                 headers
             };
             settings.credentials = `include`;
+            logInfo('Issuing backend GET request.', { url });
             const response = await fetch(url, settings);
 
             if (!response.ok) {
                 const errorBody = await response.text().catch(() => "");
-                console.error(`GET ${url} failed with status ${response.status}: ${errorBody}`);
+                logError('Backend GET request failed.', { url, status: response.status, errorBody });
                 return undefined;
             }
 
             const contentType = response.headers.get("content-type") ?? "";
             if (!contentType.includes("application/json")) {
                 const errorBody = await response.text().catch(() => "");
-                console.error(`GET ${url} returned non-JSON content (${contentType}): ${errorBody}`);
+                logError('Backend GET returned unexpected content type.', { url, contentType, errorBody });
                 return undefined;
             }
 
             const data = await response.json();
-
-            console.log(data);
+            const summary: Record<string, unknown> = { url };
+            if (Array.isArray(data)) {
+                summary.items = data.length;
+            }
+            logInfo('Backend GET succeeded.', summary);
 
             return data as T;
         }
         catch (error) {
-            console.error('Error making GET request:', error);
+            logError('Unexpected error during backend GET request.', { route, error });
         }
         finally {
             await this.logout();

acumate-plugin/src/api/layered-data-service.ts

@@ -5,6 +5,7 @@ import { IAcuMateApiClient } from "./acu-mate-api-client";
 import { CachedDataService } from "./cached-data-service";
 import { FeaturesCache, GraphAPICache, GraphAPIStructureCachePrefix } from "./constants";
 import { FeatureModel } from "../model/FeatureModel";
+import { logInfo } from "../logging/logger";
 
 export class LayeredDataService implements IAcuMateApiClient {
 
@@ -19,16 +20,19 @@ export class LayeredDataService implements IAcuMateApiClient {
     async getGraphs(): Promise<GraphModel[] | undefined> {
         const cachedResult = await this.cacheService.getGraphs();
         if (cachedResult) {
+            logInfo('Serving graphs from cache.', { count: cachedResult.length });
             return cachedResult;
         }
 
+        logInfo('Graph cache miss. Fetching from backend...');
         if (this.inflightGraphs) {
             return this.inflightGraphs;
         }
 
         this.inflightGraphs = this.apiService
             .getGraphs()
             .then(result => {
+                logInfo('Graphs fetched from backend.', { count: result?.length ?? 0 });
                 this.cacheService.store(GraphAPICache, result);
                 return result;
             })
@@ -43,6 +47,7 @@ export class LayeredDataService implements IAcuMateApiClient {
     async getGraphStructure(graphName: string): Promise<GraphStructure | undefined> {
         const cachedResult = await this.cacheService.getGraphStructure(graphName);
         if (cachedResult) {
+            logInfo('Serving cached graph structure.', { graphName });
             return cachedResult;
         }
 
@@ -51,9 +56,11 @@ export class LayeredDataService implements IAcuMateApiClient {
             return existing;
         }
 
+        logInfo('Graph structure cache miss. Fetching from backend...', { graphName });
         const pending = this.apiService
             .getGraphStructure(graphName)
             .then(result => {
+                logInfo('Graph structure fetched from backend.', { graphName, hasResult: Boolean(result) });
                 this.cacheService.store(GraphAPIStructureCachePrefix + graphName, result);
                 return result;
             })
@@ -68,16 +75,19 @@ export class LayeredDataService implements IAcuMateApiClient {
     async getFeatures(): Promise<FeatureModel[] | undefined> {
         const cachedResult = await this.cacheService.getFeatures();
         if (cachedResult) {
+            logInfo('Serving feature metadata from cache.', { count: cachedResult.length });
             return cachedResult;
         }
 
+        logInfo('Feature cache miss. Fetching from backend...');
         if (this.inflightFeatures) {
             return this.inflightFeatures;
         }
 
         this.inflightFeatures = this.apiService
             .getFeatures()
             .then(result => {
+                logInfo('Features fetched from backend.', { count: result?.length ?? 0 });
                 this.cacheService.store(FeaturesCache, result);
                 return result;
             })