Getting execution-id / trace in background functions

[Elyx0]

Environment details

• OS: MacOS 10.13.6
• Node.js version: 10.15.3
• npm version: 6.4.1
• @google-cloud/logging version: 5.3.1
• Firebase Cloud Functions

Steps to reproduce

1. In a Firebase cloud functions (scheduler or pubsub or httpRequest)

console.log('Init');

This gets taged correctly with an execution and the correct labels.
2.

import { Logging, detectServiceContext } from '@google-cloud/logging';

I've tried stealing export function getCurrentTraceFromAgent() { and the detectServiceContext trick
from @google-cloud/logging-bunyan": "^1.2.3", it didn't work either.
Also went around https://stackoverflow.com/questions/49185824/log-jsonpayload-in-firebase-cloud-functions it didn't work.

It's been 5hours and I'm starting to get a bit crazy on how to achieve the same behavior than a console.log and adding my own metadata

[bcoe]

@Elyx0 could you provide a little bit of a code sample, as to what you're trying to achieve? i.e.,

• how you're instantiating the logger.
• how you're logging.
• and what the expected entry in stackdriver is.

[Elyx0]

Sure, ok:

This is how a normal console.log() shows in stackdiver:

resource.label is filled and I get the execution id : 76894...etc and the trace with a hash

---

Now when using stackdiver as such:

import util from 'util';
const LOGGING_TRACE_KEY = 'logging.googleapis.com/trace';
import * as trace from '@google-cloud/trace-agent';
trace.start();
import { Logging, detectServiceContext } from '@google-cloud/logging';
let logging = new Logging();

/**
 * Gets the current fully qualified trace ID when available from the
 * @google-cloud/trace-agent library in the LogEntry.trace field format of:
 * "projects/[PROJECT-ID]/traces/[TRACE-ID]".
 *  (not working - took from bunyan logging)
 */
export function getCurrentTraceFromAgent() {
  const globalThis: any = global;
  const agent = globalThis._google_trace_agent;
  if (!agent || !agent.getCurrentContextId || !agent.getWriterProjectId) {
    return null;
  }

  const traceId = agent.getCurrentContextId();
  if (!traceId) {
    return null;
  }

  const traceProjectId = agent.getWriterProjectId();
  if (!traceProjectId) {
    return null;
  }
  return `projects/${traceProjectId}/traces/${traceId}`;
}

export const createLogger = params => {
  let serviceContext;
  const level = params.level || 'INFO';
  const log = logging.log('cloudfunctions.googleapis.com%2Fcloud-functions', {
    removeCircular: true,
  });
  return {
    info: function(additionalData, message = null) {
      if (process.env.FUNCTIONS_EMULATOR) {
        console.log(util.inspect(additionalData, null, 10, true));
        return;
      }
      let event = {};
      // Trying to get the service from process.env or
      // detectServiceContext 
      serviceContext = {
        service: process.env.FUNCTION_NAME || process.env.K_SERVICE,
        resourceType: 'cloud_function',
      };
      if (serviceContext && !serviceContext.service) {
        throw new Error(
          `If 'serviceContext' is specified then ` +
            `'serviceContext.service' is required.`
        );
      }
      if (!serviceContext) {
        detectServiceContext(log.logging.auth).then(
          realServiceContext => {
            serviceContext = realServiceContext;
            console.log('Got new service request', realServiceContext);
          },
          err => {
            console.error(err, 'ERROR GETTING SERVICE CONTEXT');
            /* swallow any errors. */
          }
        );
      }
        event = {
          module: params.name,
          message: additionalData,
        };
      const metadata = {
        resource: {
          type: 'cloud_function',
          serviceContext,
          labels: {
            module: params.name,
            function_name: process.env.FUNCTION_TARGET,
            project: process.env.GCLOUD_PROJECT,
            region: process.env.FUNCTION_REGION,
            ...serviceContext,
          },
        },
        severity: params.level,
        labels: {
          module: params.name,
          // execution_id: // How to get execution id?
          ...serviceContext,
      }
    }
      if (!metadata[LOGGING_TRACE_KEY]) {
        const trace = getCurrentTraceFromAgent();
        if (trace) {
          metadata[LOGGING_TRACE_KEY] = trace;
        }
      }
      metadata.trace = metadata[LOGGING_TRACE_KEY];
      log.write(log.entry(metadata, event)).catch(err => {
        console.error(err);
      });
     }
    }
  };
