Skip to content

Commit 5b4d796

Browse files
jochen-testingbotjochen-testingbot
committed
add more logging
1 parent 8272038 commit 5b4d796

File tree

2 files changed

+86
-25
lines changed

2 files changed

+86
-25
lines changed

‎src/main/java/ssh/CustomConnectionMonitor.java‎

Lines changed: 42 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,8 @@ public class CustomConnectionMonitor implements ConnectionMonitor {
1717
private final App app;
1818
private Timer timer;
1919
private boolean retrying = false;
20+
private long currentRetryDelay = 5000;
21+
private final int maxRetries = 3;
2022

2123
public CustomConnectionMonitor(SSHTunnel tunnel, App app) {
2224
this.tunnel = tunnel;
@@ -31,50 +33,78 @@ public void connectionLost(Throwable reason) {
3133

3234
app.getHttpProxy().stop();
3335

34-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.SEVERE, "SSH Connection lost! {0}", reason.getMessage());
36+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.SEVERE,
37+
String.format("[%s] SSH Connection lost! %s", tunnel.getConnectionId(), reason.getMessage()));
3538

3639
if (!this.retrying) {
3740
this.retrying = true;
38-
timer = new Timer();
39-
timer.schedule(new PollTask(), 5000, 5000);
41+
timer = new Timer("Reconnect-" + tunnel.getConnectionId());
42+
timer.schedule(new ReconnectTask(), currentRetryDelay);
4043
}
4144
}
4245

43-
class PollTask extends TimerTask {
46+
class ReconnectTask extends TimerTask {
4447
private int retryAttempts = 0;
48+
4549
@Override
4650
public void run() {
4751
try {
48-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO, "Trying to re-establish SSH Connection");
4952
retryAttempts += 1;
53+
54+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO,
55+
String.format("[%s] Attempting to re-establish SSH Connection (attempt %d, delay %dms)",
56+
tunnel.getConnectionId(), retryAttempts, currentRetryDelay));
57+
5058
tunnel.stop();
5159
tunnel.connect();
5260

5361
if (tunnel.isAuthenticated()) {
62+
// Successful reconnection
5463
retrying = false;
5564
retryAttempts = 0;
5665
timer.cancel();
66+
5767
app.getHttpProxy().start();
5868
tunnel.createPortForwarding();
59-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO, "Successfully re-established SSH Connection");
69+
70+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO,
71+
String.format("[%s] Successfully re-established SSH Connection after %d attempts",
72+
tunnel.getConnectionId(), retryAttempts));
6073
return;
6174
}
62-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO, "Attempts {0}", retryAttempts);
75+
6376
} catch (Exception ex) {
64-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.WARNING, ex.getMessage());
77+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.WARNING,
78+
String.format("[%s] Reconnection attempt %d failed: %s",
79+
tunnel.getConnectionId(), retryAttempts, ex.getMessage()));
6580
}
66-
if (retryAttempts >= 3) {
67-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO, "Giving up retrying this Connection. Creating a new Tunnel Connection.");
68-
// give up connecting to this tunnel VM, try another one
81+
82+
// Check if we should continue retrying
83+
if (retryAttempts >= maxRetries) {
84+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.WARNING,
85+
String.format("[%s] Giving up retrying after %d attempts. Creating a new Tunnel Connection.",
86+
tunnel.getConnectionId(), retryAttempts));
87+
88+
// Give up connecting to this tunnel VM, try another one
6989
timer.cancel();
7090
retrying = false;
7191
retryAttempts = 0;
92+
7293
app.stop();
7394
try {
7495
app.boot();
7596
} catch (Exception ex) {
76-
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.SEVERE, null, ex);
97+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.SEVERE,
98+
String.format("[%s] Failed to create new tunnel: %s", tunnel.getConnectionId(), ex.getMessage()), ex);
7799
}
100+
} else {
101+
timer.cancel();
102+
timer = new Timer("Reconnect-" + tunnel.getConnectionId());
103+
timer.schedule(new ReconnectTask(), currentRetryDelay);
104+
105+
Logger.getLogger(CustomConnectionMonitor.class.getName()).log(Level.INFO,
106+
String.format("[%s] Will retry in %dms (attempt %d)",
107+
tunnel.getConnectionId(), currentRetryDelay, retryAttempts + 1));
78108
}
79109
}
80110
}

‎src/main/java/ssh/SSHTunnel.java‎

Lines changed: 44 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
import java.io.IOException;
77
import java.util.Timer;
88
import java.util.TimerTask;
9+
import java.util.UUID;
910
import java.util.logging.Level;
1011
import java.util.logging.Logger;
1112

