diff --git a/packages/grpc-js-xds/interop/Dockerfile b/packages/grpc-js-xds/interop/Dockerfile index e8a0a98c..b93e309d 100644 --- a/packages/grpc-js-xds/interop/Dockerfile +++ b/packages/grpc-js-xds/interop/Dockerfile @@ -33,6 +33,6 @@ COPY --from=build /node/src/grpc-node/packages/grpc-js ./packages/grpc-js/ COPY --from=build /node/src/grpc-node/packages/grpc-js-xds ./packages/grpc-js-xds/ ENV GRPC_VERBOSITY="DEBUG" -ENV GRPC_TRACE=xds_client,xds_resolver,cds_balancer,eds_balancer,priority,weighted_target,round_robin,resolving_load_balancer,subchannel,keepalive,dns_resolver,fault_injection,http_filter,csds +ENV GRPC_TRACE=xds_client,xds_resolver,cds_balancer,eds_balancer,priority,weighted_target,round_robin,resolving_load_balancer,subchannel,keepalive,dns_resolver,fault_injection,http_filter,csds,outlier_detection ENTRYPOINT [ "node", "/node/src/grpc-node/packages/grpc-js-xds/build/interop/xds-interop-client" ] diff --git a/packages/grpc-js/src/load-balancer-outlier-detection.ts b/packages/grpc-js/src/load-balancer-outlier-detection.ts index dde618b7..e9793bea 100644 --- a/packages/grpc-js/src/load-balancer-outlier-detection.ts +++ b/packages/grpc-js/src/load-balancer-outlier-detection.ts @@ -18,7 +18,7 @@ import { ChannelOptions, connectivityState, StatusObject } from "."; import { Call } from "./call-stream"; import { ConnectivityState } from "./connectivity-state"; -import { Status } from "./constants"; +import { LogVerbosity, Status } from "./constants"; import { durationToMs, isDuration, msToDuration } from "./duration"; import { ChannelControlHelper, createChildChannelControlHelper, registerLoadBalancerType } from "./experimental"; import { BaseFilter, Filter, FilterFactory } from "./filter"; @@ -28,7 +28,13 @@ import { PickArgs, Picker, PickResult, PickResultType, QueuePicker, UnavailableP import { Subchannel } from "./subchannel"; import { SubchannelAddress, subchannelAddressToString } from "./subchannel-address"; import { BaseSubchannelWrapper, ConnectivityStateListener, SubchannelInterface } from "./subchannel-interface"; +import * as logging from './logging'; +const TRACER_NAME = 'outlier_detection'; + +function trace(text: string): void { + logging.trace(LogVerbosity.DEBUG, TRACER_NAME, text); +} const TYPE_NAME = 'outlier_detection'; @@ -412,6 +418,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { if (!successRateConfig) { return; } + trace('Running success rate check'); // Step 1 const targetRequestVolume = successRateConfig.request_volume; let addresesWithTargetVolume = 0; @@ -424,6 +431,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { successRates.push(successes/(successes + failures)); } } + trace('Found ' + addresesWithTargetVolume + ' success rate candidates; currentEjectionPercent=' + this.getCurrentEjectionPercent() + ' successRates=[' + successRates + ']'); if (addresesWithTargetVolume < successRateConfig.minimum_hosts) { return; } @@ -438,9 +446,10 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { const successRateVariance = successRateDeviationSum / successRates.length; const successRateStdev = Math.sqrt(successRateVariance); const ejectionThreshold = successRateMean - successRateStdev * (successRateConfig.stdev_factor / 1000); + trace('stdev=' + successRateStdev + ' ejectionThreshold=' + ejectionThreshold); // Step 3 - for (const mapEntry of this.addressMap.values()) { + for (const [address, mapEntry] of this.addressMap.entries()) { // Step 3.i if (this.getCurrentEjectionPercent() > this.latestConfig.getMaxEjectionPercent()) { break; @@ -453,9 +462,12 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { } // Step 3.iii const successRate = successes / (successes + failures); + trace('Checking candidate ' + address + ' successRate=' + successRate); if (successRate < ejectionThreshold) { const randomNumber = Math.random() * 100; + trace('Candidate ' + address + ' randomNumber=' + randomNumber + ' enforcement_percentage=' + successRateConfig.enforcement_percentage); if (randomNumber < successRateConfig.enforcement_percentage) { + trace('Ejecting candidate ' + address); this.eject(mapEntry, ejectionTimestamp); } } @@ -470,13 +482,14 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { if (!failurePercentageConfig) { return; } + trace('Running failure percentage check. threshold=' + failurePercentageConfig.threshold + ' request volume threshold=' + failurePercentageConfig.request_volume); // Step 1 if (this.addressMap.size < failurePercentageConfig.minimum_hosts) { return; } // Step 2 - for (const mapEntry of this.addressMap.values()) { + for (const [address, mapEntry] of this.addressMap.entries()) { // Step 2.i if (this.getCurrentEjectionPercent() > this.latestConfig.getMaxEjectionPercent()) { break; @@ -484,6 +497,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { // Step 2.ii const successes = mapEntry.counter.getLastSuccesses(); const failures = mapEntry.counter.getLastFailures(); + trace('Candidate successes=' + successes + ' failures=' + failures); if (successes + failures < failurePercentageConfig.request_volume) { continue; } @@ -491,7 +505,9 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { const failurePercentage = (failures * 100) / (failures + successes); if (failurePercentage > failurePercentageConfig.threshold) { const randomNumber = Math.random() * 100; + trace('Candidate ' + address + ' randomNumber=' + randomNumber + ' enforcement_percentage=' + failurePercentageConfig.enforcement_percentage); if (randomNumber < failurePercentageConfig.enforcement_percentage) { + trace('Ejecting candidate ' + address); this.eject(mapEntry, ejectionTimestamp); } } @@ -525,6 +541,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { private runChecks() { const ejectionTimestamp = new Date(); + trace('Ejection timer running'); this.switchAllBuckets(); @@ -537,7 +554,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { this.runSuccessRateCheck(ejectionTimestamp); this.runFailurePercentageCheck(ejectionTimestamp); - for (const mapEntry of this.addressMap.values()) { + for (const [address, mapEntry] of this.addressMap.entries()) { if (mapEntry.currentEjectionTimestamp === null) { if (mapEntry.ejectionTimeMultiplier > 0) { mapEntry.ejectionTimeMultiplier -= 1; @@ -548,6 +565,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { const returnTime = new Date(mapEntry.currentEjectionTimestamp.getTime()); returnTime.setMilliseconds(returnTime.getMilliseconds() + Math.min(baseEjectionTimeMs * mapEntry.ejectionTimeMultiplier, Math.max(baseEjectionTimeMs, maxEjectionTimeMs))); if (returnTime < new Date()) { + trace('Unejecting ' + address); this.uneject(mapEntry); } } @@ -564,6 +582,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { } for (const address of subchannelAddresses) { if (!this.addressMap.has(address)) { + trace('Adding map entry for ' + address); this.addressMap.set(address, { counter: new CallCounter(), currentEjectionTimestamp: null, @@ -574,6 +593,7 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { } for (const key of this.addressMap.keys()) { if (!subchannelAddresses.has(key)) { + trace('Removing map entry for ' + key); this.addressMap.delete(key); } } @@ -585,15 +605,18 @@ export class OutlierDetectionLoadBalancer implements LoadBalancer { if (lbConfig.getSuccessRateEjectionConfig() || lbConfig.getFailurePercentageEjectionConfig()) { if (this.timerStartTime) { + trace('Previous timer existed. Replacing timer'); clearTimeout(this.ejectionTimer); const remainingDelay = lbConfig.getIntervalMs() - ((new Date()).getTime() - this.timerStartTime.getTime()); this.startTimer(remainingDelay); } else { + trace('Starting new timer'); this.timerStartTime = new Date(); this.startTimer(lbConfig.getIntervalMs()); this.switchAllBuckets(); } } else { + trace('Counting disabled. Cancelling timer.'); this.timerStartTime = null; clearTimeout(this.ejectionTimer); }