export default createLogger;

import { createLogger } from '../logger';
const logger = createLogger({ name: TOPIC });
logger.info('something');

But this is only what I get:

No more execution_id. I find it weird that it's not auto filled if available like console.log does.
I've tried to proxy console to intercept .log calls but with no success either.

I didn't want to meddle with the metadata and labels but they weren't getting filled by just
a simple log.write(log.entry(event)).

I was able to find FUNCTION_TARGET in process.env as well as K_SERVICE but the execution id could only be found when received from an onRequest in the req parameter

functions.https.onRequest(async (req, res) => {

Following https://stackoverflow.com/a/55642248/1659084 said I tried

// Http Endpoint
export const runFetcher = functions.https.onRequest(async (req, res) => {
  // global
  const { Logging } = require('@google-cloud/logging');
  const logging = new Logging();
  const Log = logging.log('cloudfunctions.googleapis.com%2Fcloud-functions');
  const LogMetadata = {
    severity: 'INFO',
    type: 'cloud_function',
    labels: {
      function_name: process.env.FUNCTION_NAME,
      project: process.env.GCLOUD_PROJECT,
      region: process.env.FUNCTION_REGION,
    },
  };

  // per request
  const execution_id = req.get('function-execution-id');
  console.log(`Execution id: ${execution_id}`);
  const data = { foo: 'bar' };
  const traceId = req.get('x-cloud-trace-context').split('/')[0];
  console.log(`Trace id: ${traceId}`);
  const metadata = {
    ...LogMetadata,
    severity: 'INFO',
    trace: `projects/${process.env.GCLOUD_PROJECT}/traces/${traceId}`,
    labels: {
      execution_id: execution_id,
    },
  };
  Log.write(Log.entry(metadata, data));

I now get it correctly-ish for http requests.

But from a pubsub from firebase or scheduler

The req parameter isn't there anymore as the call only receives a context parameter:
This is a a dump of this parameter from

functions.pubsub
  .schedule('every 1 minutes')
  .onRun(async context => {
    console.log(util.inspect(context, false, 20, true));

{
    "eventId": "769030521996568",
    "timestamp": "2019-10-01T00:36:00.570Z",
    "eventType": "google.pubsub.topic.publish",
    "resource": {
        "service": "pubsub.googleapis.com",
        "name": "projects/ricochet-1556948300759/topics/firebase-schedule-pollerCrontab-us-central1",
        "type": "type.googleapis.com/google.pubsub.v1.PubsubMessage"
    },
    "params": {}
}

So eventId appears but no trace hash here, Hence me referencing this issue in the other issues.
I've tried stackdiver logging bunyan and winston none of them filled all the params a simple console.log does. But consolelog doesn't allow me to add my own labels and metadata to sift through the logs easily, or ship them elsewhere to be analyzed.

I hope I was kind of clear, hoping for feedback!

[bcoe]

@Elyx0 thank you for the detailed information, this should give us enough context to dig into the issue 👍

[rhodgkins]

I've also raised this in the firebase-functions repo too previously about the missing execution_id firebase/firebase-functions#560

[Elyx0]

Any updates? It's a must have to me to be able to follow an error with additional jsonPayload alongside its execution id

[rthotakura-wp]

Since Cloud Functions logs in Stackdriver are not guaranteed to be printed as a group in consecutive succession (for obvious reasons) this issue greatly hinders our ability to debug (follow the logs of a particular execution) high traffic Cloud Functions.

Workaround or a fix would be much appreciated.

[jpreynat]

Same here, being able to reproduce the behavior of console.log for Node 10 in order to customize it using this module seems essential.

[bcoe]

there's a tracking issue on the product here.

I'm going to share this issue with a few folks, and see if we can't get a few extra eyeballs on it.

[Elyx0]

@bcoe Access denied on your link. I've retried as of today with the latest "everything" for a solid 6 hours again and it's still not there. It's very hard to debug parrallel invocations of the same request without the execution-id available as a global.

I was tempted to define it with a let externally in the global scope and have the .onRequest set it to req.get('function-execution-id') but it's not bulletproof at all. I have no idea how people using firebase at scale are doing. (Mentionned here: #591)

[Elyx0]

Another issue that you probably know @bcoe is that even when I instantiate the logging the latest as possible and not in the global scope, i randomly get

Exception from a finished function: Error: Could not load the default credentials. Browse to https://cloud.google.com/docs/authentication/getting-started for more information.

when trying to log

[bcoe]

@Elyx0 I recommend instantiating the logging client inside of the cloud function:

let logger;
module.exports = function (req, res) {
  if (!logger) {
    logger = new Client();
  }
  await logger.method;
  await logger.method;
}

Note you should also make sure to await all logging actions before sending a response. Cloud functions sleep before a function is invoked, and immediately after it is invoked, so it's important to avoid asynchronous behavior outside of the function itself.

[Elyx0]

Thanks @bcoe , that's where I was a bit mislead I thought all pending logging were a special case that would be drained before the container stops. In https://www.npmjs.com/package/@google-cloud/logging#batching-writes it said to fire-and-forget.

The quick fix would be to build some await allLogsSent() before res.send ?
I wish logs were written and collected outside of the container so I could just await for them.
Or if we could pay for some kind of afterResSendBeforeExit() queue.

I feel a bit betrayed by the serverless promise here. Is it the same for other serverless providers?

[bcoe]

@Elyx0 this is a known issue, and I care about getting it fixed 👍 I hope this isn't a requirement in the future.

[skalashnyk]

@Elyx0 this is a known issue, and I care about getting it fixed 👍 I hope this isn't a requirement in the future.

@bcoe, so there is no way to avoid calling await logger.info() or plain console.log() to log within Google functions environment?

[bcoe]

@skalashnyk as it stands today, as soon as res.send is called, a Cloud Function removes processing, so if you have outstanding logs, they might never be sent, this is something we need to figure out how to fix at a lower level in the cloud function implementation.

[sk-]

@Elyx0 I have a POC hack to achieve this when using javascript Google Cloud functions/Firebase functions.

It'd be great if we could get some support from functions-framework itself.

The patch works as follow, when you are loading your function we patch the express application so that we can add a middleware. This middleware will extract the execution and trace id from the http headers, and set it in the context.

const srcFunctions = require('firebase-functions/lib/cloud-functions');
const onFinished = require('on-finished');
const express = require('express');

function cloudFunctionMiddleware(req, res, next) {
  console.info(JSON.stringify(req.headers));
  const executionId = req.get('function-execution-id');
  console.log(`Execution id: ${executionId}`);
  const traceId = req.get('x-cloud-trace-context');
  console.log(`Trace id: ${traceId}`);
  if (req.body) {
    const event = req.body;
    const {data, context} = event;
    if (data && context) {
      context.executionId = executionId;
      context.traceId = traceId;
    }
  }
  onFinished(res, (err, res) => {
    console.info('finished custom middleware');
  });
  next();
}

function patchFunctionsInvoker() {
  const { all: originalAll, post: originalPost } = express.application;
  express.application.all = function all(path, ...rest) {
    console.info('Express all');
    if (this._router){
    console.info(JSON.stringify(this._router.stack));
    }
    console.info('adding middleware');
    this.use(cloudFunctionMiddleware);
    if (this._router){
      console.info(JSON.stringify(this._router.stack));
    }
    return originalAll.bind(this)(path, ...rest);
  }
  express.application.post = function post(path, ...rest) {
    console.info('Express post');
    if (this._router){
    console.info(JSON.stringify(this._router.stack));
    }
    console.info('adding middleware');
    this.use(cloudFunctionMiddleware);
    if (this._router){
      console.info(JSON.stringify(this._router.stack));
    }
    return originalPost.bind(this)(path, ...rest);
  }
}

patchFunctionsInvoker();

[grant]

For the Functions Framework, we currently don't expose the execution-id (or most other HTTP headers) for events.

I've created an issue here:
GoogleCloudPlatform/functions-framework#34

We need to add it to the Functions Framework contract, then implement it in the frameworks. Comments/thoughts/(or even better - PRs) are welcome :) Was talking to some coworkers about this.

[0xSage]

Hello,

As of v9.5.0, CloudFunctions (and CloudRun/GAE) users can now use this library to synchronously log to STDOUT with class LogSync. Support in Winston/Bunyan may take longer though.

These logs will be picked up by the respective Logging agent and submitted to the API at that level. The advantage to still using this library (instead of just console.log) is i) fewer lines ii) you can toggle btw writing to API vs stdout in dev mode and iii) you will get a richer log - as the LogSync class injects trace/span for you, and lets you log raw http.incomingRequest types, etc.

Recommended usage:

    await logging.setProjectId()
    await logging.setDetectedResource()
    const log = logging.logSync(logname);
    const meta = { // optional field overrides here  }
    const entry = log.entry(meta, 'a log message');
    log.write(entry);

Example of what the log looks like in Cloud Functions (notice the Functions Logging agent doesn't lift custom resource, timestamp and logname fields though - there's a separate ticket out for that. BUT other agents, e.g. GKE Logging agents do lift those fields.):

{
  "insertId": "000000-f6104258-03bf-46c9-b337-4d58d6b0421e",
  "jsonPayload": {
    "logName": "projects/log-bench/logs/my-log",
    "resource": {
      "labels": {
        "function_name": "log-node-func-nicolezh",
        "region": "us-west2"
      },
      "type": "cloud_function"
    },
    "message": "hello world",
    "timestamp": "2021-02-01T01:01:01.001Z"
  },
  "httpRequest": {
    "requestMethod": "POST",
    "requestUrl": "https://google.com",
    "protocol": "https:"
  },
  "resource": {
    "type": "cloud_function",
    "labels": {
      "function_name": "log-node-func-nicolezh",
      "region": "us-west2",
      "project_id": "log-bench"
    }
  },
  "timestamp": "2021-06-22T06:23:34.772Z",
  "severity": "WARNING",
  "labels": {
    "foo": "bar",
    "execution_id": "pkd1hnvh2axq"
  },
  "logName": "projects/log-bench/logs/cloudfunctions.googleapis.com%2Fcloud-functions",
  "receiveTimestamp": "2021-06-22T06:23:45.593884296Z"
}

Let me know if you encounter issues using this - happy to resolve.

[jorgemgr94]

Hello,

As of v9.5.0, CloudFunctions (and CloudRun/GAE) users can now use this library to synchronously log to STDOUT with class LogSync. Support in Winston/Bunyan may take longer though.

These logs will be picked up by the respective Logging agent and submitted to the API at that level. The advantage to still using this library (instead of just console.log) is i) fewer lines ii) you can toggle btw writing to API vs stdout in dev mode and iii) you will get a richer log - as the LogSync class injects trace/span for you, and lets you log raw http.incomingRequest types, etc.

