Improving Logging in ConnectionManipulationProxyServer to aid diagnosis of timing based issues in Java v3 test failures.

Signed-off-by: James Sutton <james.sutton@uk.ibm.com>

Author: jpwsutton

org.eclipse.paho.client.mqttv3.test/src/test/java/org/eclipse/paho/client/mqttv3/test/automaticReconnect/OfflineBufferingTest.java

@@ -178,7 +178,7 @@ public void testManyMessageBufferAndDeliver() throws Exception {
 		IMqttToken subConnectToken = subClient.connect();
 		subConnectToken.waitForCompletion(5000);
 		// Subscribe to topic
-		subClient.subscribe(topicPrefix + methodName, 0);
+		subClient.subscribe(topicPrefix + methodName, 1);
 
 		// Enable Proxy & Connect to server
 		proxy.enableProxy();
@@ -225,7 +225,7 @@ public void testManyMessageBufferAndDeliver() throws Exception {
 
 		// Check that all messages have been delivered
 		for (int x = 0; x < 100; x++) {
-			boolean recieved = mqttV3Receiver.validateReceipt(topicPrefix + methodName, 0, Integer.toString(x).getBytes());
+			boolean recieved = mqttV3Receiver.validateReceipt(topicPrefix + methodName, 1, Integer.toString(x).getBytes());
 			Assert.assertTrue(recieved);
 		}
 		log.info("All messages sent and Recieved correctly.");

org.eclipse.paho.client.mqttv3.test/src/test/java/org/eclipse/paho/client/mqttv3/test/utilities/ConnectionManipulationProxyServer.java

@@ -34,6 +34,7 @@ public ConnectionManipulationProxyServer(String host, int remotePort, int localP
 	}
 
 	public void startProxy(){
+		log.info("[CPMS Proxy] - Starting Proxy");
 		synchronized (enableLock) {
 			enableProxy = true;
 		}
@@ -42,6 +43,7 @@ public void startProxy(){
 	}
 
 	public void enableProxy(){
+		log.info("[CPMS Proxy] - Enabling Proxy");
 		synchronized (enableLock) {
 			enableProxy = true;
 		}
@@ -52,6 +54,7 @@ public void enableProxy(){
 	}
 
 	public void disableProxy(){
+		log.info("[CPMS Proxy] - Disabling Proxy");
 		synchronized (enableLock) {
 			enableProxy = false;
 		}
@@ -66,6 +69,7 @@ public void disableProxy(){
 	}
 
 	public void stopProxy(){
+		log.info("[CPMS Proxy] - Stopping Proxy");
 		synchronized (enableLock) {
 			enableProxy = false;
 		}
@@ -74,6 +78,7 @@ public void stopProxy(){
 	}
 
 	private void killOpenSockets(){
+		log.info("[CPMS Proxy] - killOpenSockets Called.");
 		try {
 			if(serverSocket != null){
 				serverSocket.close();
@@ -91,6 +96,7 @@ private void killOpenSockets(){
 
 	@Override
 	public void run() {
+		log.info("[CPMS Proxy] - Proxy Thread running.");
 		try {
 
 			final byte[] request = new byte[1024];
@@ -116,13 +122,14 @@ public void run() {
 
 
 
-					//log.fine("Proxy: Waiting for incoming connection");
+					log.info("[CPMS Proxy] - Waiting for incoming connection..");
 
 					try {
 						// Wait for a connection on the local Port
 						client = serverSocket.accept();
 
-						log.fine("Proxy: Client Opened Connection to Proxy...");
+						
+						log.info("[CPMS Proxy] - Client Opened Connection to Proxy...");
 
 						final InputStream streamFromClient = client.getInputStream();
 						final OutputStream streamToClient = client.getOutputStream();
@@ -135,7 +142,7 @@ public void run() {
 							client.close();
 							continue;
 						}
-						log.fine("Proxy: Proxy Connected to Server");
+						log.info("Proxy: Proxy Connected to Server");
 
 						// Get Server Streams
 						final InputStream streamFromServer = server.getInputStream();
@@ -150,7 +157,7 @@ public void run() {
 										streamToServer.flush();
 									}
 								} catch (IOException ex){
-									//log.warning("Proxy: 1 Connection lost: " + ex.getMessage());
+									log.warning("[CPMS Proxy] - IOException in client to server stream: " + ex.getMessage());
 									try {
 										client.close();
 										server.close();
@@ -173,7 +180,8 @@ public void run() {
 							}
 
 					 } catch (IOException ex){
-						 //log.warning("Proxy: 2 Connection lost: " + ex.getMessage());
+						 log.warning("[CPMS Proxy] - IOException in server to client stream: " + ex.getMessage());
+						 log.info("[CPMS Proxy] - ");
 						 client.close();
 						 server.close();
 					}
@@ -182,8 +190,7 @@ public void run() {
 
 
 					}  catch (IOException ex) {
-						//log.warning("Proxy: 3 Connection lost: " + ex.getMessage());
-						//ex.printStackTrace();
+						log.warning("[CPMS Proxy] - General IO Exception caught in main Thread: " + ex.getMessage());
 						break;
 					} finally {
 						try {
@@ -194,22 +201,23 @@ public void run() {
 								client.close();
 							}
 						} catch(IOException ex) {
-							//log.warning("Proxy: 4 Connection lost: " + ex.getMessage());
+							log.warning("[CPMS Proxy] - IOException caught whilst closing proxy connection.: " + ex.getMessage());
 						}
 					}
 
 
 
 				}
 			}
-			log.fine("Proxy: Proxy Thread finishing..");
+			log.info("[CPMS Proxy] - Proxy Thread finishing..");
+			
 			if(!serverSocket.isClosed()){
 				serverSocket.close();
 			}
-			log.fine("Proxy: Server Socket Closed, returning...");
+			log.info("[CPMS Proxy] - Server Socket Closed, returning...");
 
 		} catch(IOException ex) {
-			log.warning("Proxy: 5 Thread Connection lost: " + ex.getMessage());
+			log.warning("[CPMS Proxy] - Thread Connection lost: " + ex.getMessage());
 			ex.printStackTrace();
 		}