Improve structured logging with proper fields and messages

Add missing structured fields to log calls while preserving
human-readable messages with interpolated values. This makes
logs both machine-parseable and human-friendly.

Changes:
- Add jobId, executionId, path fields to job operations
- Add cartridgeName, codeVersionId fields to code operations
- Add method, url fields to client logging
- Add headerName, keyPreview, username, port fields to auth
- Change reserved 'hostname' field to 'server' in watch.ts

Author: clavery

packages/b2c-tooling-sdk/src/auth/api-key.ts

@@ -37,7 +37,7 @@ export class ApiKeyStrategy implements AuthStrategy {
 
     // Show partial key for identification (first 8 chars)
     const keyPreview = key.length > 8 ? `${key.slice(0, 8)}...` : key;
-    logger.debug({headerName}, `[Auth] Using API Key authentication (${headerName}): ${keyPreview}`);
+    logger.debug({headerName, keyPreview}, `[Auth] Using API Key authentication (${headerName}): ${keyPreview}`);
   }
 
   async fetch(url: string, init: RequestInit = {}): Promise<Response> {

packages/b2c-tooling-sdk/src/auth/oauth-implicit.ts

@@ -107,20 +107,17 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
 
     const logger = getLogger();
     logger.debug(
-      {clientId: this.config.clientId, accountManagerHost: this.accountManagerHost, localPort: this.localPort},
-      `[Auth] ImplicitOAuthStrategy initialized for client: ${this.config.clientId}`,
-    );
-    logger.trace(
-      {scopes: this.config.scopes},
-      `[Auth] Configured scopes: ${this.config.scopes?.join(', ') || '(none)'}`,
+      {clientId: this.config.clientId, accountManagerHost: this.accountManagerHost, port: this.localPort},
+      '[Auth] ImplicitOAuthStrategy initialized',
     );
+    logger.trace({scopes: this.config.scopes}, '[Auth] Configured scopes');
   }
 
   async fetch(url: string, init: RequestInit = {}): Promise<Response> {
     const logger = getLogger();
     const method = init.method || 'GET';
 
-    logger.trace({method, url}, `[Auth] Fetching with implicit OAuth: ${method} ${url}`);
+    logger.trace({method, url}, '[Auth] Fetching with implicit OAuth');
 
     const token = await this.getAccessToken();
 
@@ -132,10 +129,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
     let res = await fetch(url, {...init, headers});
     const duration = Date.now() - startTime;
 
-    logger.debug(
-      {method, url, status: res.status, duration},
-      `[Auth] Response: ${method} ${url} ${res.status} ${duration}ms`,
-    );
+    logger.debug({method, url, status: res.status, duration}, '[Auth] Response');
 
     // RESILIENCE: If the server says 401, the token might have expired or been revoked.
     // We retry exactly once after invalidating the cached token.
@@ -149,10 +143,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
       res = await fetch(url, {...init, headers});
       const retryDuration = Date.now() - retryStart;
 
-      logger.debug(
-        {method, url, status: res.status, duration: retryDuration},
-        `[Auth] Retry response: ${method} ${url} ${res.status} ${retryDuration}ms`,
-      );
+      logger.debug({method, url, status: res.status, duration: retryDuration}, '[Auth] Retry response');
     }
 
     return res;
@@ -244,10 +235,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
         );
         ACCESS_TOKEN_CACHE.delete(clientId);
       } else {
-        logger.debug(
-          {timeUntilExpiryMs: timeUntilExpiry},
-          `[Auth] Reusing cached access token (expires in ${Math.round(timeUntilExpiry / 1000)}s)`,
-        );
+        logger.debug({timeUntilExpiryMs: timeUntilExpiry}, '[Auth] Reusing cached access token');
         return cached.accessToken;
       }
     }
@@ -314,7 +302,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
     logger.trace({authorizeUrl}, '[Auth] Authorization URL');
 
     // Print URL to console (in case machine has no default browser)
-    logger.info(`Login URL: ${authorizeUrl}`);
+    logger.info({url: authorizeUrl}, `Login URL: ${authorizeUrl}`);
     logger.info('If the URL does not open automatically, copy/paste it into a browser on this machine.');
 
     // Attempt to open the browser
