Skip to content

Commit eba699a

Browse files
temawitemawi
authored
rls: Adding extra debug logs (#10902)
1 parent 0447497 commit eba699a

File tree

2 files changed

+57
-1
lines changed

2 files changed

+57
-1
lines changed

‎rls/src/main/java/io/grpc/rls/CachingRlsLbClient.java

+47
Original file line numberDiff line numberDiff line change
@@ -196,6 +196,7 @@ static Status convertRlsServerStatus(Status status, String serverName) {
196196

197197
@CheckReturnValue
198198
private ListenableFuture<RouteLookupResponse> asyncRlsCall(RouteLookupRequest request) {
199+
logger.log(ChannelLogLevel.DEBUG, "Making an async call to RLS");
199200
final SettableFuture<RouteLookupResponse> response = SettableFuture.create();
200201
if (throttler.shouldThrottle()) {
201202
logger.log(ChannelLogLevel.DEBUG, "Request is throttled");
@@ -224,6 +225,7 @@ public void onError(Throwable t) {
224225

225226
@Override
226227
public void onCompleted() {
228+
logger.log(ChannelLogLevel.DEBUG, "routeLookup call completed");
227229
throttler.registerBackendResponse(false);
228230
}
229231
});
@@ -237,10 +239,13 @@ public void onCompleted() {
237239
*/
238240
@CheckReturnValue
239241
final CachedRouteLookupResponse get(final RouteLookupRequest request) {
242+
logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to get cached entry");
240243
synchronized (lock) {
244+
logger.log(ChannelLogLevel.DEBUG, "Acquired lock to get cached entry");
241245
final CacheEntry cacheEntry;
242246
cacheEntry = linkedHashLruCache.read(request);
243247
if (cacheEntry == null) {
248+
logger.log(ChannelLogLevel.DEBUG, "No cache entry found, making a new lrs request");
244249
return handleNewRequest(request);
245250
}
246251

@@ -249,10 +254,12 @@ final CachedRouteLookupResponse get(final RouteLookupRequest request) {
249254
logger.log(ChannelLogLevel.DEBUG, "Cache hit for the request");
250255
DataCacheEntry dataEntry = ((DataCacheEntry) cacheEntry);
251256
if (dataEntry.isStaled(ticker.read())) {
257+
logger.log(ChannelLogLevel.DEBUG, "Cache entry is stale");
252258
dataEntry.maybeRefresh();
253259
}
254260
return CachedRouteLookupResponse.dataEntry((DataCacheEntry) cacheEntry);
255261
}
262+
logger.log(ChannelLogLevel.DEBUG, "Cache hit for a backup entry");
256263
return CachedRouteLookupResponse.backoffEntry((BackoffCacheEntry) cacheEntry);
257264
}
258265
}
@@ -582,22 +589,31 @@ final class DataCacheEntry extends CacheEntry {
582589
* </pre>
583590
*/
584591
void maybeRefresh() {
592+
logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to maybe refresh cache entry");
585593
synchronized (lock) {
594+
logger.log(ChannelLogLevel.DEBUG, "Lock to maybe refresh cache entry acquired");
586595
if (pendingCallCache.containsKey(request)) {
587596
// pending already requested
597+
logger.log(ChannelLogLevel.DEBUG,
598+
"A pending refresh request already created, no need to proceed with refresh");
588599
return;
589600
}
590601
final ListenableFuture<RouteLookupResponse> asyncCall = asyncRlsCall(request);
591602
if (!asyncCall.isDone()) {
603+
logger.log(ChannelLogLevel.DEBUG,
604+
"Async call to rls not yet complete, adding a pending cache entry");
592605
pendingCallCache.put(request, new PendingCacheEntry(request, asyncCall));
593606
} else {
594607
// async call returned finished future is most likely throttled
595608
try {
609+
logger.log(ChannelLogLevel.DEBUG, "Waiting for RLS call to return");
596610
RouteLookupResponse response = asyncCall.get();
611+
logger.log(ChannelLogLevel.DEBUG, "RLS call to returned");
597612
linkedHashLruCache.cacheAndClean(request, new DataCacheEntry(request, response));
598613
} catch (InterruptedException e) {
599614
Thread.currentThread().interrupt();
600615
} catch (Exception e) {
616+
logger.log(ChannelLogLevel.DEBUG, "RLS call failed, adding a backoff entry", e);
601617
BackoffCacheEntry backoffEntry =
602618
new BackoffCacheEntry(request, Status.fromThrowable(e), backoffProvider.get());
603619
linkedHashLruCache.cacheAndClean(request, backoffEntry);
@@ -710,33 +726,46 @@ public void run() {
710726
delayNanos,
711727
TimeUnit.NANOSECONDS,
712728
scheduledExecutorService);
729+
logger.log(ChannelLogLevel.DEBUG, "BackoffCacheEntry created with a delay of {0} nanos",
730+
delayNanos);
713731
}
714732

715733
/** Forcefully refreshes cache entry by ignoring the backoff timer. */
716734
void forceRefresh() {
735+
logger.log(ChannelLogLevel.DEBUG, "Forcefully refreshing cache entry");
717736
if (scheduledHandle.isPending()) {
718737
scheduledHandle.cancel();
719738
transitionToPending();
720739
}
721740
}
722741

723742
private void transitionToPending() {
743+
logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to transition to pending");
724744
synchronized (lock) {
745+
logger.log(ChannelLogLevel.DEBUG, "Acquired lock to transition to pending");
725746
if (shutdown) {
747+
logger.log(ChannelLogLevel.DEBUG, "Already shut down, not transitioning to pending");
726748
return;
727749
}
750+
logger.log(ChannelLogLevel.DEBUG, "Calling RLS for transition to pending");
728751
ListenableFuture<RouteLookupResponse> call = asyncRlsCall(request);
729752
if (!call.isDone()) {
753+
logger.log(ChannelLogLevel.DEBUG,
754+
"Transition to pending RLS call not done, adding a pending cache entry");
730755
PendingCacheEntry pendingEntry = new PendingCacheEntry(request, call, backoffPolicy);
731756
pendingCallCache.put(request, pendingEntry);
732757
linkedHashLruCache.invalidate(request);
733758
} else {
734759
try {
760+
logger.log(ChannelLogLevel.DEBUG,
761+
"Waiting for transition to pending RLS call response");
735762
RouteLookupResponse response = call.get();
736763
linkedHashLruCache.cacheAndClean(request, new DataCacheEntry(request, response));
737764
} catch (InterruptedException e) {
738765
Thread.currentThread().interrupt();
739766
} catch (Exception e) {
767+
logger.log(ChannelLogLevel.DEBUG,
768+
"Transition to pending RLS call failed, creating a backoff entry", e);
740769
linkedHashLruCache.cacheAndClean(
741770
request,
742771
new BackoffCacheEntry(request, Status.fromThrowable(e), backoffPolicy));
@@ -939,9 +968,13 @@ private final class BackoffRefreshListener implements ChildLbStatusListener {
939968

940969
@Override
941970
public void onStatusChanged(ConnectivityState newState) {
971+
logger.log(ChannelLogLevel.DEBUG, "LB status changed to: {0}", newState);
942972
if (prevState == ConnectivityState.TRANSIENT_FAILURE
943973
&& newState == ConnectivityState.READY) {
974+
logger.log(ChannelLogLevel.DEBUG, "Transitioning from TRANSIENT_FAILURE to READY");
975+
logger.log(ChannelLogLevel.DEBUG, "Acquiring lock force refresh backoff cache entries");
944976
synchronized (lock) {
977+
logger.log(ChannelLogLevel.DEBUG, "Lock acquired for refreshing backoff cache entries");
945978
for (CacheEntry value : linkedHashLruCache.values()) {
946979
if (value instanceof BackoffCacheEntry) {
947980
((BackoffCacheEntry) value).forceRefresh();
@@ -978,29 +1011,40 @@ public PickResult pickSubchannel(PickSubchannelArgs args) {
9781011
new Object[]{serviceName, methodName, args.getHeaders(), response});
9791012

9801013
if (response.getHeaderData() != null && !response.getHeaderData().isEmpty()) {
1014+
logger.log(ChannelLogLevel.DEBUG, "Updating LRS metadata from the LRS response headers");
9811015
Metadata headers = args.getHeaders();
9821016
headers.discardAll(RLS_DATA_KEY);
9831017
headers.put(RLS_DATA_KEY, response.getHeaderData());
9841018
}
9851019
String defaultTarget = lbPolicyConfig.getRouteLookupConfig().defaultTarget();
1020+
logger.log(ChannelLogLevel.DEBUG, "defaultTarget = {0}", defaultTarget);
9861021
boolean hasFallback = defaultTarget != null && !defaultTarget.isEmpty();
9871022
if (response.hasData()) {
1023+
logger.log(ChannelLogLevel.DEBUG, "LRS response has data, proceed with selecting a picker");
9881024
ChildPolicyWrapper childPolicyWrapper = response.getChildPolicyWrapper();
9891025
SubchannelPicker picker =
9901026
(childPolicyWrapper != null) ? childPolicyWrapper.getPicker() : null;
9911027
if (picker == null) {
1028+
logger.log(ChannelLogLevel.DEBUG,
1029+
"Child policy wrapper didn't return a picker, returning PickResult with no results");
9921030
return PickResult.withNoResult();
9931031
}
9941032
// Happy path
1033+
logger.log(ChannelLogLevel.DEBUG, "Returning PickResult");
9951034
return picker.pickSubchannel(args);
9961035
} else if (response.hasError()) {
1036+
logger.log(ChannelLogLevel.DEBUG, "RLS response has errors");
9971037
if (hasFallback) {
1038+
logger.log(ChannelLogLevel.DEBUG, "Using RLS fallback");
9981039
return useFallback(args);
9991040
}
1041+
logger.log(ChannelLogLevel.DEBUG, "No RLS fallback, returning PickResult with an error");
10001042
return PickResult.withError(
10011043
convertRlsServerStatus(response.getStatus(),
10021044
lbPolicyConfig.getRouteLookupConfig().lookupService()));
10031045
} else {
1046+
logger.log(ChannelLogLevel.DEBUG,
1047+
"RLS response had no data, return a PickResult with no data");
10041048
return PickResult.withNoResult();
10051049
}
10061050
}
@@ -1021,7 +1065,9 @@ private PickResult useFallback(PickSubchannelArgs args) {
10211065
private void startFallbackChildPolicy() {
10221066
String defaultTarget = lbPolicyConfig.getRouteLookupConfig().defaultTarget();
10231067
logger.log(ChannelLogLevel.DEBUG, "starting fallback to {0}", defaultTarget);
1068+
logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to start fallback child policy");
10241069
synchronized (lock) {
1070+
logger.log(ChannelLogLevel.DEBUG, "Acquired lock for starting fallback child policy");
10251071
if (fallbackChildPolicyWrapper != null) {
10261072
return;
10271073
}
@@ -1031,6 +1077,7 @@ private void startFallbackChildPolicy() {
10311077

10321078
// GuardedBy CachingRlsLbClient.lock
10331079
void close() {
1080+
logger.log(ChannelLogLevel.DEBUG, "Closing RLS picker");
10341081
if (fallbackChildPolicyWrapper != null) {
10351082
refCountedChildPolicyWrapperFactory.release(fallbackChildPolicyWrapper);
10361083
}

‎rls/src/main/java/io/grpc/rls/RlsLoadBalancer.java

+10-1
Original file line numberDiff line numberDiff line change
@@ -53,12 +53,14 @@ public Status acceptResolvedAddresses(ResolvedAddresses resolvedAddresses) {
5353
logger.log(ChannelLogLevel.DEBUG, "Received resolution result: {0}", resolvedAddresses);
5454
LbPolicyConfiguration lbPolicyConfiguration =
5555
(LbPolicyConfiguration) resolvedAddresses.getLoadBalancingPolicyConfig();
56-
checkNotNull(lbPolicyConfiguration, "Missing rls lb config");
56+
checkNotNull(lbPolicyConfiguration, "Missing RLS LB config");
5757
if (!lbPolicyConfiguration.equals(this.lbPolicyConfiguration)) {
58+
logger.log(ChannelLogLevel.DEBUG, "A new RLS LB config received");
5859
boolean needToConnect = this.lbPolicyConfiguration == null
5960
|| !this.lbPolicyConfiguration.getRouteLookupConfig().lookupService().equals(
6061
lbPolicyConfiguration.getRouteLookupConfig().lookupService());
6162
if (needToConnect) {
63+
logger.log(ChannelLogLevel.DEBUG, "RLS lookup service changed, need to connect");
6264
if (routeLookupClient != null) {
6365
routeLookupClient.close();
6466
}
@@ -78,12 +80,15 @@ public Status acceptResolvedAddresses(ResolvedAddresses resolvedAddresses) {
7880
// not required.
7981
this.lbPolicyConfiguration = lbPolicyConfiguration;
8082
}
83+
logger.log(ChannelLogLevel.DEBUG, "RLS LB accepted resolved addresses successfully");
8184
return Status.OK;
8285
}
8386

8487
@Override
8588
public void requestConnection() {
89+
logger.log(ChannelLogLevel.DEBUG, "connection requested from RLS LB");
8690
if (routeLookupClient != null) {
91+
logger.log(ChannelLogLevel.DEBUG, "requesting a connection from the routeLookupClient");
8792
routeLookupClient.requestConnection();
8893
}
8994
}
@@ -106,17 +111,21 @@ public String toString() {
106111
}
107112

108113
if (routeLookupClient != null) {
114+
logger.log(ChannelLogLevel.DEBUG, "closing the routeLookupClient on a name resolution error");
109115
routeLookupClient.close();
110116
routeLookupClient = null;
111117
lbPolicyConfiguration = null;
112118
}
119+
logger.log(ChannelLogLevel.DEBUG,
120+
"Updating balancing state to TRANSIENT_FAILURE with an error picker");
113121
helper.updateBalancingState(ConnectivityState.TRANSIENT_FAILURE, new ErrorPicker());
114122
}
115123

116124
@Override
117125
public void shutdown() {
118126
logger.log(ChannelLogLevel.DEBUG, "Rls lb shutdown");
119127
if (routeLookupClient != null) {
128+
logger.log(ChannelLogLevel.DEBUG, "closing the routeLookupClient because of RLS LB shutdown");
120129
routeLookupClient.close();
121130
routeLookupClient = null;
122131
}

0 commit comments

Comments
 (0)