grpc
/
grpc-java
mirror of https://github.com/grpc/grpc-java.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

grpclb: enhance grpclb logging

This commit is contained in:
ZHANG Dapeng 2020-10-07 16:22:52 -07:00 committed by GitHub
parent cc5403c4c9
commit 6cdd537f0e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 115 additions and 58 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

55
grpclb/src/main/java/io/grpc/grpclb/GrpclbState.java
View File

@ -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<LbAddressGroup> newLbAddressGroups, List<EquivalentAddressGroup> 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<DropEntry> newDropList = new ArrayList<>();
List<BackendAddressGroup> 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<DropEntry> newDropList, List<BackendAddressGroup> 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<List<EquivalentAddressGroup>, Subchannel> newSubchannelMap =
new HashMap<>();
List<BackendEntry> 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());
}

118
grpclb/src/test/java/io/grpc/grpclb/GrpclbLoadBalancerTest.java
View File

@ -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-<api.google.com>] Got an LB response: " + buildInitialResponse(9097),
"WARNING: [grpclb-<api.google.com>] "
+ "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-<api.google.com>] Created",
"DEBUG: [grpclb-<api.google.com>] Error: " + error,
"INFO: [grpclb-<api.google.com>] 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-<api.google.com>] 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-<api.google.com>] Got an LB response: " + buildLbResponse(backends1),
"INFO: [grpclb-<api.google.com>] 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-<api.google.com>]"
+ " 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-<api.google.com>] 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-<api.google.com>] 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-<api.google.com>] 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-<api.google.com>] "
+ "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-<api.google.com>] Got an LB response: " + buildLbResponse(backends2),
"INFO: [grpclb-<api.google.com>] 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-<api.google.com>]"
+ " 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<EquivalentAddressGroup> 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-<api.google.com>] Using fallback backends",
"INFO: [grpclb-<api.google.com>]"
+ " Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], "
+ "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]",
"INFO: [grpclb-<api.google.com>] "
+ "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<EquivalentAddressGroup> backendList = createResolvedBackendAddresses(2);
deliverResolvedAddresses(backendList, Collections.<EquivalentAddressGroup>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-<api.google.com>] Using fallback backends",
"INFO: [grpclb-<api.google.com>] "
+ "Using RR list=[[[FakeSocketAddress-fake-address-0]/{}], "
+ "[[FakeSocketAddress-fake-address-1]/{}]], drop=[null, null]",
"INFO: [grpclb-<api.google.com>] "
+ "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-<api.google.com>] 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-<api.google.com>] Got an LB response: " + buildLbResponse(backends1),
"INFO: [grpclb-<api.google.com>] 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-<api.google.com>] "
+ "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-<api.google.com>] 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-<api.google.com>] 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-<api.google.com>] Got an LB response: " + buildLbResponse(backends2),
"INFO: [grpclb-<api.google.com>] 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-<api.google.com>] "
+ "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-<api.google.com>] 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-<api.google.com>] 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]");