feat(observability): add structured logging to loader spans

platform/wab/src/wab/server/loader/gen-code-bundle.ts

@@ -5,7 +5,8 @@ import {
   resolveProjectDeps,
   VersionToSync,
 } from "@/wab/server/loader/resolve-projects";
-import { withSpan } from "@/wab/server/util/apm-util";
+import { logger } from "@/wab/server/observability";
+import { withSpan, withTimeSpent } from "@/wab/server/util/apm-util";
 import { upsertS3CacheEntry } from "@/wab/server/util/s3-util";
 import {
   CachedCodegenOutputBundle,
@@ -76,7 +77,14 @@ export async function genPublishedLoaderCodeBundle(
       ...(await resolveProjectDeps(dbMgr, projectVersions)),
       ...projectVersions,
     }),
-    `Project versions ${JSON.stringify(projectVersions)}`
+    undefined,
+    {
+      project_count: Object.keys(projectVersions).length,
+      project_ids: Object.keys(projectVersions),
+      projects: Object.entries(projectVersions).map(
+        ([id, v]) => `${id}@${v.version}`
+      ),
+    }
   );
 
   await ensureDevFlags(dbMgr);
@@ -217,7 +225,16 @@ async function genLoaderCodeBundleForProjectVersions(
             // If version is a branch name, we want to get the latest of that branch
             if (v.version === "latest" || maybeBranch) {
               // If no explicit version, then we cannot cache; just perform the codegen
-              return await codegenProject(projectId, v.version, v.indirect);
+              const { result, spentTime } = await withTimeSpent(() =>
+                codegenProject(projectId, v.version, v.indirect)
+              );
+              logger().info("loader-codegen-project", {
+                project_id: projectId,
+                project_version: v.version,
+                indirect: v.indirect,
+                duration_ms: spentTime,
+              });
+              return result;
             } else {
               return await upsertS3CacheEntry<
                 [
@@ -233,18 +250,32 @@ async function genLoaderCodeBundleForProjectVersions(
                   indirect: v.indirect,
                   exportOpts,
                 }),
-                compute: async () =>
-                  await codegenProject(projectId, v.version, v.indirect),
+                compute: async () => {
+                  const { result, spentTime } = await withTimeSpent(() =>
+                    codegenProject(projectId, v.version, v.indirect)
+                  );
+                  logger().info("loader-codegen-project", {
+                    project_id: projectId,
+                    project_version: v.version,
+                    indirect: v.indirect,
+                    duration_ms: spentTime,
+                  });
+                  return result;
+                },
                 serialize: (obj) => JSON.stringify(obj),
                 deserialize: (str) => JSON.parse(str),
               });
             }
           })
         ),
-      `Projects ${JSON.stringify({
-        ...projectVersions,
-        loaderVersion: opts.loaderVersion,
-      })}`
+      undefined,
+      {
+        platform: opts.platform,
+        loader_version: opts.loaderVersion,
+        browser_only: opts.browserOnly,
+        project_count: Object.keys(projectVersions).length,
+        project_versions: JSON.stringify(projectVersions),
+      }
     )
   );
 
@@ -306,10 +337,18 @@ async function genLoaderCodeBundleForProjectVersions(
         return await bundleProjects();
       }
     },
-    `Projects ${JSON.stringify({
-      ...projectVersions,
-      loaderVersion: opts.loaderVersion,
-    })}`
+    undefined,
+    {
+      platform: opts.platform,
+      loader_version: opts.loaderVersion,
+      browser_only: opts.browserOnly,
+      mode: opts.mode,
+      project_count: Object.keys(projectVersions).length,
+      project_ids: Object.keys(projectVersions),
+      projects: Object.entries(projectVersions).map(
+        ([id, v]) => `${id}@${v.version}`
+      ),
+    }
   );
   return result;
 }

platform/wab/src/wab/server/loader/module-bundler.ts

@@ -560,41 +560,51 @@ export async function bundleModules(
     throw new LoaderDeprecatedVersionError();
   }
 