@@ -337,7 +325,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
             hasAccessToken: !!accessToken,
             hasError: !!error,
           },
-          `[Auth] Received redirect request: ${requestUrl.pathname}`,
+          '[Auth] Received redirect request',
         );
 
         if (!accessToken && !error) {
@@ -349,7 +337,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
         } else if (accessToken) {
           const authDuration = Date.now() - startTime;
           // Successfully received access token
-          logger.debug({authDurationMs: authDuration}, `[Auth] Got access token response (took ${authDuration}ms)`);
+          logger.debug({duration: authDuration}, `[Auth] Got access token response (${authDuration}ms)`);
           logger.info('Successfully authenticated');
 
           try {
@@ -366,7 +354,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
 
           logger.debug(
             {expiresIn, expiresAt: expiration.toISOString(), scopes},
-            `[Auth] Token expires in ${expiresIn}s, scopes: ${scopes.join(', ') || '(none)'}`,
+            `[Auth] Token expires in ${expiresIn}s, scopes: ${scopes.join(' ')}`,
           );
 
           resolve({
@@ -391,7 +379,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
         } else if (error) {
           // OAuth error response
           const errorMessage = errorDescription || error;
-          logger.error({error, errorDescription}, `[Auth] OAuth error: ${errorMessage}`);
+          logger.error({error, errorDescription}, `[Auth] OAuth error: ${error}`);
           response.writeHead(500, {'Content-Type': 'text/plain'});
           response.write(`Authentication failed: ${errorMessage}`);
           response.end();
@@ -421,7 +409,7 @@ export class ImplicitOAuthStrategy implements AuthStrategy {
       });
 
       server.on('error', (err) => {
-        logger.error({error: err.message, port: this.localPort}, `[Auth] Failed to start OAuth redirect server`);
+        logger.error({error: err.message, port: this.localPort}, '[Auth] Failed to start OAuth redirect server');
         reject(new Error(`Failed to start OAuth redirect server: ${err.message}`));
       });
     });

packages/b2c-tooling-sdk/src/auth/oauth.ts

@@ -178,7 +178,7 @@ export class OAuthStrategy implements AuthStrategy {
     logger.debug({method, url}, `[Auth REQ] ${method} ${url}`);
 
     // Trace: Log request details
-    logger.trace({headers: requestHeaders, body: params.toString()}, `[Auth REQ BODY] ${method} ${url}`);
+    logger.trace({method, url, headers: requestHeaders, body: params.toString()}, `[Auth REQ BODY] ${method} ${url}`);
 
     const startTime = Date.now();
     const response = await fetch(url, {
@@ -202,7 +202,7 @@ export class OAuthStrategy implements AuthStrategy {
 
     if (!response.ok) {
       const errorText = await response.text();
-      logger.trace({headers: responseHeaders, body: errorText}, `[Auth RESP BODY] ${method} ${url}`);
+      logger.trace({method, url, headers: responseHeaders, body: errorText}, `[Auth RESP BODY] ${method} ${url}`);
       throw new Error(`Failed to get access token: ${response.status} ${response.statusText} - ${errorText}`);
     }
 
@@ -213,7 +213,7 @@ export class OAuthStrategy implements AuthStrategy {
     };
 
     // Trace: Log response details
-    logger.trace({headers: responseHeaders, body: data}, `[Auth RESP BODY] ${method} ${url}`);
+    logger.trace({method, url, headers: responseHeaders, body: data}, `[Auth RESP BODY] ${method} ${url}`);
 
     const jwt = decodeJWT(data.access_token);
     logger.trace({jwt: jwt.payload}, '[Auth] JWT payload');

packages/b2c-tooling-sdk/src/clients/middleware.ts

@@ -143,7 +143,7 @@ export function createLoggingMiddleware(config?: string | LoggingMiddlewareConfi
       // Mask sensitive/large body keys before logging
       const maskedBody = maskBody(body, maskBodyKeys);
       logger.trace(
-        {headers: headersToObject(request.headers), body: maskedBody},
+        {method: request.method, url, headers: headersToObject(request.headers), body: maskedBody},
         `${reqTag} ${request.method} ${url} body`,
       );
 
@@ -178,7 +178,7 @@ export function createLoggingMiddleware(config?: string | LoggingMiddlewareConfi
       // Mask sensitive/large body keys before logging
       const maskedResponseBody = maskBody(responseBody, maskBodyKeys);
       logger.trace(
-        {headers: headersToObject(response.headers), body: maskedResponseBody},
+        {method: request.method, url, headers: headersToObject(response.headers), body: maskedResponseBody},
         `${respTag} ${request.method} ${url} body`,
       );
 

packages/b2c-tooling-sdk/src/clients/webdav.ts

@@ -143,7 +143,12 @@ export class WebDavClient {
 
     // Trace: Log request details
     logger.trace(
-      {headers: this.headersToObject(request.headers), body: this.formatBody(init?.body)},
+      {
+        method: request.method,
+        url: request.url,
+        headers: this.headersToObject(request.headers),
+        body: this.formatBody(init?.body),
+      },
       `[WebDAV REQ BODY] ${request.method} ${request.url}`,
     );
 
@@ -188,7 +193,10 @@ export class WebDavClient {
       const clonedResponse = response.clone();
       responseBody = await clonedResponse.text();
     }
-    logger.trace({headers: responseHeaders, body: responseBody}, `[WebDAV RESP BODY] ${request.method} ${request.url}`);
+    logger.trace(
+      {method: request.method, url: request.url, headers: responseHeaders, body: responseBody},
+      `[WebDAV RESP BODY] ${request.method} ${request.url}`,
+    );
 
     return response;
   }

packages/b2c-tooling-sdk/src/operations/code/deploy.ts

@@ -92,10 +92,10 @@ export async function deleteCartridges(instance: B2CInstance, cartridges: Cartri
     const cartridgePath = `Cartridges/${codeVersion}/${c.dest}`;
     try {
       await webdav.delete(cartridgePath);
-      logger.debug({cartridge: c.dest}, `Deleted ${cartridgePath}`);
+      logger.debug({cartridgeName: c.dest, path: cartridgePath}, `Deleted ${cartridgePath}`);
     } catch {
       // Ignore errors - cartridge may not exist
-      logger.debug({cartridge: c.dest}, `Could not delete ${cartridgePath} (may not exist)`);
+      logger.debug({cartridgeName: c.dest, path: cartridgePath}, `Could not delete ${cartridgePath} (may not exist)`);
     }
   }
 }
@@ -243,7 +243,7 @@ export async function findAndDeployCartridges(
 
   logger.debug({count: cartridges.length}, `Found ${cartridges.length} cartridge(s)`);
   for (const c of cartridges) {
-    logger.debug({cartridge: c.name, path: c.src}, `  ${c.name}`);
+    logger.debug({cartridgeName: c.name, path: c.src}, `  ${c.name}`);
   }
 
   // Optionally delete existing cartridges first

packages/b2c-tooling-sdk/src/operations/code/versions.ts

@@ -116,7 +116,7 @@ export async function reloadCodeVersion(instance: B2CInstance, codeVersionId?: s
     throw new Error('No code version specified and no active version found');
   }
 
-  logger.debug({targetVersion}, `Reloading code version ${targetVersion}`);
+  logger.debug({codeVersionId: targetVersion}, `Reloading code version ${targetVersion}`);
 
   // If the target is already active, we need to toggle to another version first
   if (activeVersion?.id === targetVersion) {
@@ -125,13 +125,13 @@ export async function reloadCodeVersion(instance: B2CInstance, codeVersionId?: s
       throw new Error('Cannot reload: no alternate code version available for toggle');
     }
 
-    logger.debug({alternateVersion: alternateVersion.id}, `Temporarily activating ${alternateVersion.id}`);
+    logger.debug({codeVersionId: alternateVersion.id}, `Temporarily activating ${alternateVersion.id}`);
     await activateCodeVersion(instance, alternateVersion.id!);
   }
 
   // Now activate the target version
   await activateCodeVersion(instance, targetVersion);
-  logger.debug({targetVersion}, `Code version ${targetVersion} reloaded`);
+  logger.debug({codeVersionId: targetVersion}, `Code version ${targetVersion} reloaded`);
 }
 
 /**

packages/b2c-tooling-sdk/src/operations/code/watch.ts

@@ -145,7 +145,7 @@ export async function watchCartridges(
 
   logger.debug({count: cartridges.length}, `Watching ${cartridges.length} cartridge(s)`);
   for (const c of cartridges) {
-    logger.info({cartridge: c.name, path: c.src}, `  ${c.name}`);
+    logger.info({cartridgeName: c.name, path: c.src}, `  ${c.name}`);
   }
 
   const webdav = instance.webdav;
@@ -229,7 +229,7 @@ export async function watchCartridges(
         await webdav.delete(uploadPath);
 
         logger.debug(
-          {fileCount: validUploadFiles.length, hostname: instance.config.hostname},
+          {fileCount: validUploadFiles.length, server: instance.config.hostname},
           `Uploaded ${validUploadFiles.length} file(s)`,
         );
 
@@ -253,9 +253,9 @@ export async function watchCartridges(
         const deletePath = `${webdavLocation}/${f.dest}`;
         try {
           await webdav.delete(deletePath);
-          logger.info({file: deletePath}, `Deleted: ${deletePath}`);
+          logger.info({path: deletePath}, `Deleted: ${deletePath}`);
         } catch (error) {
-          logger.debug({file: deletePath, error}, `Failed to delete ${deletePath}`);
+          logger.debug({path: deletePath, error}, `Failed to delete ${deletePath}`);
         }
       }
 
@@ -291,7 +291,7 @@ export async function watchCartridges(
     options.onError?.(error);
   });
 
-  logger.debug({hostname: instance.config.hostname, codeVersion}, 'Watching for changes...');
+  logger.debug({server: instance.config.hostname, codeVersion}, 'Watching for changes...');
 
   return {
     watcher,

packages/b2c-tooling-sdk/src/operations/jobs/run.ts

@@ -117,12 +117,12 @@ export async function executeJob(
     const errorBody = await response.text().catch(() => '');
     if (errorBody.includes('JobAlreadyRunningException')) {
       if (waitForRunning) {
-        logger.warn(`Job ${jobId} already running, waiting for it to finish...`);
+        logger.warn({jobId}, `Job ${jobId} already running, waiting for it to finish...`);
 
         // Search for the running execution
         const runningExecution = await findRunningJobExecution(instance, jobId);
         if (runningExecution) {
-          logger.debug({executionId: runningExecution.id}, `Found running execution ${runningExecution.id}`);
+          logger.debug({jobId, executionId: runningExecution.id}, `Found running execution ${runningExecution.id}`);
           await waitForJob(instance, jobId, runningExecution.id!);
           // Retry execution after the running job finishes
           return executeJob(instance, jobId, {...options, waitForRunning: false});
@@ -139,7 +139,7 @@ export async function executeJob(
     throw new Error(message);
   }
 
-  logger.debug({executionId: data.id, status: data.execution_status}, `Job ${jobId} started: ${data.id}`);
+  logger.debug({jobId, executionId: data.id, status: data.execution_status}, `Job ${jobId} started: ${data.id}`);
 
   return data;
 }
@@ -231,14 +231,14 @@ export async function waitForJob(
 
     // Check for terminal states
     if (execution.execution_status === 'aborted' || execution.exit_status?.code === 'ERROR') {
-      logger.debug({execution}, `Job ${jobId} failed`);
+      logger.debug({jobId, executionId, execution}, `Job ${jobId} failed`);
       throw new JobExecutionError(`Job ${jobId} failed`, execution);
     }
 
     if (execution.execution_status === 'finished') {
       const durationSec = (execution.duration ?? 0) / 1000;
       logger.debug(
-        {executionId, status: execution.exit_status?.code, duration: durationSec},
+        {jobId, executionId, status: execution.exit_status?.code, duration: durationSec},
         `Job ${jobId} finished. Status: ${execution.exit_status?.code} (duration: ${durationSec}s)`,
       );
       return execution;
@@ -247,7 +247,7 @@ export async function waitForJob(
     // Log periodic updates
     if (ticks % 5 === 0) {
       logger.debug(
-        {executionId, status: execution.execution_status, elapsed: elapsed / 1000},
+        {jobId, executionId, status: execution.execution_status, elapsed: elapsed / 1000},
         `Waiting for job ${jobId} to finish (${(elapsed / 1000).toFixed(0)}s elapsed)...`,
       );
     }