Add extra debuging and fix controller logs (#1227)

The controller logs just use master0000 as the logId was using the port
and since we use dynamic port the value is non stable (changes during he
test) and also collides (every controller will start as master0000)

Also adds diadnostic logging to HARRecprder as I have been seeing tests
where firefox can not connect to Jenkins as the browser is not running
and test failures where the HAR can not be gathered as the proxy has
already been stopped.

```
java.lang.IllegalStateException: Proxy server is already stopped. Cannot re-stop.
	at com.browserup.bup.BrowserUpProxyServer.stop(BrowserUpProxyServer.java:514)
	at com.browserup.bup.BrowserUpProxyServer.stop(BrowserUpProxyServer.java:493)
	at org.jenkinsci.test.acceptance.recorder.HarRecorder.recordHar(HarRecorder.java:120)
	at org.jenkinsci.test.acceptance.recorder.HarRecorder.failed(HarRecorder.java:114)
	at org.junit.rules.TestWatcher.failedQuietly(TestWatcher.java:90
```

```
org.openqa.selenium.WebDriverException:
Reached error page: about:neterror?e=proxyConnectFailure&u=http%3A//mvn%3A42593/pluginManager/available&c=UTF-8&d=Firefox%20is%20configured%20to%20use%20a%20proxy%20server%20that%20is%20refusing%20connections.
Build info: version: '4.9.1', revision: 'eb2032df7f'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.15.0-1030-gcp', java.version: '11.0.18'
Driver info: org.openqa.selenium.remote.RemoteWebDriver
Command: [9241c692-6c94-4037-b34b-273cf4e18279, get {url=http://mvn:42593/pluginManager/available}]
Capabilities {acceptInsecureCerts: true, browserName: firefox, browserVersion: 106.0.4, moz:accessibilityChecks: false, moz:buildID: 20221102214123, moz:debuggerAddress: 127.0.0.1:20092, moz:firefoxOptions: {prefs: {dom.disable_beforeunload: false, dom.max_chrome_script_run_time: 600000, dom.max_script_run_time: 600000, intl.accept_languages: en}}, moz:geckodriverVersion: 0.32.0, moz:headless: false, moz:platformVersion: 5.15.0-1030-gcp, moz:processID: 1075, moz:profile: /tmp/rust_mozprofilerHfdHB, moz:shutdownTimeout: 60000, moz:useNonSpecCompliantPointerOrigin: false, moz:webdriverClick: true, moz:windowless: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(manual, http=mvn:4367..., se:bidi: ws://172.18.0.2:4444/sessio..., se:cdp: ws://172.18.0.2:4444/sessio..., se:cdpVersion: 85.0, se:noVncPort: 7900, se:vnc: ws://172.18.0.2:4444/sessio..., se:vncEnabled: true, se:vncLocalAddress: ws://172.18.0.2:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify}
Session ID: 9241c692-6c94-4037-b34b-273cf4e18279
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
	at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.createException(W3CHttpResponseCodec.java:200)
	at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:133)
	at org.openqa.selenium.remote.codec.w3c.W3CHttpResponseCodec.decode(W3CHttpResponseCodec.java:53)
	at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:193)
	at org.openqa.selenium.remote.TracedCommandExecutor.execute(TracedCommandExecutor.java:51)
	at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:543)
	at org.openqa.selenium.remote.RemoteWebDriver.get(RemoteWebDriver.java:297)
```

src/main/java/org/jenkinsci/test/acceptance/FallbackConfig.java

@@ -273,7 +273,7 @@ private Proxy createSeleniumProxy(String testName) throws UnknownHostException {
             // bind to the loopback to prevent exposing the proxy to the world.
             proxyAddr = InetAddress.getLoopbackAddress();
         }
-        BrowserUpProxy proxy = HarRecorder.getProxy(proxyAddr);
+        BrowserUpProxy proxy = HarRecorder.getProxy(proxyAddr, testName);
         proxy.newHar(testName);
         return ClientUtil.createSeleniumProxy(proxy, proxyAddr);
     }

src/main/java/org/jenkinsci/test/acceptance/controller/LocalController.java

@@ -14,6 +14,7 @@
 import java.util.Arrays;
 import java.util.HashMap;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;
 import java.util.logging.Logger;
 
 import org.apache.commons.io.FileUtils;
@@ -22,6 +23,7 @@
 import org.jenkinsci.test.acceptance.junit.FailureDiagnostics;
 import org.jenkinsci.test.acceptance.log.LogListenable;
 import org.jenkinsci.test.acceptance.log.LogListener;
+import org.jenkinsci.test.acceptance.utils.ElasticTime;
 import org.jenkinsci.utils.process.CommandBuilder;
 import org.jenkinsci.utils.process.ProcessInputStream;
 import org.junit.runners.model.MultipleFailureException;
@@ -46,6 +48,9 @@ public abstract class LocalController extends JenkinsController implements LogLi
     @Inject @Named("jenkins.war")
     protected /*final*/ File war;
 
+    @Inject
+    protected ElasticTime time;
+
     /**
      * JENKINS_HOME directory for jenkins.war to be launched.
      */
