From 81a1aa17b24cba3f81c0e13f9870503cc358fe1c Mon Sep 17 00:00:00 2001 From: murgatroid99 Date: Fri, 4 Oct 2019 10:21:15 -0700 Subject: [PATCH] Add tracing functionality and a few connectivity state tracers --- packages/grpc-js/package.json | 2 +- packages/grpc-js/src/channel.ts | 4 ++- .../grpc-js/src/load-balancer-pick-first.ts | 12 +++++++++ packages/grpc-js/src/logging.ts | 27 ++++++++++++++++++- packages/grpc-js/src/resolver-dns.ts | 13 +++++++++ .../grpc-js/src/resolving-load-balancer.ts | 9 +++++++ packages/grpc-js/src/subchannel.ts | 13 +++++++++ 7 files changed, 77 insertions(+), 3 deletions(-) diff --git a/packages/grpc-js/package.json b/packages/grpc-js/package.json index fac20634..38e10479 100644 --- a/packages/grpc-js/package.json +++ b/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", diff --git a/packages/grpc-js/src/channel.ts b/packages/grpc-js/src/channel.ts index b2fdb654..5fac0ef9 100644 --- a/packages/grpc-js/src/channel.ts +++ b/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) { diff --git a/packages/grpc-js/src/load-balancer-pick-first.ts b/packages/grpc-js/src/load-balancer-pick-first.ts index d1252507..0771abbe 100644 --- a/packages/grpc-js/src/load-balancer-pick-first.ts +++ b/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, {}) ); diff --git a/packages/grpc-js/src/logging.ts b/packages/grpc-js/src/logging.ts index 859b3ac5..31e38e4d 100644 --- a/packages/grpc-js/src/logging.ts +++ b/packages/grpc-js/src/logging.ts @@ -18,7 +18,23 @@ import { LogVerbosity } from './constants'; let _logger: Partial = 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 => { 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)); + } +} \ No newline at end of file diff --git a/packages/grpc-js/src/resolver-dns.ts b/packages/grpc-js/src/resolver-dns.ts index a8546f1c..a6b0ae16 100644 --- a/packages/grpc-js/src/resolver-dns.ts +++ b/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(); } diff --git a/packages/grpc-js/src/resolving-load-balancer.ts b/packages/grpc-js/src/resolving-load-balancer.ts index 16d72539..f6680115 100644 --- a/packages/grpc-js/src/resolving-load-balancer.ts +++ b/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); } diff --git a/packages/grpc-js/src/subchannel.ts b/packages/grpc-js/src/subchannel.ts index 9148746f..cbf517cb 100644 --- a/packages/grpc-js/src/subchannel.ts +++ b/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; + } }