Console instrumentation ignore span context when calling pushLog

[mxab]

Description

When using e.g. console.info(... inside an active span the instrumented console doesn't provide the span context to the pushLogs call

https://github.com/grafana/faro-web-sdk/blob/3f200325c1ae146526e8b71ebb6deed391958b36/packages/web-sdk/src/instrumentations/console/instrumentation.ts#L24

If this is missing the pushLog doesn't attach tracing infos to the log statment

https://github.com/grafana/faro-web-sdk/blob/3f200325c1ae146526e8b71ebb6deed391958b36/packages/core/src/api/logs/initialize.ts#L36

Steps to reproduce

  faro.api
      .getOTEL()
      ?.trace.getTracer('frontend')
      .startActiveSpan('hello world', (span) => {
        // send a log message

        console.info("sending hello to backend")

Expected behavior

When using console.info inside a active span the logs should have trace data

Actual behavior

No trace / span data inside the logs on the faro side for kind=log log entries

Environment

• SDK version: 1.8.0

[mxab]

Ok, so I miss read the code it falls back on calling the tracesApi.getTraceContext() if no span context is provided.

But if I debug it in the browser the otel.trace.getSpanContext(otel.context.active()) returns an undefined context

But the console.log is called inside an active span:

Any ideas what I'm missing @codecapitano ?

[codecapitano]

Hi @mxab I tested it in the Faro demo. But I think there's an issue because I got another ask recently because of an undefined context.

Screenshot from the demo.

[codecapitano]

@mxab When and were do you initialize Faro? Do you maybe have something else running which initializes otel?

Maybe you can share your Faro config?

[codecapitano]

But if I debug it in the browser the otel.trace.getSpanContext(otel.context.active()) returns an undefined context

getSpanConext is fetching the context with this line of code:
const ctx = otel?.trace.getSpanContext(otel.context.active());

If there's no active span it returns undefined because it can't find an active context.

[mxab]

Hmm the otel.context.active() returns a value

But the returned base context seems to be empty, there fore not finding any span context.

The general init is an angular application

import { ErrorHandler, NgModule, APP_INITIALIZER } from '@angular/core';
import { BrowserModule } from '@angular/platform-browser';

import { AppRoutingModule } from './app-routing.module';
import { AppComponent } from './app.component';
import { HomeComponent } from './home/home.component';
import { ReactiveFormsModule } from '@angular/forms';
import { provideHttpClient, withInterceptorsFromDi } from '@angular/common/http';
import { FaroErrorHandler } from './errors';

import { getWebInstrumentations, initializeFaro, createSession, faro } from '@grafana/faro-web-sdk';
import { TracingInstrumentation } from '@grafana/faro-web-tracing';
import { NavigationStart, Router } from '@angular/router';
import { filter, map } from 'rxjs';


function initFaro(router: Router): Function {
  return async () => {

    initializeFaro({  // <---------------------------------------------------------INIT FARO
      url: 'http://localhost:12347/collect',

      apiKey: 'secret',
      app: {
        name: 'my-angular-app',
        version: '1.0.0',
        environment: 'development'

      },
      sessionTracking: {
        enabled: true,
        session: createSession({
        }),
      },
      instrumentations: [...getWebInstrumentations(), new TracingInstrumentation(
        {
          instrumentationOptions: {
            // Requests to these URLs will have tracing headers attached.
            propagateTraceHeaderCorsUrls: [new RegExp('http://localhost:8080/*'), new RegExp('http://localhost:8000/*')],
          },
        }
      )],
    });
   // --------------------------------------------- end init

  // ---------------------------------------------- configure faro view setting
    router.events.pipe(
      filter(e => e instanceof NavigationStart),
      map(e => e as NavigationStart))
      .subscribe((e: NavigationStart) => {
        faro.api.setView({
          name: e.url
        })
      })
  //---------------------------------------------- end faro view
  }
}


@NgModule({
  declarations: [
    AppComponent,
    HomeComponent
  ],
  bootstrap: [AppComponent],
  imports: [BrowserModule, ReactiveFormsModule, AppRoutingModule],
  providers: [
    { provide: APP_INITIALIZER, useFactory: initFaro, multi: true, deps: [Router] }, // <------------------ faro init via APP_INITIALIZER
    { provide: ErrorHandler, useClass: FaroErrorHandler },
    provideHttpClient(withInterceptorsFromDi())
  ]
})
export class AppModule { }

```


I have another application which uses 1.6.0 where it works. The setup looks similar. Investigating more....

[codecapitano]

Thank you so much Max 🙏 Please don't hesitate to ask or when you want to validate assumptions. You can also find ob the Faro community Slack

Hmm ok, with 1.8.0 we update the otel dependencies in the web-tracing and Faro core packages.

Cheers

[codecapitano]

Maybe an idea: I see that the initOtel(trace, context)) function in faro core doesn't validate the inputs.

Maybe it happens that it gets called multiple times and overwrites the context with undefined at the last call. 🤔

[mxab]

I downgraded to 1.6.0 but the issue remain.

I noticed when I the console.info inside the .startActiveSpan('hello world', (span) => {

The span it self has a value of a NonRecordingSpan3 

{
    "_spanContext": {
        "traceId": "00000000000000000000000000000000",
        "spanId": "0000000000000000",
        "traceFlags": 0
    }
}

    faro.api
      .getOTEL()
      ?.trace.getTracer('frontend')
      .startActiveSpan('hello world', (span) => {
        // send a log message

        console.info("sending hello to backend")
        const request$ = this.http.get<{message: string, id: number}>(backend, {
          params: {
            name
          }
        });

        lastValueFrom(request$).then((res) => {
          console.info("got response from backend ", res.message)
          this.results.push(res);
        }).finally(() => {
          span.end();
        });

        

      });
     

[codecapitano]

Did you already try the otel logger?

Right before calling the Faro init function you can enable otel logging.

import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
// ...
 diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.ALL);

And you can also enable Faro debug logs

initializefaro({
  // ...
  internalLoggerLevel: InternalLoggerLevel.VERBOSE
})

[mxab]

Sorry for the late response, somehow I missed that message. I added the dialog and verbose parts, but I don't see any verbose logs anywhere

[codecapitano]

You should see them in the browsers console, no?

[mxab]

Hi @codecapitano sorry for responding so late, I got dragged into other issues and hey suddenly its half a year later :D

It looks like the issue is resolved with a newer version of faro.

Any ways thank you for your support on that issue!

[codecapitano]

Hey @mxab no worries at all and many thanks for the update :) Glad it's working now.

Thanks for opening the issue and making Faro better. Please keep asking and reporting.

Cheers