@@ -200,10 +205,9 @@ public void startNow() throws IOException {
         logWatcher = new JenkinsLogWatcher(getLogId(),process,logFile, getLogPrinter());
         logWatcher.start();
         try {
-            LOGGER.info("Waiting for Jenkins to become running in "+ this);
+            LOGGER.info("Waiting for Jenkins (" + getLogId() + ") to become running in "+ this);
             this.logWatcher.waitTillReady();
             onReady();
-            LOGGER.info("Jenkins is running in " + this);
         } catch (Exception e) {
             diagnoseFailedLoad(e);
         }
@@ -212,12 +216,22 @@ public void startNow() throws IOException {
     /**
      * Called when the Jenkins instance is ready to be used.
      */
-    protected void onReady() throws IOException {}
+    protected void onReady() throws IOException {
+        LOGGER.info("Jenkins (" + getLogId() + ") is running in " + this);
+    }
 
     @Override
-    public void stopNow() throws IOException{
+    public void stopNow() throws IOException {
+        LOGGER.info("Stopping Jenkins (" + getLogId() + ") in " + this);
         process.getProcess().destroy();
         Runtime.getRuntime().removeShutdownHook(shutdownHook);
+        try {
+            if (!process.getProcess().waitFor(time.seconds(20), TimeUnit.MILLISECONDS)) {
+                throw new IOException("Jenkins (" + getLogId() + ") failed to stop within the allowed timeout");
+            }
+        } catch (InterruptedException e) {
+            throw new IOException("Jenkins (" + getLogId() + ") failed to terminate due to interruption", e);
+        }
     }
 
     @Override

src/main/java/org/jenkinsci/test/acceptance/controller/WinstoneController.java

@@ -12,6 +12,7 @@
 import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
+import java.util.Objects;
 import java.util.logging.Logger;
 
 import org.apache.commons.io.FileUtils;
@@ -82,6 +83,7 @@ protected void onReady() throws IOException {
                 throw new IOException("Unable to parse port from " + s + ". Jenkins did not start.");
             }
         }
+        super.onReady();
     }
 
     @Override
@@ -125,6 +127,13 @@ public URL getUrl() {
         }
     }
 
+    @Override
+    public String getLogId() {
+        // as we will generally start with using a port of `0` we can not use the base classes implementation
+        // as the logging id will change through the lifecycle and not be initialized from the outset
+        return String.format("master%08d",  System.identityHashCode(this));
+    }
+
     @Override
     public String toString() {
         return getUrl().toExternalForm();

src/main/java/org/jenkinsci/test/acceptance/recorder/HarRecorder.java

@@ -14,6 +14,8 @@
 import java.io.File;
 import java.io.IOException;
 import java.net.InetAddress;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import static org.jenkinsci.test.acceptance.recorder.HarRecorder.State.*;
 
 /**
@@ -24,6 +26,9 @@
  */
 @GlobalRule
 public class HarRecorder extends TestWatcher {
+
+    private final static Logger LOGGER = Logger.getLogger(HarRecorder.class.getName());
+
     public enum State {
         OFF("off", false, false), FAILURES_ONLY("failuresOnly", true, false), ALWAYS("always", true, true);
 
@@ -72,8 +77,10 @@ public static State value(String value) {
      * Create a proxy to record the HAR listening on the specified address
      * @param networkAddress the specific address to bind to, or {@code null} to bind on all addresses
      */
-    public static BrowserUpProxy getProxy(InetAddress networkAddress) {
+    public static BrowserUpProxy getProxy(InetAddress networkAddress, String testName) {
+        LOGGER.log(Level.INFO, "Obtaining proxy for {0}...", testName);
         if (proxy == null) {
+            LOGGER.log(Level.INFO, "Creating new Proxy for {0}...", testName);
             // start the proxy
             proxy = new BrowserUpProxyServer();
             // enable more detailed HAR capture, if desired (see CaptureType for the complete list)
@@ -86,6 +93,10 @@ public static BrowserUpProxy getProxy(InetAddress networkAddress) {
             proxy.setTrustAllServers(true);
             proxy.setMitmDisabled(true);
             proxy.start(0, networkAddress);
+            LOGGER.log(Level.INFO, "Proxy Created and listening on port {0}", proxy.getPort());
+        }
+        else {
+            LOGGER.log(Level.INFO, "Existing Proxy for {0} returned using port {1}", new Object[] {testName, proxy.getPort()});
         }
         return proxy;
     }
@@ -117,6 +128,7 @@ protected void failed(Throwable e, Description description) {
 
     private void recordHar() {
         if (proxy != null) {
+            LOGGER.log(Level.INFO, "Stopping proxy running on on port {0}", proxy.getPort());
             proxy.stop();
             Har har = proxy.getHar();
             File file = diagnostics.touch("jenkins.har");

src/test/java/org/jenkinsci/test/acceptance/recorder/HarRecorderTest.java

@@ -25,7 +25,7 @@ public void shouldRecordFailingTestExecutionByDefault() {
             Description desc = description();
             HarRecorder harRecorder = rule(desc);
             HarRecorder.CAPTURE_HAR = HarRecorder.State.FAILURES_ONLY;
-            BrowserUpProxy proxy = HarRecorder.getProxy(InetAddress.getLoopbackAddress());
+            BrowserUpProxy proxy = HarRecorder.getProxy(InetAddress.getLoopbackAddress(), "anything-here");
             proxy.newHar("jenkins");
 
             System.out.println("Good Bye World");