ConsoleSpanExporter not logging anything for Custom Spans for prebuilds

[jinja12]

I have a basic NextJS application, inside which there are some custom build scripts which run as prebuild alongside the default next build package.json:

  "scripts": {
    "dev": "next dev",
    "build": "node prebuild.js && next build",
    "start": next start",
    "lint": "next lint"
  },

The prebuild.js file:

const { execSync } = require("child_process");
const {
  diag,
  DiagConsoleLogger,
  DiagLogLevel,
  trace,
  context,
} = require("@opentelemetry/api");
const { NodeSDK } = require("@opentelemetry/sdk-node");
const {
  getNodeAutoInstrumentations,
} = require("@opentelemetry/auto-instrumentations-node");
const {
  ConsoleSpanExporter,
  SimpleSpanProcessor,
} = require("@opentelemetry/sdk-trace-base");
const {
  envDetectorSync,
  hostDetectorSync,
  processDetectorSync,
} = require("@opentelemetry/resources");

function awaitAttributes(detector) {
  return {
    async detect(config) {
      const resource = detector.detect(config);
      await resource.waitForAsyncAttributes?.();
      return resource;
    },
  };
}

diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

// Initialize the OpenTelemetry SDK with ConsoleSpanExporter
const sdk = new NodeSDK({
  traceExporter: new ConsoleSpanExporter(),
  spanProcessors: [new SimpleSpanProcessor(new ConsoleSpanExporter())],
  instrumentations: [getNodeAutoInstrumentations()],
  resourceDetectors: [
    awaitAttributes(envDetectorSync),
    awaitAttributes(processDetectorSync),
    awaitAttributes(hostDetectorSync),
  ],
});

// Start the SDK
sdk.start();

async function buildPackage(packagePath) {
  const tracer = trace.getTracer("custom-tracer");
  const span = tracer.startSpan(`Building ${packagePath}`, {
    attributes: { packagePath },
  });
  return context.with(trace.setSpan(context.active(), span), async () => {
    try {
      console.log(`Building package at ${packagePath}...`);
      execSync(`cd ${packagePath} && npm run build`, { stdio: "inherit" });
      span.addEvent("Package build complete", {
        packagePath,
        timestamp: Date.now(),
      });
    } catch (error) {
      span.recordException(error);
      console.error(`Error building ${packagePath}: ${error}`);
    } finally {
      console.log("Logging span after finally");
      console.log("Span Context: " + JSON.stringify(span.spanContext()));
      span.end();
      console.log(`Span ended for package ${packagePath}`);
    }
  });
}

async function main() {
  const packages = ["./packages_test/package1", "./packages_test/package2"];
  for (const packagePath of packages) {
    await buildPackage(packagePath);
  }

  // Shutdown the OpenTelemetry SDK properly
  await sdk
    .shutdown()
    .then(() => {
      console.log("Tracing terminated");
      process.exit(0);
    })
    .catch((error) => {
      console.error("Error terminating tracing", error);
      process.exit(1);
    });
}

main();

So basically packages_test/package1 and packages_test/package2 are my custom packages which I build inside this script. Inside their package.json file: I just initiate a sleep of some short duration around 2-5s to simulate build time inside scripts build.

UseCase: Now my aim is to get relevant Telemetry data for my build process and get an idea about the build times and other data for all builds which happen including the prebuilds. I enclosed the build process in my prebuilds script inside a span and was hoping that after span.end(), the trace details are logged automatically on my console. Nothing of that sort is logged, to test if my trace was even being initialized or not, I added console logs for my span context. Following is the log:

I am not sure why is this not working as expected (trace details not logged after span end), any insights into this would be highly appreciated. Also, it would be great if one could suggest alternative better approaches to solve the use case which I am trying to solve. Thanks!

[jinja12]

The project link: "https://github.com/jinja12/webperf"

[jinja12]

Ok so, it has managed to start working, following is the modified code:

const { execSync } = require("child_process");
const { trace } = require("@opentelemetry/api");
const { BasicTracerProvider, ConsoleSpanExporter, SimpleSpanProcessor } = require("@opentelemetry/sdk-trace-base");

const fs = require('fs');

class CustomConsoleSpanExporter extends ConsoleSpanExporter {
  export(spans, resultCallback) {
    for (const span of spans) {
      const startTime = span.startTime[0] + span.startTime[1] * 1e-9; // Convert to seconds
      const duration = span.duration[0]; // Convert to seconds
      const logMessage = `Step Name: ${span.name}, Start Time: ${startTime.toFixed(6)} secs, Duration: ${duration.toFixed(6)} secs\n`;
      console.log(logMessage);
      fs.appendFileSync('traces.txt', logMessage);
    }
    resultCallback({ code: 0 });
  }
}

const provider = new BasicTracerProvider();
provider.addSpanProcessor(new SimpleSpanProcessor(new CustomConsoleSpanExporter()));
provider.register();

const name = 'webperf';
const version = '0.1.0';
const tracer = trace.getTracer(name, version);

async function buildPackage(packagePath) {
  const span = tracer.startSpan(`Building package at ${packagePath}`);
  try {
    execSync(`cd ${packagePath} && npm run build`, { stdio: "inherit" });
  } finally {
    span.end();
  }
}

async function runRandomScript() {
  const span = tracer.startSpan("Running random script");
  try {
    execSync(`node randomScript.js`, { stdio: "inherit" });
  } finally {
    span.end();
  }
}

async function main() {
  fs.writeFileSync('traces.txt', ''); // Clear file content before starting
  const packages = ["./packages_test/package1", "./packages_test/package2"];
  for (const packagePath of packages) {
    await buildPackage(packagePath);
  }
  await runRandomScript();
}

main();

Is there some solution where instead of adding a span around each build manually and instrumenting it, I can build a wrapper over this, i.e. the prebuild script will only strictly contain the functions to build packages, and I am able to build some wrapper code: instrumentBuild.js where I can track the build times and other relevant data for each build that happens in the prebuild script ? Tagging @dyladan @pichlermarc @svrnm @blumamir @legendecas @hectorhdzg @trentm

[trentm]

Is there some solution where instead of adding a span around each build manually and instrumenting it, I can build a wrapper over this, i.e. the prebuild script will only strictly contain the functions to build packages, and I am able to build some wrapper code: instrumentBuild.js where I can track the build times and other relevant data for each build that happens in the prebuild script ?

You could perhaps write a wrapper for execSync that creates a span around the exec. Or you could consider writing an instrumentation for Node.js' child_process module. However, that would of course be much more work.

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[github-actions[bot]]

This issue was closed because it has been stale for 14 days with no activity.