Add tracing functionality and a few connectivity state tracers

packages/grpc-js/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@grpc/grpc-js",
-  "version": "0.6.4",
+  "version": "0.6.5",
   "description": "gRPC Library for Node - pure JS implementation",
   "homepage": "https://grpc.io/",
   "repository": "https://github.com/grpc/grpc-node/tree/master/packages/grpc-js",

packages/grpc-js/src/channel.ts

@@ -28,7 +28,7 @@ import { SubchannelPool, getSubchannelPool } from './subchannel-pool';
 import { ChannelControlHelper } from './load-balancer';
 import { UnavailablePicker, Picker, PickResultType } from './picker';
 import { Metadata } from './metadata';
-import { Status } from './constants';
+import { Status, LogVerbosity } from './constants';
 import { FilterStackFactory } from './filter-stack';
 import { CallCredentialsFilterFactory } from './call-credentials-filter';
 import { DeadlineFilterFactory } from './deadline-filter';
@@ -37,6 +37,7 @@ import { CompressionFilterFactory } from './compression-filter';
 import { getDefaultAuthority } from './resolver';
 import { LoadBalancingConfig } from './load-balancing-config';
 import { ServiceConfig } from './service-config';
+import { trace } from './logging';
 
 export enum ConnectivityState {
   CONNECTING,
@@ -265,6 +266,7 @@ export class ChannelImplementation implements Channel {
   }
 
   private updateState(newState: ConnectivityState): void {
+    trace(LogVerbosity.DEBUG, 'connectivity_state', this.target + ' ' + ConnectivityState[this.connectivityState] + ' -> ' + ConnectivityState[newState]);
     this.connectivityState = newState;
     const watchersCopy = this.connectivityStateWatchers.slice();
     for (const watcherObject of watchersCopy) {

packages/grpc-js/src/load-balancer-pick-first.ts

@@ -31,6 +31,14 @@ import {
 } from './picker';
 import { LoadBalancingConfig } from './load-balancing-config';
 import { Subchannel, ConnectivityStateListener } from './subchannel';
+import * as logging from './logging';
+import { LogVerbosity } from './constants';
+
+const TRACER_NAME = 'pick_first';
+
+function trace(text: string): void {
+  logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text);
+}
 
 const TYPE_NAME = 'pick_first';
 
@@ -218,6 +226,7 @@ export class PickFirstLoadBalancer implements LoadBalancer {
       this.subchannels[subchannelIndex].getConnectivityState() ===
       ConnectivityState.IDLE
     ) {
+      trace('Start connecting to subchannel with address ' + this.subchannels[subchannelIndex].getAddress());
       process.nextTick(() => {
         this.subchannels[subchannelIndex].startConnecting();
       });
@@ -228,6 +237,7 @@ export class PickFirstLoadBalancer implements LoadBalancer {
   }
 
   private pickSubchannel(subchannel: Subchannel) {
+    trace('Pick subchannel with address ' + subchannel.getAddress());
     if (this.currentPick !== null) {
       this.currentPick.unref();
       this.currentPick.removeConnectivityStateListener(
@@ -243,6 +253,7 @@ export class PickFirstLoadBalancer implements LoadBalancer {
   }
 
   private updateState(newState: ConnectivityState, picker: Picker) {
+    trace(ConnectivityState[this.currentState] + ' -> ' + ConnectivityState[newState]);
     this.currentState = newState;
     this.channelControlHelper.updateState(newState, picker);
   }
@@ -264,6 +275,7 @@ export class PickFirstLoadBalancer implements LoadBalancer {
    */
   private connectToAddressList(): void {
     this.resetSubchannelList();
+    trace('Connect to address list ' + this.latestAddressList);
     this.subchannels = this.latestAddressList.map(address =>
       this.channelControlHelper.createSubchannel(address, {})
     );

packages/grpc-js/src/logging.ts

@@ -18,7 +18,23 @@
 import { LogVerbosity } from './constants';
 
 let _logger: Partial<Console> = console;
-let _logVerbosity: LogVerbosity = LogVerbosity.DEBUG;
+let _logVerbosity: LogVerbosity = LogVerbosity.ERROR;
+
+if (process.env.GRPC_VERBOSITY) {
+  switch (process.env.GRPC_VERBOSITY) {
+    case 'DEBUG':
+      _logVerbosity = LogVerbosity.DEBUG;
+      break;
+    case 'INFO':
+      _logVerbosity = LogVerbosity.INFO;
+      break;
+    case 'ERROR':
+      _logVerbosity = LogVerbosity.ERROR;
+      break;
+    default:
+      // Ignore any other values
+  }
+}
 
 export const getLogger = (): Partial<Console> => {
   return _logger;
@@ -38,3 +54,12 @@ export const log = (severity: LogVerbosity, ...args: any[]): void => {
     _logger.error(...args);
   }
 };
+
+const enabledTracers = process.env.GRPC_TRACE ? process.env.GRPC_TRACE.split(',') : [];
+const allEnabled = enabledTracers.includes('all');
+
+export function trace(severity: LogVerbosity, tracer: string, text: string): void {
+  if (allEnabled || enabledTracers.includes(tracer)) {
+    log(severity, (new Date().toISOString() + ' | ' + tracer + ' | ' + text));
+  }
+}

packages/grpc-js/src/resolver-dns.ts

@@ -28,6 +28,14 @@ import { ServiceError } from './call';
 import { Status } from './constants';
 import { StatusObject } from './call-stream';
 import { Metadata } from './metadata';
+import * as logging from './logging';
+import { LogVerbosity } from './constants';
+
+const TRACER_NAME = 'dns_resolver';
+
+function trace(text: string): void {
+  logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text);
+}
 
 /* These regular expressions match IP addresses with optional ports in different
  * formats. In each case, capture group 1 contains the address, and capture
@@ -159,6 +167,7 @@ class DnsResolver implements Resolver {
   private percentage: number;
   private defaultResolutionError: StatusObject;
   constructor(private target: string, private listener: ResolverListener) {
+    trace('Resolver constructed for target ' + target);
     this.ipResult = parseIP(target);
     const dnsMatch = DNS_REGEX.exec(target);
     if (dnsMatch === null) {
@@ -187,6 +196,7 @@ class DnsResolver implements Resolver {
    */
   private startResolution() {
     if (this.ipResult !== null) {
+      trace('Returning IP address for target ' + this.target);
       setImmediate(() => {
         this.listener.onSuccessfulResolution(this.ipResult!, null, null);
       });
@@ -222,6 +232,7 @@ class DnsResolver implements Resolver {
             ip4Addresses,
             ip6Addresses
           );
+          trace('Resolved addresses for target ' + this.target + ': ' + allAddresses);
           if (allAddresses.length === 0) {
             this.listener.onError(this.defaultResolutionError);
             return;
@@ -255,6 +266,7 @@ class DnsResolver implements Resolver {
           );
         },
         err => {
+          trace('Resolution error for target ' + this.target + ': ' + (err as Error).message);
           this.pendingResultPromise = null;
           this.listener.onError(this.defaultResolutionError);
         }
@@ -263,6 +275,7 @@ class DnsResolver implements Resolver {
   }
 
   updateResolution() {
+    trace('Resolution update requested for target ' + this.target);
     if (this.pendingResultPromise === null) {
       this.startResolution();
     }

packages/grpc-js/src/resolving-load-balancer.ts

@@ -32,6 +32,14 @@ import { BackoffTimeout } from './backoff-timeout';
 import { Status } from './constants';
 import { StatusObject } from './call-stream';
 import { Metadata } from './metadata';
+import * as logging from './logging';
+import { LogVerbosity } from './constants';
+
+const TRACER_NAME = 'resolving_load_balancer';
+
+function trace(text: string): void {
+  logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text);
+}
 
 const DEFAULT_LOAD_BALANCER_NAME = 'pick_first';
 
@@ -297,6 +305,7 @@ export class ResolvingLoadBalancer implements LoadBalancer {
   }
 
   private updateState(connectivitystate: ConnectivityState, picker: Picker) {
+    trace(this.target + ' ' + ConnectivityState[this.currentState] + ' -> ' + ConnectivityState[connectivitystate]);
     this.currentState = connectivitystate;
     this.channelControlHelper.updateState(connectivitystate, picker);
   }

packages/grpc-js/src/subchannel.ts

@@ -24,9 +24,17 @@ import { PeerCertificate, checkServerIdentity } from 'tls';
 import { ConnectivityState } from './channel';
 import { BackoffTimeout } from './backoff-timeout';
 import { getDefaultAuthority } from './resolver';
+import * as logging from './logging';
+import { LogVerbosity } from './constants';
 
 const { version: clientVersion } = require('../../package.json');
 
+const TRACER_NAME = 'subchannel';
+
+function trace(text: string): void {
+  logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text);
+}
+
 const MIN_CONNECT_TIMEOUT_MS = 20000;
 const INITIAL_BACKOFF_MS = 1000;
 const BACKOFF_MULTIPLIER = 1.6;
@@ -277,6 +285,7 @@ export class Subchannel {
     if (oldStates.indexOf(this.connectivityState) === -1) {
       return false;
     }
+    trace(this.subchannelAddress + ' ' + ConnectivityState[this.connectivityState] + ' -> ' + ConnectivityState[newState]);
     const previousState = this.connectivityState;
     this.connectivityState = newState;
     switch (newState) {
@@ -464,4 +473,8 @@ export class Subchannel {
       ConnectivityState.CONNECTING
     );
   }
+
+  getAddress(): string {
+    return this.subchannelAddress;
+  }
 }