From 6cdd537f0e471b34cd4cca3fedcc7e0ef1c01309 Mon Sep 17 00:00:00 2001 From: ZHANG Dapeng Date: Wed, 7 Oct 2020 16:22:52 -0700 Subject: [PATCH] grpclb: enhance grpclb logging --- .../main/java/io/grpc/grpclb/GrpclbState.java | 55 ++++++-- .../grpc/grpclb/GrpclbLoadBalancerTest.java | 118 ++++++++++-------- 2 files changed, 115 insertions(+), 58 deletions(-) diff --git a/grpclb/src/main/java/io/grpc/grpclb/GrpclbState.java b/grpclb/src/main/java/io/grpc/grpclb/GrpclbState.java index 3630db63a1..2ee6befb8e 100644 --- a/grpclb/src/main/java/io/grpc/grpclb/GrpclbState.java +++ b/grpclb/src/main/java/io/grpc/grpclb/GrpclbState.java @@ -193,6 +193,7 @@ final class GrpclbState { this.serviceName = checkNotNull(helper.getAuthority(), "helper returns null authority"); } this.logger = checkNotNull(helper.getChannelLogger(), "logger"); + logger.log(ChannelLogLevel.INFO, "[grpclb-<{0}>] Created", serviceName); } void handleSubchannelState(Subchannel subchannel, ConnectivityStateInfo newState) { @@ -213,6 +214,12 @@ final class GrpclbState { */ void handleAddresses( List newLbAddressGroups, List newBackendServers) { + logger.log( + ChannelLogLevel.DEBUG, + "[grpclb-<{0}>] Resolved addresses: lb addresses {0}, backends: {1}", + serviceName, + newLbAddressGroups, + newBackendServers); if (newLbAddressGroups.isEmpty()) { // No balancer address: close existing balancer connection and enter fallback mode // immediately. @@ -273,7 +280,7 @@ final class GrpclbState { */ private void useFallbackBackends() { usingFallbackBackends = true; - logger.log(ChannelLogLevel.INFO, "Using fallback backends"); + logger.log(ChannelLogLevel.INFO, "[grpclb-<{0}>] Using fallback backends", serviceName); List newDropList = new ArrayList<>(); List newBackendAddrList = new ArrayList<>(); @@ -304,6 +311,12 @@ final class GrpclbState { if (lbCommChannel == null) { lbCommChannel = helper.createOobChannel( lbAddressGroup.getAddresses(), lbAddressGroup.getAuthority()); + logger.log( + ChannelLogLevel.DEBUG, + "[grpclb-<{0}>] Created grpclb channel: address={1}, authority={2}", + serviceName, + lbAddressGroup.getAddresses(), + lbAddressGroup.getAuthority()); } else if (lbAddressGroup.getAuthority().equals(lbCommChannel.authority())) { helper.updateOobChannelAddresses(lbCommChannel, lbAddressGroup.getAddresses()); } else { @@ -325,6 +338,9 @@ final class GrpclbState { .setInitialRequest(InitialLoadBalanceRequest.newBuilder() .setName(serviceName).build()) .build(); + logger.log( + ChannelLogLevel.DEBUG, + "[grpclb-<{0}>] Sent initial grpclb request {1}", serviceName, initRequest); try { lbStream.lbRequestWriter.onNext(initRequest); } catch (Exception e) { @@ -345,6 +361,7 @@ final class GrpclbState { } void shutdown() { + logger.log(ChannelLogLevel.INFO, "[grpclb-<{0}>] Shutdown", serviceName); shutdownLbComm(); switch (config.getMode()) { case ROUND_ROBIN: @@ -370,7 +387,7 @@ final class GrpclbState { } void propagateError(Status status) { - logger.log(ChannelLogLevel.DEBUG, "Error: {0}", status); + logger.log(ChannelLogLevel.DEBUG, "[grpclb-<{0}>] Error: {1}", serviceName, status); if (backendList.isEmpty()) { maybeUpdatePicker( TRANSIENT_FAILURE, new RoundRobinPicker(dropList, Arrays.asList(new ErrorEntry(status)))); @@ -397,7 +414,11 @@ final class GrpclbState { List newDropList, List newBackendAddrList, @Nullable GrpclbClientLoadRecorder loadRecorder) { logger.log( - ChannelLogLevel.INFO, "Using RR list={0}, drop={1}", newBackendAddrList, newDropList); + ChannelLogLevel.INFO, + "[grpclb-<{0}>] Using RR list={1}, drop={2}", + serviceName, + newBackendAddrList, + newDropList); HashMap, Subchannel> newSubchannelMap = new HashMap<>(); List newBackendList = new ArrayList<>(); @@ -605,12 +626,16 @@ final class GrpclbState { if (closed) { return; } - logger.log(ChannelLogLevel.DEBUG, "Got an LB response: {0}", response); + logger.log( + ChannelLogLevel.DEBUG, "[grpclb-<{0}>] Got an LB response: {1}", serviceName, response); LoadBalanceResponseTypeCase typeCase = response.getLoadBalanceResponseTypeCase(); if (!initialResponseReceived) { if (typeCase != LoadBalanceResponseTypeCase.INITIAL_RESPONSE) { - logger.log(ChannelLogLevel.WARNING, "Received a response without initial response"); + logger.log( + ChannelLogLevel.WARNING, + "[grpclb-<{0}>] Received a response without initial response", + serviceName); return; } initialResponseReceived = true; @@ -627,7 +652,11 @@ final class GrpclbState { maybeUpdatePicker(); return; } else if (typeCase != LoadBalanceResponseTypeCase.SERVER_LIST) { - logger.log(ChannelLogLevel.WARNING, "Ignoring unexpected response type: {0}", typeCase); + logger.log( + ChannelLogLevel.WARNING, + "[grpclb-<{0}>] Ignoring unexpected response type: {1}", + serviceName, + typeCase); return; } @@ -816,7 +845,12 @@ final class GrpclbState { } currentPicker = picker; logger.log( - ChannelLogLevel.INFO, "{0}: picks={1}, drops={2}", state, picker.pickList, picker.dropList); + ChannelLogLevel.INFO, + "[grpclb-<{0}>] Update balancing state to {1}: picks={2}, drops={3}", + serviceName, + state, + picker.pickList, + picker.dropList); helper.updateBalancingState(state, picker); } @@ -829,8 +863,11 @@ final class GrpclbState { // TODO(ejona): Allow different authorities for different addresses. Requires support from // Helper. logger.log(ChannelLogLevel.WARNING, - "Multiple authorities found for LB. " - + "Skipping addresses for {0} in preference to {1}", group.getAuthority(), authority); + "[grpclb-<{0}>] Multiple authorities found for LB. " + + "Skipping addresses for {1} in preference to {2}", + serviceName, + group.getAuthority(), + authority); } else { eags.add(group.getAddresses()); } diff --git a/grpclb/src/test/java/io/grpc/grpclb/GrpclbLoadBalancerTest.java b/grpclb/src/test/java/io/grpc/grpclb/GrpclbLoadBalancerTest.java index 7d93282757..5710981e77 100644 --- a/grpclb/src/test/java/io/grpc/grpclb/GrpclbLoadBalancerTest.java +++ b/grpclb/src/test/java/io/grpc/grpclb/GrpclbLoadBalancerTest.java @@ -652,8 +652,10 @@ public class GrpclbLoadBalancerTest { // This incident is logged assertThat(logs).containsExactly( - "DEBUG: Got an LB response: " + buildInitialResponse(9097), - "WARNING: Ignoring unexpected response type: INITIAL_RESPONSE").inOrder(); + "DEBUG: [grpclb-] Got an LB response: " + buildInitialResponse(9097), + "WARNING: [grpclb-] " + + "Ignoring unexpected response type: INITIAL_RESPONSE") + .inOrder(); // It doesn't affect load-reporting at all assertThat(fakeClock.getPendingTasks(LOAD_REPORTING_TASK_FILTER)) @@ -739,8 +741,9 @@ public class GrpclbLoadBalancerTest { deliverNameResolutionError(error); verify(helper).updateBalancingState(eq(TRANSIENT_FAILURE), pickerCaptor.capture()); assertThat(logs).containsExactly( - "DEBUG: Error: " + error, - "INFO: TRANSIENT_FAILURE: picks=" + "INFO: [grpclb-] Created", + "DEBUG: [grpclb-] Error: " + error, + "INFO: [grpclb-] Update balancing state to TRANSIENT_FAILURE: picks=" + "[Status{code=NOT_FOUND, description=www.google.com not found, cause=null}]," + " drops=[]") .inOrder(); @@ -870,7 +873,8 @@ public class GrpclbLoadBalancerTest { .updateBalancingState(any(ConnectivityState.class), any(SubchannelPicker.class)); logs.clear(); lbResponseObserver.onNext(buildInitialResponse()); - assertThat(logs).containsExactly("DEBUG: Got an LB response: " + buildInitialResponse()); + assertThat(logs).containsExactly( + "DEBUG: [grpclb-] Got an LB response: " + buildInitialResponse()); logs.clear(); lbResponseObserver.onNext(buildLbResponse(backends1)); @@ -902,19 +906,21 @@ public class GrpclbLoadBalancerTest { inOrder.verifyNoMoreInteractions(); assertThat(logs).containsExactly( - "DEBUG: Got an LB response: " + buildLbResponse(backends1), - "INFO: Using RR list=" - + "[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}](token0001)," - + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0002)]," - + " drop=[null, null]", - "INFO: CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]").inOrder(); + "DEBUG: [grpclb-] Got an LB response: " + buildLbResponse(backends1), + "INFO: [grpclb-] Using RR list=" + + "[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}](token0001)," + + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0002)]," + + " drop=[null, null]", + "INFO: [grpclb-]" + + " Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]") + .inOrder(); logs.clear(); // Let subchannels be connected deliverSubchannelState(subchannel2, ConnectivityStateInfo.forNonError(READY)); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]]," + " drops=[null, null]"); logs.clear(); @@ -928,7 +934,7 @@ public class GrpclbLoadBalancerTest { deliverSubchannelState(subchannel1, ConnectivityStateInfo.forNonError(READY)); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0001)]," + " [[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]]," + " drops=[null, null]"); @@ -947,7 +953,7 @@ public class GrpclbLoadBalancerTest { verify(subchannel1, times(2)).requestConnection(); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]]," + " drops=[null, null]"); logs.clear(); @@ -972,7 +978,8 @@ public class GrpclbLoadBalancerTest { verify(subchannel2, times(2)).requestConnection(); inOrder.verify(helper).updateBalancingState(eq(CONNECTING), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]"); + "INFO: [grpclb-] " + + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]"); logs.clear(); RoundRobinPicker picker4 = (RoundRobinPicker) pickerCaptor.getValue(); @@ -992,14 +999,15 @@ public class GrpclbLoadBalancerTest { lbResponseObserver.onNext(buildLbResponse(backends2)); assertThat(logs).containsExactly( - "DEBUG: Got an LB response: " + buildLbResponse(backends2), - "INFO: Using RR list=" - + "[[[/127.0.0.1:2030]/{io.grpc.grpclb.lbProvidedBackend=true}](token0003)," - + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0004)," - + " [[/127.0.0.1:2030]/{io.grpc.grpclb.lbProvidedBackend=true}](token0005)]," - + " drop=[null, drop(token0003), null, null, drop(token0006)]", - "INFO: CONNECTING: picks=[BUFFER_ENTRY]," - + " drops=[null, drop(token0003), null, null, drop(token0006)]") + "DEBUG: [grpclb-] Got an LB response: " + buildLbResponse(backends2), + "INFO: [grpclb-] Using RR list=" + + "[[[/127.0.0.1:2030]/{io.grpc.grpclb.lbProvidedBackend=true}](token0003)," + + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0004)," + + " [[/127.0.0.1:2030]/{io.grpc.grpclb.lbProvidedBackend=true}](token0005)]," + + " drop=[null, drop(token0003), null, null, drop(token0006)]", + "INFO: [grpclb-]" + + " Update balancing state to CONNECTING: picks=[BUFFER_ENTRY]," + + " drops=[null, drop(token0003), null, null, drop(token0006)]") .inOrder(); logs.clear(); @@ -1154,10 +1162,14 @@ public class GrpclbLoadBalancerTest { List fallbackList = Arrays.asList(backendList.get(0), backendList.get(1)); assertThat(logs).containsExactly( - "INFO: Using fallback backends", - "INFO: Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], " - + "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]", - "INFO: CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]").inOrder(); + "INFO: [grpclb-] Using fallback backends", + "INFO: [grpclb-]" + + " Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], " + + "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]", + "INFO: [grpclb-] " + + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], " + + "drops=[null, null]") + .inOrder(); // Fall back to the backends from resolver fallbackTestVerifyUseOfFallbackBackendLists(inOrder, fallbackList); @@ -1314,11 +1326,14 @@ public class GrpclbLoadBalancerTest { List backendList = createResolvedBackendAddresses(2); deliverResolvedAddresses(backendList, Collections.emptyList()); - assertThat(logs).containsExactly( - "INFO: Using fallback backends", - "INFO: Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], " - + "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]", - "INFO: CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]").inOrder(); + assertThat(logs).containsAtLeast( + "INFO: [grpclb-] Using fallback backends", + "INFO: [grpclb-] " + + "Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], " + + "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]", + "INFO: [grpclb-] " + + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]") + .inOrder(); // Fall back to the backends from resolver fallbackTestVerifyUseOfFallbackBackendLists(inOrder, backendList); @@ -2246,7 +2261,8 @@ public class GrpclbLoadBalancerTest { .updateBalancingState(any(ConnectivityState.class), any(SubchannelPicker.class)); logs.clear(); lbResponseObserver.onNext(buildInitialResponse()); - assertThat(logs).containsExactly("DEBUG: Got an LB response: " + buildInitialResponse()); + assertThat(logs).containsExactly( + "DEBUG: [grpclb-] Got an LB response: " + buildInitialResponse()); logs.clear(); lbResponseObserver.onNext(buildLbResponse(backends1)); @@ -2280,19 +2296,21 @@ public class GrpclbLoadBalancerTest { inOrder.verifyNoMoreInteractions(); assertThat(logs).containsExactly( - "DEBUG: Got an LB response: " + buildLbResponse(backends1), - "INFO: Using RR list=" - + "[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}](token0001)," - + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0002)]," - + " drop=[null, null]", - "INFO: CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]").inOrder(); + "DEBUG: [grpclb-] Got an LB response: " + buildLbResponse(backends1), + "INFO: [grpclb-] Using RR list=" + + "[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}](token0001)," + + " [[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}](token0002)]," + + " drop=[null, null]", + "INFO: [grpclb-] " + + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]") + .inOrder(); logs.clear(); // Let subchannels be connected deliverSubchannelState(subchannel2, ConnectivityStateInfo.forNonError(READY)); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]]," + " drops=[null, null]"); logs.clear(); @@ -2306,7 +2324,7 @@ public class GrpclbLoadBalancerTest { deliverSubchannelState(subchannel1, ConnectivityStateInfo.forNonError(READY)); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:2000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0001)]," + " [[[[/127.0.0.1:2010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token0002)]]," + " drops=[null, null]"); @@ -2373,19 +2391,21 @@ public class GrpclbLoadBalancerTest { inOrder.verifyNoMoreInteractions(); assertThat(logs).containsExactly( - "DEBUG: Got an LB response: " + buildLbResponse(backends2), - "INFO: Using RR list=" - + "[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}](token1001)," - + " [[/127.0.0.1:8010]/{io.grpc.grpclb.lbProvidedBackend=true}](token1002)]," - + " drop=[null, null]", - "INFO: CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]").inOrder(); + "DEBUG: [grpclb-] Got an LB response: " + buildLbResponse(backends2), + "INFO: [grpclb-] Using RR list=" + + "[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}](token1001)," + + " [[/127.0.0.1:8010]/{io.grpc.grpclb.lbProvidedBackend=true}](token1002)]," + + " drop=[null, null]", + "INFO: [grpclb-] " + + "Update balancing state to CONNECTING: picks=[BUFFER_ENTRY], drops=[null, null]") + .inOrder(); logs.clear(); // Let new subchannels be connected deliverSubchannelState(subchannel3, ConnectivityStateInfo.forNonError(READY)); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token1001)]]," + " drops=[null, null]"); logs.clear(); @@ -2398,7 +2418,7 @@ public class GrpclbLoadBalancerTest { deliverSubchannelState(subchannel4, ConnectivityStateInfo.forNonError(READY)); inOrder.verify(helper).updateBalancingState(eq(READY), pickerCaptor.capture()); assertThat(logs).containsExactly( - "INFO: READY: picks=" + "INFO: [grpclb-] Update balancing state to READY: picks=" + "[[[[[/127.0.0.1:8000]/{io.grpc.grpclb.lbProvidedBackend=true}]](token1001)]," + " [[[[/127.0.0.1:8010]/{io.grpc.grpclb.lbProvidedBackend=true}]](token1002)]]," + " drops=[null, null]");