[Tracking Issue] Auto-tracing not working in Google Cloud Functions/Firebase Cloud Functions

[SamyPesse]

When using @google-cloud/trace-agent in Firebase Cloud Functions, the custom tracing works, but auto tracing doesn't (no trace for HTTP/HTTPS/gRPC requests).

Even included as the first module, the cloud functions log output:

ERROR:@google-cloud/trace-agent: TraceAgent#start: Tracing might not work as the following modules were loaded before the trace agent was initialized: [accepts, body-parser, bytes, content-disposition, content-type, cookie, cookie-signature, crc, debug, depd, destroy, ee-first, escape-html, etag, express, finalhandler, forwarded, fresh, iconv-lite, ipaddr.js, media-typer, merge-descriptors, methods, mime, mime-db, mime-types, ms, negotiator, on-finished, parseurl, path-to-regexp, proxy-addr, qs, range-parser, raw-body, send, serve-static, type-is, utils-merge, vary]

It may related to how Firebase Cloud Functions works as an overlay of Google Cloud Functions.

[kjin]

We don't expect tracing to work out of the box for Firebase Cloud Functions (or GCF) at the moment (I'll make sure that gets documented from here on out). The error message points out that express was loaded, presumably before your function code was run.

You could try the workaround of wrapping the function contents in runInRootSpan. From the README:

const traceApi = require('@google-cloud/trace-agent').start();
traceApi.runInRootSpan({ name: 'my-root-span' }, (rootSpan) => {
  // ...
  rootSpan.endSpan();
});

You might consider using rootSpan.addLabel(key, value) to add information that is relevant to the function call, as no labels will be included by default (except for the stack trace, which in this context likely has limited usefulness).

Given how background trace publishing operations may not be supported by Cloud Function's CPU throttling model, it might be useful to publish traces as soon as they're created (by specifying that at most one trace should be buffered at a time):

const traceApi = require('@google-cloud/trace-agent').start({ bufferSize: 1 });

Please let us know if there are any issues that arise!

[kjin]

@SamyPesse If you don't mind, I am going to use this as a tracking issue for the progress of getting the Trace Agent to work with GCF.

[SamyPesse]

@kjin sure 👍 we made it works in our Firebase cloud functions, but without auto-tracing.

The lack of auto-tracing seems to come from the code added by Firebase that requires the modules like express before requiring the application.

[kjin]

@SamyPesse Thanks for the update!

We've been working with the GCF team (which I believe also maintains the Firebase Cloud Functions, or at least the functionality should be similar anyway) but I don't think we can support it yet within the next two months or so. Will give updates as I hear about them.

[steren]

Hi (I am a Product Manager on Google Cloud).
We are working to make it super easy to enable Stackdriver Trace for your functions with no setup required. You can sign up for the Alpha at https://goo.gl/forms/MtCO9Ehu3IfSsqiw2. I should send the first invites within a few weeks.

As others said, in the meantime, you should be able to import the trace module, but not everything will be traced as it is not the first module imported.

[shaneosullivan]

I'm having trouble getting the suggested workaround to work. My code looks as follows

import * as TraceAgent from "@google-cloud/trace-agent";
import * as express from "express";

const app = express();
app.post(
  "/graphql",
  graphqlHTTP({
    schema
  })
);

let tracer;

export = functions
  // @ts-ignore
  .runWith(runtimeOpts)
  .https.onRequest(async (req, resp) => {
    tracer = tracer ? tracer : TraceAgent.start({ bufferSize: 1 });

    const requestName =
      "GraphQL: Root " + (req.body ? req.body.operationName : "unspecified");

    tracer
      .runInRootSpan(
        {
          name: requestName
        },
        async rootSpan => {
          let ret;
          try {
            ret = await app(req, resp);
          } finally {
            console.log(requestName + "[end]");
            rootSpan.endSpan();
          }
          return ret;
        }
      )
      .catch(err => {
        console.error("GraphQL tracing error", err);
      });
  });

As suggested, all code runs in the rootSpan, and the bufferSize is set to 1. I still get the error

error: @google-cloud/trace-agent ERROR StackdriverTracer#start: Tracing might not work as the following modules were loaded before the trace agent was initialized: .....

I've signed up for the Alpha (thanks steren!), but I have many Firebase projects that need proper tracing, so any workaround that would help right now would be useful.

Thanks!

[kjin]

Hi @shaneosullivan -- are you still getting traces reported? The error message being shown here is likely a false alarm, as the condition for its appearance is simply that modules were loaded before the Trace Agent (which is true by nature of the workaround); it's just a blanket "warning" that suggests a possible reason why traces might not get published, if they are not.

[shaneosullivan]

@kjin I am getting traces, but only the root traces for some reason. I've wrapped each GraphQL resolver with

    const tracer = TraceAgent.get();

    const traceSpan = tracer.createChildSpan({
        name: `${reducerName}`
    });

   // Run the reducer function then ....

    traceSpan.endSpan();

but these traces do not show up anywhere. I was hoping the bufferSize:1 thing would help, but still these traces do not appear anywhere.

[kjin]

@shaneosullivan Could you provide more code around the call to createChildSpan? That looks like it should work unless there is some context loss happening here.

Also, do you have warnings turned on? If you set in the config passed to start { logLevel: 1 } then I would expect warnings to be printed upon calls to createChildSpan if those spans are not showing up.

[ofrobots]

The Cloud Functions / Firebase Functions team are working on proper support for this feature. I'm going to close this issue out over here as this is not an issue in this repo.

Please do add a comment here if you this this is incorrect.

[ofrobots]

This can now be tracked on the GCF issue tracker here: https://issuetracker.google.com/124761993

[mrdulin]

I didn't see any pg-query RPCs spans within background cloud function. Is this the reason?

[Elyx0]

Any advancements? I'm not sure if it's locking me on googleapis/nodejs-logging#591

[kjin]

Hey @Elyx0, I saw that you also posted on https://issuetracker.google.com/124761993 -- you should treat that as the source of truth. Thanks!

[danielguardicore]

@ofrobots any way to get an ETA? H1? H2?