Functions v2 missing labels with Firebase structured logs

[metadiego]

Firebase logger structured logs for v2 Cloud functions are missing labels.

This causes a secondary issue, which is that, when trying to access function logs from Firebase console, the logs are empty. Reason being that the URL generated when you click 'View Logs' (see screenshot below) assumes that the function has appropriate labels, but it does not:

Related issues

Maybe this: https://github.com/firebase/firebase-functions/issues/703

[REQUIRED] Version info

node:16 firebase-functions:3.24.1 firebase-tools:11.19.0 firebase-admin:11.3.0

[REQUIRED] Test case

Create a log from a v2 Cloud Function. Invoke the function. Go to Firebase console > Functions. Click on 'View logs' for previously created function. Logs will be empty because labels are missing.

[REQUIRED] Steps to reproduce

Create a v2 Cloud Function and, using logger, create a structured log, for example:

      functions.logger.debug('Hello world', { structuredData: true });

Inspect the output in your logs.

[REQUIRED] Expected behavior

v2 function logs are similar to v1 function logs, which include labels: function name and version, like this example v1 log label:

[REQUIRED] Actual behavior

v2 function does not include any labels.

Were you able to successfully deploy your functions?

Yes.

No

[google-oss-bot]

I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.

[dan-wu-open]

Ah yes, I ran into this as well, and created a ticket here https://github.com/firebase/firebase-js-sdk/issues/6925

Basically, V2. functions are grouped under the "Cloud Run Revision" resource type. If you look in my linked ticket, you'll see that they had this same bug in the cloud function logging packages for Go + Java.

[metadiego]

Hey @dan-wu-open, thanks for your reply. I don't understand why your ticket was closed, though, as the issue seems to be unsolved. I don't see how the reply to your problem - linking to https://github.com/firebase/firebase-functions - addresses the issue. Am I missing something?

[dan-wu-open]

I think it's because the root cause is with firebase-functions, so we need to make a change in that package, rather than in firebase-js-sdk

[metadiego]

Oh got it, thanks for the clarification @dan-wu-open. Guess this issue is in the right place then.

[pgainullin]

As a work-around using resource.labels.configuration_name instead of resource.labels.function_name seems to work (although note that underscrores in the function names will need to be replaced with hyphens).

[indicava]

I just migrated my first project from gen1 to gen2 callable functions and the logging is just terrible. It's not just that the labels are (still) missing but with gen1 function execution time appeared in the "function finished..." built in log message. Also any custom logging done in code is also missing labels. Huge downgrade from gen1 log message structure.

[glumb]

I also just upgraded to gen 2.

When looking at the logs I was surprised that it is no longer possible to filter logs which belong to one invocation, as 'execution_id' is missing. This is a crucial mechanism to inspect the logs in order to trace what happened during this particular invocation.

How to do that without the labels? No mention of this topic in the migration guide either.

[brunapereira]

Is there any track of this issue? I just upgrade to v2 and I don't have the execution id anymore, nor the function name anywhere in the logs. And the logs of execution started and execution finished are missing. Is there going to be any feature related to that in the following releases? I'm kinda disapointed..

[clivi-kj]

Need this as well

[clivi-kj]

Has anyone figured out a workaround to filter by one execution?

[lox]

Is anyone at Google actually listening to these issues? The V2 functions seem broken in so many ways.

[glumb]

Has anyone figured out a workaround to filter by one execution?

We created a custom wrapper for the logging. First for every invocation, a random value is created and used as execution ID. We pass this object as last argument to the log methods.

export function createExtendedLogContext(): ExtendedLogContext {
  // create a random execution id with 10 digits and chars
  const execution_id = Math.random().toString(36).substring(2, 12)

  return {
    'logging.googleapis.com/labels': {
      execution_id,
      function_name: process.env.FUNCTION_NAME || ''
    }
  }
}

[HonahleeWill]

Just ran into this issue when migrating from v1 function to v2.

With v1 functions I made no changes to my codebase, and all logging through console.log had an execution id attached. This allowed me to match log lines with requests using the labels.execution_id.

The v1 docs say that you need to include a compatibility patch to get this behaviour, but I did not. Seems this was the default behaviour.

