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 <hans...@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) {