-  return withSpan("loader-bundle-esbuild", async () => {
-    try {
-      return await bundleModulesEsbuild(
-        dir,
-        codegenOutputs,
-        componentDeps,
-        opts
-      );
-    } catch (err) {
-      const bundleErrorStr: string = err.toString();
-      logger().error(
-        `Error bundling with esbuild: ${bundleErrorStr}: ${err.stack}`
-      );
+  return withSpan(
+    "loader-bundle-esbuild",
+    async () => {
       try {
-        const errPrefix = await uploadErrorFiles(err, dir);
-        logger().error(`Errors uploaded: ${errPrefix}`);
-      } catch (err2) {
-        logger().error(`Error uploading error files: ${err2.toString()}`);
-      }
+        return await bundleModulesEsbuild(
+          dir,
+          codegenOutputs,
+          componentDeps,
+          opts
+        );
+      } catch (err) {
+        const bundleErrorStr: string = err.toString();
+        logger().error(
+          `Error bundling with esbuild: ${bundleErrorStr}: ${err.stack}`
+        );
+        try {
+          const errPrefix = await uploadErrorFiles(err, dir);
+          logger().error(`Errors uploaded: ${errPrefix}`);
+        } catch (err2) {
+          logger().error(`Error uploading error files: ${err2.toString()}`);
+        }
 
-      const transformedBundleErrorStr = transformBundlerErrors(
-        bundleErrorStr,
-        componentRefs
-      );
+        const transformedBundleErrorStr = transformBundlerErrors(
+          bundleErrorStr,
+          componentRefs
+        );
 
-      if (transformedBundleErrorStr) {
-        logger().error(`transformedError: ${transformedBundleErrorStr}`);
-        throw new LoaderBundlingError(transformedBundleErrorStr);
-      }
+        if (transformedBundleErrorStr) {
+          logger().error(`transformedError: ${transformedBundleErrorStr}`);
+          throw new LoaderBundlingError(transformedBundleErrorStr);
+        }
 
-      await checkEsbuildFatalError(bundleErrorStr);
+        await checkEsbuildFatalError(bundleErrorStr);
 
-      throw new Error(`Error bundling with esbuild: ${bundleErrorStr}`);
+        throw new Error(`Error bundling with esbuild: ${bundleErrorStr}`);
+      }
+    },
+    undefined,
+    {
+      platform: opts.platform,
+      loader_version: opts.loaderVersion,
+      browser_only: opts.browserOnly,
+      mode: opts.mode,
     }
-  });
+  );
 }
 
 function deriveEsbuildDefines(opts: {

platform/wab/src/wab/server/loader/resolve-projects.ts

@@ -77,7 +77,7 @@ export async function resolveLatestProjectVersions(
   opts: { prefilledOnly: boolean } = { prefilledOnly: false }
 ) {
   return withSpan(
-    `resolveLatestProjectVersions-${projectIdsAndTags.length}`,
+    "resolveLatestProjectVersions",
     async () => {
       const pkgVersions = await Promise.all(
         projectIdsAndTags.map((projectIdAndTag) =>
@@ -96,6 +96,14 @@ export async function resolveLatestProjectVersions(
           pkgVersion.version,
         ])
       );
+    },
+    undefined,
+    {
+      project_count: projectIdsAndTags.length,
+      project_ids: projectIdsAndTags.map((p) => p.projectId),
+      projects: projectIdsAndTags.map((p) =>
+        p.tag ? `${p.projectId}@${p.tag}` : p.projectId
+      ),
     }
   );
 }

platform/wab/src/wab/server/util/apm-util.ts

@@ -1,11 +1,13 @@
 import { logger } from "@/wab/server/observability";
 import { WabPromTimer } from "@/wab/server/promstats";
+import { Properties } from "@/wab/shared/observability/Properties";
 import { trace } from "@opentelemetry/api";
 
 export async function withSpan<T>(
   name: string,
   f: () => Promise<T>,
-  msg?: string
+  msg?: string,
+  payload?: Properties
 ) {
   const start = new Date().getTime();
   const promTimer = new WabPromTimer(name);
@@ -14,8 +16,13 @@ export async function withSpan<T>(
     try {
       return await f();
     } finally {
+      const durationMs = new Date().getTime() - start;
       const suffix = msg ? `: ${msg}` : "";
-      logger().info(`${name} took ${new Date().getTime() - start}ms${suffix}`);
+      logger().info(`${name} took ${durationMs}ms${suffix}`, {
+        operation_name: name,
+        duration_ms: durationMs,
+        ...payload,
+      });
       promTimer.end();
       span.end();
     }

platform/wab/src/wab/server/workers/codegen.ts

@@ -231,7 +231,13 @@ export async function doGenCode(
         indirect,
         opts.scheme
       ),
-    `Project ${projectId}`
+    undefined,
+    {
+      project_id: projectId,
+      version,
+      revision_number: revisionNumber,
+      revision_id: revisionId,
+    }
   );
 
   if (project.workspace?.teamId) {

platform/wab/src/wab/server/workers/prefill-cloudfront.ts

@@ -60,17 +60,6 @@ export async function prefillCloudfront(
           publishment.projectIds
         );
 
-        const label = `Pre-filling codegen combo ${JSON.stringify(
-          resolvedProjectIdSpecs
-        )}, version=${publishment.loaderVersion}, platform=${
-          publishment.platform
-        }, browserOnly=${publishment.browserOnly}, i18n=${JSON.stringify({
-          key: publishment.i18nKeyScheme,
-          prefix: publishment.i18nTagPrefix,
-        })}, appDir=${publishment.appDir} projectIds=${JSON.stringify(
-          publishment.projectIds
-        )} pkgVersionId=${pkgVersionId}`;
-
         await withSpan(
           "loader-prefill",
           async () => {
@@ -95,7 +84,18 @@ export async function prefillCloudfront(
               })
             );
           },
-          label
+          undefined,
+          {
+            platform: publishment.platform,
+            loader_version: publishment.loaderVersion,
+            browser_only: publishment.browserOnly,
+            app_dir: publishment.appDir,
+            i18n_key_scheme: publishment.i18nKeyScheme,
+            i18n_tag_prefix: publishment.i18nTagPrefix,
+            pkg_version_id: pkgVersionId,
+            project_ids: publishment.projectIds,
+            projects: resolvedProjectIdSpecs,
+          }
         );
       })
     );