Moving to v2 I noticed:

• console.log no longer patched by default
• Including the patch as per v2 docs does not do anything

My workaround:

• Use the firebase log functions from "firebase-functions/logger"
• labels.execution_id is gone, appears to be replaced by trace

If you want to do something like @glumb I would suggest looking at the "x-cloud-trace-context" header that cloud functions receive. You can extract the trace id from this header. This would allow you to join your log requests with the standard log lines.

Really surprised to see no mention of this change on the version comparison chart.

[lox]

How does one get at the headers outside of onRequest / onCall @HonahleeWill?

[HonahleeWill]

How does one get at the headers outside of onRequest / onCall @HonahleeWill?

Not gonna be possible as far as I know. The trace is generated per-request, so you will need access to the request headers to read it. You will need to generate a new logging context for each request (also ensure that context isn't shared by other requests).

[lox]

Looks like the code in https://github.com/firebase/firebase-functions/blob/3e7a4b77967e46a067712445c499c5df005b8e31/src/logger/index.ts#L158 is reading from traceId set somewhere, but I wasn't able to find where in firebase-functions that traceId was actually set.

[HonahleeWill]

I ended up just writing my own patch for console logging. This might help you @lox:

import { log as logFirebase, debug as debugFirebase, info as infoFirebase, warn as warnFirebase, error as errorFirebase } from 'firebase-functions/logger';

console.log = logFirebase;
console.debug = debugFirebase;
console.info = infoFirebase;
console.warn = warnFirebase;
console.error = errorFirebase;

[lox]

@HonahleeWill nope, will still not help due to https://github.com/firebase/firebase-functions/pull/1440 not being released.

[ciriousjoker]

@lox #1440 is released now (v4.5.0)

[exaby73]

Hello @lox @metadiego. With the release of #1440, is the logging working as expected?

[ciriousjoker]

• I suspect that this won't solve the issue, because #1440 only wrapped Firestore function trigger handlers in wrapTraceContext
• onRequest is already wrapping its handler, but onCall isn't yet (#1487)

[lox]

That is a bummer :(

[google-oss-bot]

Hey @metadiego. We need more information to resolve this issue but there hasn't been an update in 7 weekdays. I'm marking the issue as stale and if there are no new updates in the next 3 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[lox]

What information is needed? I don't believe this is fixed yet.

[exaby73]

@lox The label wasn't automatically removed since the OP didn't reply. Sorry about that, remove it and labeled it

[fgatti675]

Any estimates on when this will be fixed?

[stamler]

One year, still an issue :(

[abdalamichel]

any updates ? i have migrates from v1 to v2 and every trace indicator is missing from onDocumentCreated or onDocumentUpdated.

Also is really hard to follow traces for new v2 cloud functions. Have to edit Summary fields all the times and its not integrated with Log Explorer as v1 was.

I m considering moving back to v1 because every issue is a tragedy to analyze

[orestesgaolin]

We retracted from v2 to v1 mostly due to this issue. Fortunately it was just a fraction of functions that we've experimented with v2.

[fgatti675]

Yes honestly, this is incredibly frustrating. And time continues to pass and we have 0 news. There is no simple way to see a full log trace. Why was this product released in this state? I mean, no one at Google is using this service and being bothered just like the rest of us? We are paying for a suboptimal service and should not be thinking about downgrading. Please do something

[AliCuchalloGabrielFerando]

In terms of performance to develop, it did not improve performance. That is my conclusion.

[AndreRLima]

What if we open a ticket at https://issuetracker.google.com/ telling them the issue. And then we discuss it in there, I have seen bigger problems being reported there and the guys from Google took some time, but after some pressure the problem was fixed.

[lox]

@AndreRLima are you referring specifically to missing labels other than trace contexts? This issue is a bit all over the place. Most of the function types seem to have had trace contexts added now.

[AndreRLima]

@lox Yes, I am referring to missing labels

[lox]

@AndreRLima so just the function name and the revision id?

[AndreRLima]

@lox Yeah, I would say so, but the tracing is still strange, v1 tracing is way better than v2

This how my log looks like.

I am using import { onRequest } from 'firebase-functions/v2/https';

[lox]

This is how mine look using a v2 onCall handler:

I have resource.labels.service_name added to my summary fields.

[AndreRLima]

@lox cool, thanks. Yeah, I did not know that you could add like that. Just in case someone does not know as well.

You need to do the following:

1. Go to the Google Cloud Console.
2. Navigate to Logging -> Logs Explorer.
3. Click on the Edit button next to Summary fields.
4. In the dropdown, select resource.labels.service_name and click Add.

[deepak-agendaboa]

In v1, there is execution_id. Using this execution id, it is very easy to check the logs. labels.execution_id="id" But in v2, there is no such thing.

[lox]

@deepak-agendaboa I believe that is because in v1 cloudfunctions were used, v2 is cloudrun. Most function types include a trace now, which should be functionally comparable.

[AndreRLima]

Hi @lox, is it possible to save the Summary field resource.labels.service_name to always show up? Every time that I open a new tab I need to do steps that put here, so that I can see it.

[lox]

@AndreRLima Yup, summary fields can be saved in a saved search.

[blidd-google]

Hey folks, Brian here from the Cloud Functions for Firebase team. Sorry to hear that many of you have been frustrated or confused by the logging experience in 2nd gen functions - we appreciate your feedback, and are working to alleviate this pain point in the migration process from 1st gen. That said, I'd like to address the various points people have discussed on this thread:

Labels

2nd gen functions are Cloud Run services under the hood. Running the following query in the Cloud Logs Explorer should display all logs relevant to a specific function:

(resource.type = "cloud_function"
resource.labels.function_name = "foo"
resource.labels.region = "us-central1")
 OR 
(resource.type = "cloud_run_revision"
resource.labels.service_name = "foo"
resource.labels.location = "us-central1")
 severity>=DEFAULT

By default, navigating to the Cloud Logs Explorer on either the Firebase Console or the function details page on the Cloud Console will run this query. Some of the folks in this thread have provided helpful guidance above on adding summary fields to label log entries from a specific function.

Tracing

In the last few months, our team found that a couple of 2nd gen trigger types were not tracking the trace context. We've recently reviewed all supported trigger types in 2nd gen to ensure logs from each invocation will be linked together by their common trace ID.

The trace ID can be found in the payload of an expanded log entry (trace: projects/<project_name>/traces/<trace_id>). Adding trace=<trace_id> will run a query for all logs that are tagged with trace_id.

Alternatively, log entries with trace context will show up in the Cloud Console with an icon of a few horizontal lines:

Clicking that icon will display a menu, from which you can select "Show entries from this trace" to filter the logs for entires with the same trace ID.

Thanks all for your patience - seeing as logging is now working as intended, I'm going to close this issue out. Please feel free to open a new issue if you are still experiencing problems with logging in 2nd gen.

[orestesgaolin]

Hi! I'm still a bit confused with how the logs are organized with v2, so maybe you could clarify what to expect in the future?

I've just deployed sample v2 function using nodejs and it seems that its logs are not present in the Cloud Functions resource type anymore. However, the mention of the deployment is still there (function deployed via firebase deploy). The logs for the v2 function are available under Cloud Run Revision. Are there any plans to unify this behavior? I'd love to be able to see both v2 and v1 functions under the same resource type, especially during transition period.

[lox]

V2 functions have moved from Cloud Functions to Cloud Run, that sounds like very expected behaviour @orestesgaolin?

[abdulaziz-mohammed]

it's still missing trace id. I would like to debug a hit to an edpoint isolated from any other requests like it used to be with functions v1. now it's all mixed

please help

[blidd-google]

Hi @abdulaziz-mohammed, which trigger type do you have deployed that when invoked is missing the trace ID? Could you open a new issue with a reproducible example? It would really help us get to the bottom of the issue you are dealing with.

[leonelqf]

I really miss the fields "execution id" and "function name" from entries by default...

[jobweegink]

The trace ID can be found in the payload of an expanded log entry

@blidd-google This seems not to be the case for an onDocumentWritten event, when I click "Show entries from this trace" it only shows one log line. Can you validate this, then I can open a new issue.