Recommended usage:

    await logging.setProjectId()
    await logging.setDetectedResource()
    const log = logging.logSync(logname);
    const meta = { // optional field overrides here  }
    const entry = log.entry(meta, 'a log message');
    log.write(entry);

Example of what the log looks like in Cloud Functions (notice the Functions Logging agent doesn't lift custom resource, timestamp and logname fields though - there's a separate ticket out for that. BUT other agents, e.g. GKE Logging agents do lift those fields.):

{
  "insertId": "000000-f6104258-03bf-46c9-b337-4d58d6b0421e",
  "jsonPayload": {
    "logName": "projects/log-bench/logs/my-log",
    "resource": {
      "labels": {
        "function_name": "log-node-func-nicolezh",
        "region": "us-west2"
      },
      "type": "cloud_function"
    },
    "message": "hello world",
    "timestamp": "2021-02-01T01:01:01.001Z"
  },
  "httpRequest": {
    "requestMethod": "POST",
    "requestUrl": "https://google.com",
    "protocol": "https:"
  },
  "resource": {
    "type": "cloud_function",
    "labels": {
      "function_name": "log-node-func-nicolezh",
      "region": "us-west2",
      "project_id": "log-bench"
    }
  },
  "timestamp": "2021-06-22T06:23:34.772Z",
  "severity": "WARNING",
  "labels": {
    "foo": "bar",
    "execution_id": "pkd1hnvh2axq"
  },
  "logName": "projects/log-bench/logs/cloudfunctions.googleapis.com%2Fcloud-functions",
  "receiveTimestamp": "2021-06-22T06:23:45.593884296Z"
}

Let me know if you encounter issues using this - happy to resolve.

This feature is now available on Cloud Logging for Bunyan: Node.js Client by feat: Logging provider for Cloud Functions that outputs structured logs to process.stdout #605