You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@geode.apache.org by mh...@apache.org on 2021/10/26 16:56:42 UTC
[geode] 01/01: GEODE-9425: debug messages.
This is an automated email from the ASF dual-hosted git repository.
mhanson pushed a commit to branch bugfix/GEODE-9425
in repository https://gitbox.apache.org/repos/asf/geode.git
commit 3d49be9aa2f77439c1d4864761bdff117688b063
Author: Mark Hanson <ha...@vmware.com>
AuthorDate: Tue Oct 26 09:53:58 2021 -0700
GEODE-9425: debug messages.
---
.../internal/AutoConnectionSourceDUnitTest.java | 73 +++++++++++++++---
.../cache/client/internal/LocatorTestBase.java | 20 +++++
.../membership/gms/fd/GMSHealthMonitor.java | 88 +++++++++++-----------
.../tcpserver/AdvancedSocketCreatorImpl.java | 3 +-
4 files changed, 127 insertions(+), 57 deletions(-)
diff --git a/geode-core/src/distributedTest/java/org/apache/geode/cache/client/internal/AutoConnectionSourceDUnitTest.java b/geode-core/src/distributedTest/java/org/apache/geode/cache/client/internal/AutoConnectionSourceDUnitTest.java
index eebbde3..6bfff2b 100644
--- a/geode-core/src/distributedTest/java/org/apache/geode/cache/client/internal/AutoConnectionSourceDUnitTest.java
+++ b/geode-core/src/distributedTest/java/org/apache/geode/cache/client/internal/AutoConnectionSourceDUnitTest.java
@@ -30,6 +30,7 @@ import java.util.Comparator;
import java.util.HashSet;
import java.util.List;
+import org.apache.logging.log4j.Logger;
import org.awaitility.core.ConditionTimeoutException;
import org.junit.After;
import org.junit.Assert;
@@ -43,9 +44,11 @@ import org.apache.geode.cache.client.Pool;
import org.apache.geode.cache.client.PoolManager;
import org.apache.geode.cache.server.CacheServer;
import org.apache.geode.distributed.internal.ServerLocationAndMemberId;
+import org.apache.geode.logging.internal.log4j.api.LogService;
import org.apache.geode.management.membership.ClientMembership;
import org.apache.geode.management.membership.ClientMembershipEvent;
import org.apache.geode.management.membership.ClientMembershipListenerAdapter;
+import org.apache.geode.test.dunit.AsyncInvocation;
import org.apache.geode.test.dunit.RMIException;
import org.apache.geode.test.dunit.VM;
import org.apache.geode.test.junit.categories.ClientServerTest;
@@ -60,6 +63,7 @@ public class AutoConnectionSourceDUnitTest extends LocatorTestBase {
private static final String VALUE = "value";
private static final Object BRIDGE_LISTENER = "BRIDGE_LISTENER";
private static final long MAX_WAIT = 60000;
+ private Logger logger;
@Override
public final void postSetUp() {
@@ -189,24 +193,23 @@ public class AutoConnectionSourceDUnitTest extends LocatorTestBase {
final String hostName = getServerHostName();
VM locator0VM = VM.getVM(0);
VM locator1VM = VM.getVM(1);
- VM clientVM = VM.getVM(2);
+ VM locator2VM = VM.getVM(2);
VM serverVM = VM.getVM(3);
+ VM serverVM2 = VM.getVM(4);
+ VM clientVM2 = VM.getVM(5);
+ logger = LogService.getLogger();
final int locator0Port = locator0VM.invoke("Start Locator1 ", () -> startLocator(hostName, ""));
final int locator1Port = locator1VM.invoke("Start Locator2 ",
() -> startLocator(hostName, getLocatorString(hostName, locator0Port)));
assertThat(locator0Port).isGreaterThan(0);
assertThat(locator1Port).isGreaterThan(0);
+ logger.info("MLH starting client Locator 0 = " + locator0Port + " Locator 1 = " + locator1Port);
startBridgeClient(null, hostName, locator0Port);
InetSocketAddress locatorToWaitFor = new InetSocketAddress(hostName, locator1Port);
- MyLocatorCallback callback = (MyLocatorCallback) remoteObjects.get(CALLBACK_KEY);
- boolean discovered = callback.waitForDiscovery(locatorToWaitFor, MAX_WAIT);
- Assert.assertTrue(
- "Waited " + MAX_WAIT + " for " + locatorToWaitFor
- + " to be discovered on client. List is now: " + callback.getDiscovered(),
- discovered);
+ waitForLocatorDiscovery(VM.getVM(-1), locatorToWaitFor);
InetSocketAddress[] initialLocators =
new InetSocketAddress[] {new InetSocketAddress(hostName, locator0Port)};
@@ -221,20 +224,58 @@ public class AutoConnectionSourceDUnitTest extends LocatorTestBase {
verifyLocatorsMatched(expectedLocators, pool.getOnlineLocators());
- // stop one of the locators and ensure that the client can find and use a server
- locator0VM.invoke("Stop Locator", this::stopLocator);
+ logger.info("MLH Locators = " + pool.getLocators().size() + " online locators = "
+ + pool.getOnlineLocators().size());
- await().until(() -> pool.getOnlineLocators().size() == 1);
+ await().until(() -> pool.getOnlineLocators().size() == 2);
+ logger.info("MLH Starting the server");
int serverPort = serverVM.invoke("Start BridgeServer",
- () -> startBridgeServer(null, getLocatorString(hostName, locator1Port)));
+ () -> startPartitionedRegionServer(getLocatorString(hostName, locator0Port), REGION_NAME));
+ logger.info("MLH Server port is " + serverPort);
assertThat(serverPort).isGreaterThan(0);
+
+ int server2Port = serverVM2.invoke("Start BridgeServer 2",
+ () -> startPartitionedRegionServer(getLocatorString(hostName, locator0Port), REGION_NAME));
+ logger.info("MLH Server port is " + serverPort);
+ assertThat(server2Port).isGreaterThan(0);
+
+ logger.info("MLH Stopping locator 1 expect messages for " + locator1Port);
+ // stop one of the locators and ensure that the client can find and use a server
+ AsyncInvocation<Void> asycInvocation =
+ locator1VM.invokeAsync("Stop Locator", this::stopLocator);
+
+ doPuts(20000);
+
+ asycInvocation.get();
+
+ logger.info("MLH verifyLocatorsMatched before shutdown");
+
verifyLocatorsMatched(initialLocators, pool.getLocators());
InetSocketAddress[] postShutdownLocators =
- new InetSocketAddress[] {new InetSocketAddress(hostName, locator1Port)};
+ new InetSocketAddress[] {new InetSocketAddress(hostName, locator0Port)};
verifyLocatorsMatched(postShutdownLocators, pool.getOnlineLocators());
+ logger.info("MLH staring locator2 ");
+
+ final int locator2Port = locator2VM.invoke("Start Locator 3 ",
+ () -> startLocator(hostName, getLocatorString(hostName, locator0Port)));
+ logger.info("MLH started locator2 port = " + locator2Port);
+
+
+ await().until(() -> pool.getOnlineLocators().size() == 2);
+
+ logger
+ .info("MLH starting clientvm2 Hostname = " + hostName + " locator0Port = " + locator0Port);
+ InetSocketAddress locatorToWaitFor2 = new InetSocketAddress(hostName, locator2Port);
+ clientVM2.invoke("StartBridgeClient", () -> startBridgeClient(null, hostName, locator0Port));
+ AsyncInvocation<Void> asyncInvocation2 = clientVM2.invokeAsync("doPuts", () -> doPuts(20000));
+ logger.info("MLH 2 Online Locators = " + pool.getOnlineLocators());
+ stopBridgeMemberVM(serverVM2);
+ asyncInvocation2.get();
+ doPuts(20000);
+ waitForLocatorDiscovery(clientVM2, locatorToWaitFor2);
await().untilAsserted(
() -> assertThatCode(
@@ -244,6 +285,14 @@ public class AutoConnectionSourceDUnitTest extends LocatorTestBase {
}
+ private void doPuts(int putCount) throws InterruptedException {
+ Cache cache = (Cache) LocatorTestBase.remoteObjects.get(CACHE_KEY);
+ Region<Integer, String> region = cache.getRegion(REGION_NAME);
+ for (int i = 0; i < putCount; i++) {
+ region.put(i, "value" + i);
+ }
+ }
+
@Test
public void testClientCanUseAnEmbeddedLocator() {
VM vm0 = VM.getVM(0);
diff --git a/geode-dunit/src/main/java/org/apache/geode/cache/client/internal/LocatorTestBase.java b/geode-dunit/src/main/java/org/apache/geode/cache/client/internal/LocatorTestBase.java
index eb1111b..949ee02 100644
--- a/geode-dunit/src/main/java/org/apache/geode/cache/client/internal/LocatorTestBase.java
+++ b/geode-dunit/src/main/java/org/apache/geode/cache/client/internal/LocatorTestBase.java
@@ -215,6 +215,26 @@ public abstract class LocatorTestBase extends JUnit4DistributedTestCase {
return server.getPort();
}
+
+ protected int startPartitionedRegionServer(final String locators, final String region)
+ throws IOException {
+ CacheFactory cacheFactory = new CacheFactory().set(MCAST_PORT, "0").set(LOCATORS, locators);
+
+ Cache cache = cacheFactory.create();
+ cache.createRegionFactory(RegionShortcut.PARTITION).setEnableSubscriptionConflation(true)
+ .create(region);
+
+ CacheServer server = cache.addCacheServer();
+ server.setPort(0);
+
+ server.start();
+
+ remoteObjects.put(CACHE_KEY, cache);
+
+ return server.getPort();
+ }
+
+
protected int startBridgeServerWithEmbeddedLocator(final String[] groups, final String locators,
final String[] regions, final ServerLoadProbe probe) throws IOException {
Cache cache = new CacheFactory().set(MCAST_PORT, "0").set(LOCATORS, locators)
diff --git a/geode-membership/src/main/java/org/apache/geode/distributed/internal/membership/gms/fd/GMSHealthMonitor.java b/geode-membership/src/main/java/org/apache/geode/distributed/internal/membership/gms/fd/GMSHealthMonitor.java
index 0c1ea02..d472232 100644
--- a/geode-membership/src/main/java/org/apache/geode/distributed/internal/membership/gms/fd/GMSHealthMonitor.java
+++ b/geode-membership/src/main/java/org/apache/geode/distributed/internal/membership/gms/fd/GMSHealthMonitor.java
@@ -255,8 +255,8 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
public void run() {
ID neighbor = nextNeighbor;
- if (logger.isDebugEnabled()) {
- logger.debug("cluster health monitor invoked with {}", neighbor);
+ if (logger.isInfoEnabled()) {
+ logger.info("cluster health monitor invoked with {}", neighbor);
}
try {
if (GMSHealthMonitor.this.isStopping) {
@@ -294,7 +294,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
if (nextNeighborTS == null) {
- logger.debug("timestamp for {} was found null - setting current time as timestamp",
+ logger.info("timestamp for {} was found null - setting current time as timestamp",
neighbor);
TimeStamp customTS = new TimeStamp(currentTime);
memberTimeStamps.put(neighbor, customTS);
@@ -304,14 +304,14 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
long interval = memberTimeoutInMillis / GMSHealthMonitor.LOGICAL_INTERVAL;
long lastTS = currentTime - nextNeighborTS.getTime();
if (lastTS + interval >= memberTimeoutInMillis) {
- logger.debug("Checking member {} ", neighbor);
+ logger.info("Checking member {} ", neighbor);
// now do check request for this member;
checkMember(neighbor);
}
}
} finally {
- if (logger.isDebugEnabled()) {
- logger.debug("cluster health monitor pausing");
+ if (logger.isInfoEnabled()) {
+ logger.info("cluster health monitor pausing");
}
}
}
@@ -362,20 +362,20 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
// be an old ID in the membership view that we do not want to respond to
int myVmViewId = gmbr.getVmViewId();
if (playingDead) {
- logger.debug("HealthMonitor: simulating sick member in health check");
+ logger.info("HealthMonitor: simulating sick member in health check");
} else if (uuidLSBs == myUUID.getLeastSignificantBits()
&& uuidMSBs == myUUID.getMostSignificantBits()
&& (vmViewId == myVmViewId || myVmViewId < 0)) {
- logger.debug("HealthMonitor: sending OK reply");
+ logger.info("HealthMonitor: sending OK reply");
out.write(OK);
out.flush();
socket.shutdownOutput();
GMSHealthMonitor.this.stats.incFinalCheckResponsesSent();
GMSHealthMonitor.this.stats.incTcpFinalCheckResponsesSent();
- logger.debug("HealthMonitor: server replied OK.");
+ logger.info("HealthMonitor: server replied OK.");
} else {
- if (logger.isDebugEnabled()) {
- logger.debug(
+ if (logger.isInfoEnabled()) {
+ logger.info(
"HealthMonitor: sending ERROR reply - my UUID is {},{} received is {},{}. My viewID is {} received is {}",
Long.toHexString(myUUID.getMostSignificantBits()),
Long.toHexString(myUUID.getLeastSignificantBits()), Long.toHexString(uuidMSBs),
@@ -386,16 +386,16 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
socket.shutdownOutput();
GMSHealthMonitor.this.stats.incFinalCheckResponsesSent();
GMSHealthMonitor.this.stats.incTcpFinalCheckResponsesSent();
- logger.debug("HealthMonitor: server replied ERROR.");
+ logger.info("HealthMonitor: server replied ERROR.");
}
} catch (IOException e) {
// this is expected if it is a connection-timeout or other failure
// to connect
} catch (RuntimeException e) {
- logger.debug("Unexpected runtime exception", e);
+ logger.info("Unexpected runtime exception", e);
throw e;
} catch (Error e) {
- logger.debug("Unexpected error", e);
+ logger.info("Unexpected error", e);
throw e;
} finally {
if (socket != null) {
@@ -498,7 +498,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
return true;
}
long startTime = System.currentTimeMillis();
- logger.debug("Requesting heartbeat from {}", member);
+ logger.info("Requesting heartbeat from {}", member);
final HeartbeatRequestMessage<ID> hrm = constructHeartbeatRequestMessage(member);
Response pingResp = null;
if (waitForResponse) {
@@ -526,7 +526,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
if (isStopping) {
return true;
}
- logger.debug("no heartbeat response received from {} and no recent activity", member);
+ logger.info("no heartbeat response received from {} and no recent activity", member);
return false;
} else {
logger.trace("received heartbeat from {}", member);
@@ -539,7 +539,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
}
} catch (InterruptedException e) {
- logger.debug(
+ logger.info(
"GMSHealthMonitor checking thread interrupted, while waiting for response from member: {} .",
member);
} finally {
@@ -577,7 +577,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
}
try {
- logger.debug("Checking member {} with TCP socket connection {}:{}.", suspectMember,
+ logger.info("Checking member {} with TCP socket connection {}:{}.", suspectMember,
suspectMember.getInetAddress(), port);
clientSocket =
socketCreator.forAdvancedUse()
@@ -621,10 +621,10 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
writeMemberToStream(gmbr, out);
this.stats.incFinalCheckRequestsSent();
this.stats.incTcpFinalCheckRequestsSent();
- logger.debug("Connected to suspect member - reading response");
+ logger.info("Connected to suspect member - reading response");
int b = in.read();
- if (logger.isDebugEnabled()) {
- logger.debug("Received {}",
+ if (logger.isInfoEnabled()) {
+ logger.info("Received {}",
(b == OK ? "OK" : (b == ERROR ? "ERROR" : "unknown response: " + b)));
}
if (b >= 0) {
@@ -645,7 +645,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
return false;
}
} catch (SocketTimeoutException e) {
- logger.debug("Availability check TCP/IP connection timed out for suspect member {}",
+ logger.info("Availability check TCP/IP connection timed out for suspect member {}",
suspectMember);
return false;
} catch (IOException e) {
@@ -728,25 +728,25 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
} catch (IOException e) {
if (!isStopping) {
- logger.trace("Unexpected exception", e);
+ logger.warn("Unexpected exception", e);
}
try {
if (socket != null) {
socket.close();
}
} catch (IOException ioe) {
- logger.trace("Unexpected exception", ioe);
+ logger.warn("Unexpected exception", ioe);
}
}
}
- logger.info("GMSHealthMonitor server thread exiting");
+ logger.warn("GMSHealthMonitor server thread exiting");
} finally {
// close the server socket
if (!ssocket.isClosed()) {
try {
ssocket.close();
} catch (IOException e) {
- logger.debug("Unexpected exception", e);
+ logger.warn("Unexpected exception", e);
}
}
}
@@ -837,14 +837,14 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
ID oldNeighbor = nextNeighbor;
if (oldNeighbor != newNeighbor) {
- logger.debug("Failure detection is now watching " + newNeighbor);
+ logger.info("Failure detection is now watching " + newNeighbor);
nextNeighbor = newNeighbor;
}
}
if (nextNeighbor != null && nextNeighbor.equals(localAddress)) {
- if (logger.isDebugEnabled()) {
- logger.debug("Health monitor is unable to find a neighbor to watch. "
+ if (logger.isInfoEnabled()) {
+ logger.info("Health monitor is unable to find a neighbor to watch. "
+ "Current suspects are {}", suspectedMemberIds.keySet());
}
nextNeighbor = null;
@@ -893,7 +893,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
private void stopServices() {
- logger.debug("Stopping HealthMonitor");
+ logger.info("Stopping HealthMonitor");
isStopping = true;
if (monitorFuture != null) {
monitorFuture.cancel(true);
@@ -1026,7 +1026,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
return;
}
if (beingSick || playingDead) {
- logger.debug("sick member is ignoring check request");
+ logger.info("sick member is ignoring check request");
return;
}
@@ -1045,10 +1045,10 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
Set<ID> membersNotReceivedMsg = services.getMessenger().send(hm);
this.stats.incHeartbeatsSent();
if (membersNotReceivedMsg != null && membersNotReceivedMsg.contains(m.getSender())) {
- logger.debug("Unable to send heartbeat to member: {}", m.getSender());
+ logger.info("Unable to send heartbeat to member: {}", m.getSender());
}
} else {
- logger.debug("Ignoring heartbeat request intended for {}. My ID is {}", m.getTarget(), me);
+ logger.info("Ignoring heartbeat request intended for {}. My ID is {}", m.getTarget(), me);
}
}
@@ -1059,7 +1059,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
return;
}
if (beingSick || playingDead) {
- logger.debug("sick member is ignoring check response");
+ logger.info("sick member is ignoring check response");
return;
}
@@ -1090,7 +1090,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
return;
}
if (beingSick || playingDead) {
- logger.debug("sick member is ignoring suspect message");
+ logger.info("sick member is ignoring suspect message");
return;
}
@@ -1132,7 +1132,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
}
- logger.debug("Processing {}", incomingRequest);
+ logger.info("Processing {}", incomingRequest);
if (cv.getCoordinator().equals(localAddress)) {
// This process is the membership coordinator and should perform a final check
checkIfAvailable(sender, suspectRequests, cv);
@@ -1146,7 +1146,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
synchronized (suspectRequestsInView) {
recordSuspectRequests(suspectRequests, cv);
Set<SuspectRequest<ID>> suspectsInView = suspectRequestsInView.get(cv);
- logger.debug("Current suspects are {}", suspectsInView);
+ logger.info("Current suspects are {}", suspectsInView);
for (final SuspectRequest<ID> sr : suspectsInView) {
check.remove(sr.getSuspectMember());
membersToCheck.add(sr);
@@ -1159,10 +1159,10 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
}
if (!membersLeaving.isEmpty()) {
- logger.debug("Current leave requests are {}", membersLeaving);
+ logger.info("Current leave requests are {}", membersLeaving);
check.removeAll(membersLeaving);
}
- logger.debug(
+ logger.info(
"Proposed view with suspects & leaving members removed is {}\nwith coordinator {}\nmy address is {}",
check,
check.getCoordinator(), localAddress);
@@ -1236,7 +1236,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
final String reason = sr.getReason();
- logger.debug("Scheduling availability check for member {}; reason={}", mbr, reason);
+ logger.info("Scheduling availability check for member {}; reason={}", mbr, reason);
// its a coordinator
checkExecutor.execute(() -> {
try {
@@ -1285,8 +1285,8 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
int port = cv.getFailureDetectionPort(mbr);
if (port <= 0) {
logger.info("Unable to locate failure detection port - requesting a heartbeat");
- if (logger.isDebugEnabled()) {
- logger.debug("\ncurrent view: {}\nports: {}", cv,
+ if (logger.isInfoEnabled()) {
+ logger.info("\ncurrent view: {}\nports: {}", cv,
Arrays.toString(cv.getFailureDetectionPorts()));
}
pinged = GMSHealthMonitor.this.doCheckMember(mbr, true);
@@ -1332,7 +1332,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
Collections
.singletonList(new SuspectRequest<>(mbr, "failed availability check")));
suspectMembersMessage.setSender(localAddress);
- logger.debug("Performing local processing on suspect request");
+ logger.info("Performing local processing on suspect request");
processMessage(suspectMembersMessage);
} else {
logger.info(
@@ -1389,7 +1389,7 @@ public class GMSHealthMonitor<ID extends MemberIdentifier> implements HealthMoni
}
private void sendSuspectRequest(final List<SuspectRequest<ID>> requests) {
- logger.debug("Sending suspect request for members {}", requests);
+ logger.info("Sending suspect request for members {}", requests);
List<ID> recipients;
if (currentView.size() > MembershipConfig.SMALL_CLUSTER_SIZE) {
HashSet<ID> filter = new HashSet<>();
diff --git a/geode-tcp-server/src/main/java/org/apache/geode/distributed/internal/tcpserver/AdvancedSocketCreatorImpl.java b/geode-tcp-server/src/main/java/org/apache/geode/distributed/internal/tcpserver/AdvancedSocketCreatorImpl.java
index 4a2cbd9..679cfb1 100644
--- a/geode-tcp-server/src/main/java/org/apache/geode/distributed/internal/tcpserver/AdvancedSocketCreatorImpl.java
+++ b/geode-tcp-server/src/main/java/org/apache/geode/distributed/internal/tcpserver/AdvancedSocketCreatorImpl.java
@@ -101,7 +101,8 @@ public class AdvancedSocketCreatorImpl implements AdvancedSocketCreator {
try {
socket.connect(inetSocketAddress, Math.max(timeout, 0));
} catch (ConnectException connectException) {
- logger.info("Failed to connect to " + inetSocketAddress);
+ logger.info("Failed to connect to " + inetSocketAddress,
+ new Exception("connection failure"));
throw connectException;
} finally {
if (optionalWatcher != null) {