opentelemetry-instrumentation-grpc + nestjs grpc collision

[razcoen]

What version of OpenTelemetry are you using?

0.26.0

What version of Node are you using?

v14.18.0

Please provide the code you used to setup the OpenTelemetry SDK

import process from 'process';
import * as opentelemetry from '@opentelemetry/sdk-node';
import { JaegerExporter } from '@opentelemetry/exporter-jaeger';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';

// configure the SDK to export telemetry data to the console
// enable all auto-instrumentations from the meta package
export const initTracing = (name: string) => {
  const traceExporter = new JaegerExporter({
    endpoint: 'http://main-jaeger-collector.obs:14268/api/traces',
  });
  const sdk = new opentelemetry.NodeSDK({
    resource: new Resource({
      [SemanticResourceAttributes.SERVICE_NAME]: name,
    }),
    traceExporter,
    instrumentations: [
      getNodeAutoInstrumentations()
    ],
  });

  // gracefully shut down the SDK on process exit
  process.on('SIGTERM', () => {
    sdk
      .shutdown()
      .then(() => console.log('Tracing terminated'))
      .catch((error) => console.log('Error terminating tracing', error))
      .finally(() => process.exit(0));
  });
  // initialize the SDK and register with the OpenTelemetry API
  // this enables the API to record telemetry
  return sdk
    .start()
    .then(() => console.log('Tracing initialized'))
    .catch((error) => console.log('Error initializing tracing', error));
};

What did you do?

So I had a NestJS gRPC server up and running with two RPCs:

• Test (Unary)
• TestStream (Client side streaming)

I called initTracing in the main, right before calling NestJS bootstrap.

The TestStream function stopped working, generating this error at the client:
rpc error: code = Unimplemented desc = The server does not implement the method TestStream

Results are the same when using

new GrpcInstrumentation()

instead of

getNodeAutoInstrumentations()

I've debugged the issue, see Additional Context

Recipe

NestJS main:

async function bootstrap() {
  const app = await NestFactory.create(ExampleGrpcServerModule);
  app.connectMicroservice<MicroserviceOptions>({
    transport: Transport.GRPC,
    options: {
      package: 'protos.example',
      protoPath: path.join(__dirname, 'example.proto'),
      url: '0.0.0.0:8080',
    },
  });
  await app.startAllMicroservices();
  await app.listen(3000);
}

initTracing('example-grpc-server');
bootstrap();

NestJS gRPC controller:

@Controller()
export class ExampleController implements protos.example.Example {
  @GrpcMethod('Example', 'Test')
  test(
    req: protos.example.ExampleRequest,
  ): Observable<protos.example.ExampleResponse> {
    return new Observable<protos.example.ExampleResponse>((subscriber) => {
      subscriber.next({
        number: req.number + 1,
      });
      subscriber.complete();
    });
  }

  @GrpcStreamMethod('Example', 'TestStream')
  testStream(
    stream: Observable<protos.example.ExampleRequest>,
  ): Observable<protos.example.ExampleResponse> {
    return new Observable<protos.example.ExampleResponse>((subscriber) => {
      stream.subscribe({
        next: (req) => console.log(req.number),
        complete: () => {
          subscriber.next({ number: 420 });
          subscriber.complete();
        },
        error: (err) => console.log(err),
      });
    });
  }
}

Proto:

syntax = "proto3";

package protos.example;

message ExampleRequest {
    int32 number = 1;
    string name = 2;
}

message ExampleResponse {
    int32 number = 1;
}

service Example {
    rpc Test(ExampleRequest) returns (ExampleResponse) {}
    rpc TestStream(stream ExampleRequest) returns (ExampleResponse) {}
}

Additional context

So I've debugged the issue.
Starting with looking for The server does not implement the method in grpc-js code.
I found out that addService was called only with the Test function and not with TestStream.

I looked into NestJS grpc server code and found that it could not detect the TestStream function as a client stream, you can checkout the detection mechanism here:
https://github.com/nestjs/nest/blob/1394305bf394654a0e2c72142b06bd29277718d9/packages/microservices/server/server-grpc.ts#L98-L157

So I printed out the GrpcObject before and after instrumentation and noticed some changes.
Before grpc instrumentation the object looked like this:

Client {
  Test: [Function (anonymous)] {
    path: '/protos.example.Example/Test',
    requestStream: false,
    responseStream: false,
    requestSerialize: [Function: serialize],
    requestDeserialize: [Function: deserialize],
    responseSerialize: [Function: serialize],
    responseDeserialize: [Function: deserialize],
    originalName: 'test',
    requestType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    },
    responseType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    }
  },
  test: [Function (anonymous)] {
    path: '/protos.example.Example/Test',
    requestStream: false,
    responseStream: false,
    requestSerialize: [Function: serialize],
    requestDeserialize: [Function: deserialize],
    responseSerialize: [Function: serialize],
    responseDeserialize: [Function: deserialize],
    originalName: 'test',
    requestType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    },
    responseType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    }
  },
  TestStream: [Function (anonymous)] {
    path: '/protos.example.Example/TestStream',
    requestStream: true,
    responseStream: false,
    requestSerialize: [Function: serialize],
    requestDeserialize: [Function: deserialize],
    responseSerialize: [Function: serialize],
    responseDeserialize: [Function: deserialize],
    originalName: 'testStream',
    requestType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    },
    responseType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    }
  },
  testStream: [Function (anonymous)] {
    path: '/protos.example.Example/TestStream',
    requestStream: true,
    responseStream: false,
    requestSerialize: [Function: serialize],
    requestDeserialize: [Function: deserialize],
    responseSerialize: [Function: serialize],
    responseDeserialize: [Function: deserialize],
    originalName: 'testStream',
    requestType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    },
    responseType: {
      format: 'Protocol Buffer 3 DescriptorProto',
      type: [Object],
      fileDescriptorProtos: [Array]
    }
  }
}

After grpc instrumentation the object looked like this:

Client {
  Test: [Function: clientMethodTrace],
  test: [Function: clientMethodTrace],
  TestStream: [Function: clientMethodTrace],
  testStream: [Function: clientMethodTrace]
}

I dag into the gRPC instrumentation code and found this function (that generates the clientMethodTrace):

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-grpc/src/grpc-js/index.ts

Lines 268 to 294 in 4e311bd

	/**
	* Parse initial client call properties and start a span to trace its execution
	*/
	private _getPatchedClientMethods(
	grpcClient: typeof grpcJs
	): (original: GrpcClientFunc) => () => EventEmitter {
	const instrumentation = this;
	return (original: GrpcClientFunc) => {
	instrumentation._diag.debug('patch all client methods');
	return function clientMethodTrace(this: grpcJs.Client) {
	const name = `grpc.${original.path.replace('/', '')}`;
	const args = [...arguments];
	const metadata = getMetadata.call(
	instrumentation,
	grpcClient,
	original,
	args
	);
	const span = instrumentation.tracer.startSpan(name, {
	kind: SpanKind.CLIENT,
	});
	return context.with(trace.setSpan(context.active(), span), () =>
	makeGrpcClientRemoteCall(original, args, metadata, this)(span)
	);
	};
	};
	}

Basically the original is a function and an object.
The returned function clientMethodTrace is without those extra object entries .
(NestJS detects request/response stream by calling function.requestStream and function.responseStream which does not exist after instrumentation)

I think the correct behavior is to assign all the entries from original back to clientMethodTrace, but I might be wrong.
However I don't think NestJS should change their code since they only rely on grpc-js and it works perfectly fine with it.

Assigning the fields form original back to clientMethodTrace fixed this issue for me.