rls: Adding extra debug logs (#10902) · grpc/grpc-java@eba699a
@@ -196,6 +196,7 @@ static Status convertRlsServerStatus(Status status, String serverName) {
196196197197@CheckReturnValue
198198private ListenableFuture<RouteLookupResponse> asyncRlsCall(RouteLookupRequest request) {
199+logger.log(ChannelLogLevel.DEBUG, "Making an async call to RLS");
199200final SettableFuture<RouteLookupResponse> response = SettableFuture.create();
200201if (throttler.shouldThrottle()) {
201202logger.log(ChannelLogLevel.DEBUG, "Request is throttled");
@@ -224,6 +225,7 @@ public void onError(Throwable t) {
224225225226@Override
226227public void onCompleted() {
228+logger.log(ChannelLogLevel.DEBUG, "routeLookup call completed");
227229throttler.registerBackendResponse(false);
228230 }
229231 });
@@ -237,10 +239,13 @@ public void onCompleted() {
237239 */
238240@CheckReturnValue
239241final CachedRouteLookupResponse get(final RouteLookupRequest request) {
242+logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to get cached entry");
240243synchronized (lock) {
244+logger.log(ChannelLogLevel.DEBUG, "Acquired lock to get cached entry");
241245final CacheEntry cacheEntry;
242246cacheEntry = linkedHashLruCache.read(request);
243247if (cacheEntry == null) {
248+logger.log(ChannelLogLevel.DEBUG, "No cache entry found, making a new lrs request");
244249return handleNewRequest(request);
245250 }
246251@@ -249,10 +254,12 @@ final CachedRouteLookupResponse get(final RouteLookupRequest request) {
249254logger.log(ChannelLogLevel.DEBUG, "Cache hit for the request");
250255DataCacheEntry dataEntry = ((DataCacheEntry) cacheEntry);
251256if (dataEntry.isStaled(ticker.read())) {
257+logger.log(ChannelLogLevel.DEBUG, "Cache entry is stale");
252258dataEntry.maybeRefresh();
253259 }
254260return CachedRouteLookupResponse.dataEntry((DataCacheEntry) cacheEntry);
255261 }
262+logger.log(ChannelLogLevel.DEBUG, "Cache hit for a backup entry");
256263return CachedRouteLookupResponse.backoffEntry((BackoffCacheEntry) cacheEntry);
257264 }
258265 }
@@ -582,22 +589,31 @@ final class DataCacheEntry extends CacheEntry {
582589 * </pre>
583590 */
584591void maybeRefresh() {
592+logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to maybe refresh cache entry");
585593synchronized (lock) {
594+logger.log(ChannelLogLevel.DEBUG, "Lock to maybe refresh cache entry acquired");
586595if (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");
588599return;
589600 }
590601final ListenableFuture<RouteLookupResponse> asyncCall = asyncRlsCall(request);
591602if (!asyncCall.isDone()) {
603+logger.log(ChannelLogLevel.DEBUG,
604+"Async call to rls not yet complete, adding a pending cache entry");
592605pendingCallCache.put(request, new PendingCacheEntry(request, asyncCall));
593606 } else {
594607// async call returned finished future is most likely throttled
595608try {
609+logger.log(ChannelLogLevel.DEBUG, "Waiting for RLS call to return");
596610RouteLookupResponse response = asyncCall.get();
611+logger.log(ChannelLogLevel.DEBUG, "RLS call to returned");
597612linkedHashLruCache.cacheAndClean(request, new DataCacheEntry(request, response));
598613 } catch (InterruptedException e) {
599614Thread.currentThread().interrupt();
600615 } catch (Exception e) {
616+logger.log(ChannelLogLevel.DEBUG, "RLS call failed, adding a backoff entry", e);
601617BackoffCacheEntry backoffEntry =
602618new BackoffCacheEntry(request, Status.fromThrowable(e), backoffProvider.get());
603619linkedHashLruCache.cacheAndClean(request, backoffEntry);
@@ -710,33 +726,46 @@ public void run() {
710726delayNanos,
711727TimeUnit.NANOSECONDS,
712728scheduledExecutorService);
729+logger.log(ChannelLogLevel.DEBUG, "BackoffCacheEntry created with a delay of {0} nanos",
730+delayNanos);
713731 }
714732715733/** Forcefully refreshes cache entry by ignoring the backoff timer. */
716734void forceRefresh() {
735+logger.log(ChannelLogLevel.DEBUG, "Forcefully refreshing cache entry");
717736if (scheduledHandle.isPending()) {
718737scheduledHandle.cancel();
719738transitionToPending();
720739 }
721740 }
722741723742private void transitionToPending() {
743+logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to transition to pending");
724744synchronized (lock) {
745+logger.log(ChannelLogLevel.DEBUG, "Acquired lock to transition to pending");
725746if (shutdown) {
747+logger.log(ChannelLogLevel.DEBUG, "Already shut down, not transitioning to pending");
726748return;
727749 }
750+logger.log(ChannelLogLevel.DEBUG, "Calling RLS for transition to pending");
728751ListenableFuture<RouteLookupResponse> call = asyncRlsCall(request);
729752if (!call.isDone()) {
753+logger.log(ChannelLogLevel.DEBUG,
754+"Transition to pending RLS call not done, adding a pending cache entry");
730755PendingCacheEntry pendingEntry = new PendingCacheEntry(request, call, backoffPolicy);
731756pendingCallCache.put(request, pendingEntry);
732757linkedHashLruCache.invalidate(request);
733758 } else {
734759try {
760+logger.log(ChannelLogLevel.DEBUG,
761+"Waiting for transition to pending RLS call response");
735762RouteLookupResponse response = call.get();
736763linkedHashLruCache.cacheAndClean(request, new DataCacheEntry(request, response));
737764 } catch (InterruptedException e) {
738765Thread.currentThread().interrupt();
739766 } catch (Exception e) {
767+logger.log(ChannelLogLevel.DEBUG,
768+"Transition to pending RLS call failed, creating a backoff entry", e);
740769linkedHashLruCache.cacheAndClean(
741770request,
742771new BackoffCacheEntry(request, Status.fromThrowable(e), backoffPolicy));
@@ -939,9 +968,13 @@ private final class BackoffRefreshListener implements ChildLbStatusListener {
939968940969@Override
941970public void onStatusChanged(ConnectivityState newState) {
971+logger.log(ChannelLogLevel.DEBUG, "LB status changed to: {0}", newState);
942972if (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");
944976synchronized (lock) {
977+logger.log(ChannelLogLevel.DEBUG, "Lock acquired for refreshing backoff cache entries");
945978for (CacheEntry value : linkedHashLruCache.values()) {
946979if (value instanceof BackoffCacheEntry) {
947980 ((BackoffCacheEntry) value).forceRefresh();
@@ -978,29 +1011,40 @@ public PickResult pickSubchannel(PickSubchannelArgs args) {
9781011new Object[]{serviceName, methodName, args.getHeaders(), response});
97910129801013if (response.getHeaderData() != null && !response.getHeaderData().isEmpty()) {
1014+logger.log(ChannelLogLevel.DEBUG, "Updating LRS metadata from the LRS response headers");
9811015Metadata headers = args.getHeaders();
9821016headers.discardAll(RLS_DATA_KEY);
9831017headers.put(RLS_DATA_KEY, response.getHeaderData());
9841018 }
9851019String defaultTarget = lbPolicyConfig.getRouteLookupConfig().defaultTarget();
1020+logger.log(ChannelLogLevel.DEBUG, "defaultTarget = {0}", defaultTarget);
9861021boolean hasFallback = defaultTarget != null && !defaultTarget.isEmpty();
9871022if (response.hasData()) {
1023+logger.log(ChannelLogLevel.DEBUG, "LRS response has data, proceed with selecting a picker");
9881024ChildPolicyWrapper childPolicyWrapper = response.getChildPolicyWrapper();
9891025SubchannelPicker picker =
9901026 (childPolicyWrapper != null) ? childPolicyWrapper.getPicker() : null;
9911027if (picker == null) {
1028+logger.log(ChannelLogLevel.DEBUG,
1029+"Child policy wrapper didn't return a picker, returning PickResult with no results");
9921030return PickResult.withNoResult();
9931031 }
9941032// Happy path
1033+logger.log(ChannelLogLevel.DEBUG, "Returning PickResult");
9951034return picker.pickSubchannel(args);
9961035 } else if (response.hasError()) {
1036+logger.log(ChannelLogLevel.DEBUG, "RLS response has errors");
9971037if (hasFallback) {
1038+logger.log(ChannelLogLevel.DEBUG, "Using RLS fallback");
9981039return useFallback(args);
9991040 }
1041+logger.log(ChannelLogLevel.DEBUG, "No RLS fallback, returning PickResult with an error");
10001042return PickResult.withError(
10011043convertRlsServerStatus(response.getStatus(),
10021044lbPolicyConfig.getRouteLookupConfig().lookupService()));
10031045 } else {
1046+logger.log(ChannelLogLevel.DEBUG,
1047+"RLS response had no data, return a PickResult with no data");
10041048return PickResult.withNoResult();
10051049 }
10061050 }
@@ -1021,7 +1065,9 @@ private PickResult useFallback(PickSubchannelArgs args) {
10211065private void startFallbackChildPolicy() {
10221066String defaultTarget = lbPolicyConfig.getRouteLookupConfig().defaultTarget();
10231067logger.log(ChannelLogLevel.DEBUG, "starting fallback to {0}", defaultTarget);
1068+logger.log(ChannelLogLevel.DEBUG, "Acquiring lock to start fallback child policy");
10241069synchronized (lock) {
1070+logger.log(ChannelLogLevel.DEBUG, "Acquired lock for starting fallback child policy");
10251071if (fallbackChildPolicyWrapper != null) {
10261072return;
10271073 }
@@ -1031,6 +1077,7 @@ private void startFallbackChildPolicy() {
1031107710321078// GuardedBy CachingRlsLbClient.lock
10331079void close() {
1080+logger.log(ChannelLogLevel.DEBUG, "Closing RLS picker");
10341081if (fallbackChildPolicyWrapper != null) {
10351082refCountedChildPolicyWrapperFactory.release(fallbackChildPolicyWrapper);
10361083 }