@@ -17,7 +18,8 @@ public class SSHTunnel {
1718
private final App app;
1819
private final Connection conn;
1920
private final String server;
20-
private Timer timer;
21+
private final String connectionId;
22+
private Timer keepAliveTimer;
2123
private boolean authenticated = false;
2224
private boolean shuttingDown = false;
2325
private LocalPortForwarder lpf1;
@@ -26,6 +28,7 @@ public SSHTunnel(App app, String server) throws Exception {
2628
/* Create a connection instance */
2729
this.app = app;
2830
this.server = server;
31+
this.connectionId = UUID.randomUUID().toString().substring(0, 8);
2932

3033
this.conn = new Connection(server, 443);
3134
this.conn.addConnectionMonitor(new CustomConnectionMonitor(this, this.app));
@@ -35,27 +38,36 @@ public SSHTunnel(App app, String server) throws Exception {
3538
public final void connect() throws Exception {
3639
try {
3740
/* Now connect */
41+
long startTime = System.currentTimeMillis();
3842
conn.connect();
43+
long connectTime = System.currentTimeMillis() - startTime;
44+
45+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.INFO,
46+
String.format("[%s] Secure connection established in %dms", connectionId, connectTime));
3947
} catch (IOException ex) {
40-
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE, ex.getMessage(), ex);
48+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE,
49+
String.format("[%s] Connection failed: %s", connectionId, ex.getMessage()), ex);
50+
throw ex;
4151
}
4252

4353
try {
4454
// authenticate
4555
this.authenticated = conn.authenticateWithPassword(app.getClientKey(), app.getClientSecret());
4656
} catch (IOException ex) {
47-
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE, "Failed authenticating to the tunnel. Please make sure you are supplying correct login credentials.");
57+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE,
58+
String.format("[%s] Failed authenticating to the tunnel. Please make sure you are supplying correct login credentials.", connectionId));
4859
throw new Exception("Authentication failed: " + ex.getMessage());
4960
}
5061

51-
5262
if (!this.authenticated) {
53-
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE, "Failed authenticating to the tunnel. Please make sure you are supplying correct login credentials.");
63+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE,
64+
String.format("[%s] Failed authenticating to the tunnel. Please make sure you are supplying correct login credentials.", connectionId));
5465
throw new Exception("Authentication failed");
5566
}
5667

57-
timer = new Timer();
58-
timer.schedule(new PollTask(), 60000, 60000);
68+
// Start keep-alive timer with configurable interval
69+
keepAliveTimer = new Timer("KeepAlive-" + connectionId);
70+
keepAliveTimer.schedule(new KeepAliveTask(), 30000, 30000);
5971
}
6072

6173
public void stop(boolean quitting) {
@@ -64,14 +76,19 @@ public void stop(boolean quitting) {
6476
}
6577

6678
public void stop() {
67-
timer.cancel();
79+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.INFO, String.format("[%s] Stopping secure tunnel",connectionId));
80+
if (keepAliveTimer != null) {
81+
keepAliveTimer.cancel();
82+
}
83+
6884
conn.close();
6985
try {
7086
if (lpf1 != null) {
7187
lpf1.close();
7288
}
7389
} catch (IOException ex) {
74-
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE, null, ex);
90+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE,
91+
String.format("[%s] Error closing port forwarder: %s", connectionId, ex.getMessage()), ex);
7592
}
7693
}
7794

@@ -81,30 +98,44 @@ public void createPortForwarding() {
8198
conn.requestRemotePortForwarding(server, 2010, "0.0.0.0", app.getJettyPort());
8299
String hubHost = "hub.testingbot.com";
83100
lpf1 = conn.createLocalPortForwarder(app.getSSHPort(), hubHost, app.getHubPort());
101+
102+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.INFO,
103+
String.format("[%s] Port forwarding established: %s:2010 -> localhost:%d, localhost:%d -> %s:%d",
104+
connectionId, server, app.getJettyPort(), app.getSSHPort(), hubHost, app.getHubPort()));
84105
} catch (IOException ex) {
85-
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE, "Could not setup port forwarding. Please make sure we can make an outbound connection to port 2010.");
106+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.SEVERE,
107+
String.format("[%s] Could not setup port forwarding. Please make sure we can make an outbound connection to port 2010.", connectionId), ex);
86108
}
87109
}
88110

89111
public boolean isShuttingDown() {
90112
return shuttingDown;
91113
}
92114

115+
public String getConnectionId() {
116+
return connectionId;
117+
}
118+
93119
/**
94120
* @return the authenticated
95121
*/
96122
public boolean isAuthenticated() {
97123
return authenticated;
98124
}
99125

100-
class PollTask extends TimerTask {
126+
class KeepAliveTask extends TimerTask {
101127
@Override
102128
public void run() {
103129
try {
104-
// keep-alive attempt
130+
long startTime = System.currentTimeMillis();
105131
conn.sendIgnorePacket();
132+
long roundTripTime = System.currentTimeMillis() - startTime;
133+
134+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.FINE,
135+
String.format("[%s] Keep-alive sent, RTT: %dms", connectionId, roundTripTime));
106136
} catch (IOException ex) {
107-
// ignore?
137+
Logger.getLogger(SSHTunnel.class.getName()).log(Level.WARNING,
138+
String.format("[%s] Keep-alive failed: %s", connectionId, ex.getMessage()));
108139
}
109140
}
110141
}

0 commit comments

Comments
 (0)