SONAR-22194 Use Okhttp interceptor to log requests

build.gradle

@@ -315,7 +315,7 @@ subprojects {
         exclude 'junit:junit'
       }
       dependency 'com.squareup.okio:okio:3.9.0'
-      dependency 'io.github.hakky54:sslcontext-kickstart:8.3.4'
+      dependency 'io.github.hakky54:sslcontext-kickstart:8.3.5'
       dependency 'io.prometheus:simpleclient:0.16.0'
       dependency 'io.prometheus:simpleclient_common:0.16.0'
       dependency 'io.prometheus:simpleclient_servlet:0.16.0'
@@ -346,6 +346,7 @@ subprojects {
         entry 'okhttp'
         entry 'mockwebserver'
         entry 'okhttp-tls'
+        entry 'logging-interceptor'
       }
       dependency 'org.json:json:20240303'
       // To be removed after migration to JUnit5 is finished

server/sonar-alm-client/src/main/java/org/sonar/alm/client/azure/AzureDevOpsHttpClient.java

@@ -68,19 +68,16 @@ public class AzureDevOpsHttpClient {
 
   public void checkPAT(String serverUrl, String token) {
     String url = String.format("%s/_apis/projects?%s", getTrimmedUrl(serverUrl), API_VERSION_3);
-    LOG.debug(String.format("check pat : [%s]", url));
     doGet(token, url);
   }
 
   public GsonAzureProjectList getProjects(String serverUrl, String token) {
     String url = String.format("%s/_apis/projects?%s", getTrimmedUrl(serverUrl), API_VERSION_3);
-    LOG.debug(String.format("get projects : [%s]", url));
     return doGet(token, url, r -> buildGson().fromJson(r.body().charStream(), GsonAzureProjectList.class));
   }
 
   public GsonAzureProject getProject(String serverUrl, String token, String projectName) {
     String url = String.format("%s/_apis/projects/%s?%s", getTrimmedUrl(serverUrl), projectName, API_VERSION_3);
-    LOG.debug(String.format("get project : [%s]", url));
     return doGet(token, url, r -> buildGson().fromJson(r.body().charStream(), GsonAzureProject.class));
 
   }
@@ -89,15 +86,13 @@ public class AzureDevOpsHttpClient {
     String url = Stream.of(getTrimmedUrl(serverUrl), projectName, "_apis/git/repositories?" + API_VERSION_3)
       .filter(StringUtils::isNotBlank)
       .collect(joining("/"));
-    LOG.debug(String.format("get repos : [%s]", url));
     return doGet(token, url, r -> buildGson().fromJson(r.body().charStream(), GsonAzureRepoList.class));
   }
 
   public GsonAzureRepo getRepo(String serverUrl, String token, String projectName, String repositoryName) {
-    String url = Stream.of(getTrimmedUrl(serverUrl), projectName, "_apis/git/repositories",  repositoryName + "?" + API_VERSION_3)
+    String url = Stream.of(getTrimmedUrl(serverUrl), projectName, "_apis/git/repositories", repositoryName + "?" + API_VERSION_3)
       .filter(StringUtils::isNotBlank)
       .collect(joining("/"));
-    LOG.debug(String.format("get repo : [%s]", url));
     return doGet(token, url, r -> buildGson().fromJson(r.body().charStream(), GsonAzureRepo.class));
   }
 

server/sonar-alm-client/src/test/java/org/sonar/alm/client/azure/AzureDevOpsHttpClientTest.java

@@ -82,9 +82,8 @@ public class AzureDevOpsHttpClientTest {
     assertThat(azureDevOpsUrlCall).isEqualTo(server.url("") + "_apis/projects?api-version=3.0");
     assertThat(request.getMethod()).isEqualTo("GET");
 
-    assertThat(logTester.logs()).hasSize(1);
     assertThat(logTester.logs(Level.DEBUG))
-      .contains("check pat : [" + server.url("").toString() + "_apis/projects?api-version=3.0]");
+      .contains("--> GET " + server.url("").toString() + "_apis/projects?api-version=3.0");
   }
 
   @Test
@@ -136,9 +135,8 @@ public class AzureDevOpsHttpClientTest {
     assertThat(azureDevOpsUrlCall).isEqualTo(server.url("") + "_apis/projects?api-version=3.0");
     assertThat(request.getMethod()).isEqualTo("GET");
 
-    assertThat(logTester.logs(Level.DEBUG)).hasSize(1);
     assertThat(logTester.logs(Level.DEBUG))
-      .contains("get projects : [" + server.url("") + "_apis/projects?api-version=3.0]");
+      .contains("--> GET " + server.url("") + "_apis/projects?api-version=3.0");
     assertThat(projects.getValues()).hasSize(2);
     assertThat(projects.getValues())
       .extracting(GsonAzureProject::getName, GsonAzureProject::getDescription)
@@ -227,9 +225,8 @@ public class AzureDevOpsHttpClientTest {
     assertThat(azureDevOpsUrlCall).isEqualTo(server.url("") + "projectName/_apis/git/repositories?api-version=3.0");
     assertThat(request.getMethod()).isEqualTo("GET");
 
-    assertThat(logTester.logs(Level.DEBUG)).hasSize(1);
     assertThat(logTester.logs(Level.DEBUG))
-      .contains("get repos : [" + server.url("").toString() + "projectName/_apis/git/repositories?api-version=3.0]");
+      .contains("--> GET " + server.url("").toString() + "projectName/_apis/git/repositories?api-version=3.0");
     assertThat(repos.getValues()).hasSize(1);
     assertThat(repos.getValues())
       .extracting(GsonAzureRepo::getName, GsonAzureRepo::getUrl, r -> r.getProject().getName())
@@ -280,9 +277,8 @@ public class AzureDevOpsHttpClientTest {
     assertThat(azureDevOpsUrlCall).isEqualTo(server.url("") + "Project-Name/_apis/git/repositories/Repo-Name-1?api-version=3.0");
     assertThat(request.getMethod()).isEqualTo("GET");
 
-    assertThat(logTester.logs(Level.DEBUG)).hasSize(1);
     assertThat(logTester.logs(Level.DEBUG))
-      .contains("get repo : [" + server.url("").toString() + "Project-Name/_apis/git/repositories/Repo-Name-1?api-version=3.0]");
+      .contains("--> GET " + server.url("").toString() + "Project-Name/_apis/git/repositories/Repo-Name-1?api-version=3.0");
     assertThat(repo.getId()).isEqualTo("Repo-Id-1");
     assertThat(repo.getName()).isEqualTo("Repo-Name-1");
     assertThat(repo.getUrl()).isEqualTo("https://ado.sonarqube.com/DefaultCollection/Repo-Id-1");

sonar-scanner-engine/src/main/java/org/sonar/scanner/http/DefaultScannerWsClient.java

@@ -33,12 +33,11 @@ import java.util.Map;
 import java.util.Set;
 import javax.annotation.CheckForNull;
 import org.apache.commons.lang3.StringUtils;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.sonar.api.CoreProperties;
 import org.sonar.api.notifications.AnalysisWarnings;
 import org.sonar.api.utils.MessageException;
-import org.sonar.api.utils.log.Logger;
-import org.sonar.api.utils.log.Loggers;
-import org.sonar.api.utils.log.Profiler;
 import org.sonar.scanner.bootstrap.GlobalAnalysisMode;
 import org.sonarqube.ws.client.HttpException;
 import org.sonarqube.ws.client.WsClient;
@@ -56,9 +55,9 @@ import static org.sonar.api.utils.Preconditions.checkState;
 
 public class DefaultScannerWsClient implements ScannerWsClient {
   private static final int MAX_ERROR_MSG_LEN = 128;
-  private static final String SQ_TOKEN_EXPIRATION_HEADER = "SonarQube-Authentication-Token-Expiration";
+  static final String SQ_TOKEN_EXPIRATION_HEADER = "SonarQube-Authentication-Token-Expiration";
   private static final DateTimeFormatter USER_FRIENDLY_DATETIME_FORMAT = DateTimeFormatter.ofPattern("MMMM dd, yyyy");
-  private static final Logger LOG = Loggers.get(DefaultScannerWsClient.class);
+  private static final Logger LOG = LoggerFactory.getLogger(DefaultScannerWsClient.class);
 
   private final Set<String> warningMessages = new HashSet<>();
 
@@ -85,9 +84,7 @@ public class DefaultScannerWsClient implements ScannerWsClient {
    */
   public WsResponse call(WsRequest request) {
     checkState(!globalMode.isMediumTest(), "No WS call should be made in medium test mode");
-    Profiler profiler = Profiler.createIfDebug(LOG).start();
     WsResponse response = target.wsConnector().call(request);
-    profiler.stopDebug(format("%s %d %s", request.getMethod(), response.code(), response.requestUrl()));
     failIfUnauthorized(response);
     checkAuthenticationWarnings(response);
     return response;

sonar-scanner-engine/src/test/java/org/sonar/scanner/http/DefaultScannerWsClientTest.java

@@ -19,62 +19,73 @@
  */
 package org.sonar.scanner.http;
 
+import com.github.tomakehurst.wiremock.junit.WireMockRule;
 import java.time.LocalDateTime;
 import java.time.ZoneOffset;
 import java.time.format.DateTimeFormatter;
 import java.util.Collections;
 import java.util.List;
 import org.apache.commons.lang3.StringUtils;
+import org.junit.Before;
 import org.junit.Rule;
 import org.junit.Test;
-import org.mockito.Mockito;
 import org.slf4j.event.Level;
 import org.sonar.api.notifications.AnalysisWarnings;
 import org.sonar.api.testfixtures.log.LogTester;
 import org.sonar.api.utils.MessageException;
-import org.sonar.api.utils.log.LoggerLevel;
 import org.sonar.scanner.bootstrap.GlobalAnalysisMode;
 import org.sonar.scanner.bootstrap.ScannerProperties;
 import org.sonarqube.ws.client.GetRequest;
+import org.sonarqube.ws.client.HttpConnector;
 import org.sonarqube.ws.client.HttpException;
-import org.sonarqube.ws.client.MockWsResponse;
 import org.sonarqube.ws.client.WsClient;
+import org.sonarqube.ws.client.WsClientFactories;
 import org.sonarqube.ws.client.WsRequest;
-import org.sonarqube.ws.client.WsResponse;
 
+import static com.github.tomakehurst.wiremock.client.WireMock.aResponse;
+import static com.github.tomakehurst.wiremock.client.WireMock.get;
+import static com.github.tomakehurst.wiremock.client.WireMock.ok;
+import static com.github.tomakehurst.wiremock.client.WireMock.urlEqualTo;
+import static com.github.tomakehurst.wiremock.core.WireMockConfiguration.options;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.assertThatThrownBy;
 import static org.mockito.Mockito.mock;
-import static org.mockito.Mockito.when;
 import static org.sonar.api.utils.DateUtils.DATETIME_FORMAT;
+import static org.sonar.scanner.http.DefaultScannerWsClient.SQ_TOKEN_EXPIRATION_HEADER;
 
 public class DefaultScannerWsClientTest {
 
+  public static final String URL_ENDPOINT = "/api/issues/search";
   @Rule
   public LogTester logTester = new LogTester();
 
-  private final WsClient wsClient = mock(WsClient.class, Mockito.RETURNS_DEEP_STUBS);
+  @Rule
+  public WireMockRule server = new WireMockRule(options().dynamicPort());
+
+  private WsClient wsClient;
 
   private final AnalysisWarnings analysisWarnings = mock(AnalysisWarnings.class);
 
+  @Before
+  public void prepareWsClient() {
+    wsClient = WsClientFactories.getDefault().newClient(HttpConnector.newBuilder().url(server.baseUrl()).build());
+  }
+
   @Test
   public void call_whenDebugLevel_shouldLogAndProfileRequest() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse().setRequestUrl("https://local/api/issues/search");
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT)).willReturn(ok()));
 
-    logTester.setLevel(LoggerLevel.DEBUG);
+    logTester.setLevel(Level.DEBUG);
     DefaultScannerWsClient underTest = new DefaultScannerWsClient(wsClient, false, new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
 
-    WsResponse result = underTest.call(request);
-
-    // do not fail the execution -> interceptor returns the response
-    assertThat(result).isSameAs(response);
+    underTest.call(request);
 
     // check logs
     List<String> debugLogs = logTester.logs(Level.DEBUG);
-    assertThat(debugLogs).hasSize(1);
-    assertThat(debugLogs.get(0)).contains("GET 200 https://local/api/issues/search | time=");
+    assertThat(debugLogs).hasSize(2);
+    assertThat(debugLogs.get(0)).isEqualTo("--> GET " + server.url(URL_ENDPOINT));
+    assertThat(debugLogs.get(1)).matches("<-- 200 OK " + server.url(URL_ENDPOINT) + " \\(.*ms, unknown-length body\\)");
   }
 
   @Test
@@ -98,14 +109,13 @@ public class DefaultScannerWsClientTest {
   @Test
   public void call_whenUnauthorizedAndDebugEnabled_shouldLogResponseDetails() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse()
-      .setContent("Missing credentials")
-      .setHeader("Authorization: ", "Bearer ImNotAValidToken")
-      .setCode(403);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(aResponse()
+        .withStatus(403)
+        .withBody("Missing credentials")
+        .withHeader("Authorization", "Bearer ImNotAValidToken")));
 
-    logTester.setLevel(LoggerLevel.DEBUG);
-
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    logTester.setLevel(Level.DEBUG);
 
     DefaultScannerWsClient client = new DefaultScannerWsClient(wsClient, false,
       new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
@@ -115,21 +125,20 @@ public class DefaultScannerWsClientTest {
         "You're not authorized to analyze this project or the project doesn't exist on SonarQube and you're not authorized to create it. Please contact an administrator.");
 
     List<String> debugLogs = logTester.logs(Level.DEBUG);
-    assertThat(debugLogs).hasSize(2);
-    assertThat(debugLogs.get(1)).contains("Error response content: Missing credentials, headers: {Authorization: =[Bearer ImNotAValidToken]}");
+    assertThat(debugLogs).hasSize(3);
+    assertThat(debugLogs.get(2)).contains("Error response content: Missing credentials, headers: {authorization=[Bearer ImNotAValidToken]");
   }
 
   @Test
   public void call_whenUnauthenticatedAndDebugEnabled_shouldLogResponseDetails() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse()
-      .setContent("Missing authentication")
-      .setHeader("X-Test-Header: ", "ImATestHeader")
-      .setCode(401);
-
-    logTester.setLevel(LoggerLevel.DEBUG);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(aResponse()
+        .withStatus(401)
+        .withBody("Missing authentication")
+        .withHeader("X-Test-Header", "ImATestHeader")));
 
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    logTester.setLevel(Level.DEBUG);
 
     DefaultScannerWsClient client = new DefaultScannerWsClient(wsClient, false,
       new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
@@ -139,17 +148,17 @@ public class DefaultScannerWsClientTest {
         "or the credentials in the properties 'sonar.login' and 'sonar.password'.");
 
     List<String> debugLogs = logTester.logs(Level.DEBUG);
-    assertThat(debugLogs).hasSize(2);
-    assertThat(debugLogs.get(1)).contains("Error response content: Missing authentication, headers: {X-Test-Header: =[ImATestHeader]}");
+    assertThat(debugLogs).hasSize(3);
+    assertThat(debugLogs.get(2)).matches("Error response content: Missing authentication, headers: \\{.*x-test-header=\\[ImATestHeader\\].*");
   }
 
   @Test
   public void call_whenMissingCredentials_shouldFailWithMsg() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse()
-      .setContent("Missing authentication")
-      .setCode(401);
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(aResponse()
+        .withStatus(401)
+        .withBody("Missing authentication")));
 
     DefaultScannerWsClient client = new DefaultScannerWsClient(wsClient, false,
       new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
@@ -162,10 +171,10 @@ public class DefaultScannerWsClientTest {
   @Test
   public void call_whenInvalidCredentials_shouldFailWithMsg() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse()
-      .setContent("Invalid credentials")
-      .setCode(401);
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(aResponse()
+        .withStatus(401)
+        .withBody("Invalid credentials")));
 
     DefaultScannerWsClient client = new DefaultScannerWsClient(wsClient, /* credentials are configured */true,
       new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
@@ -177,10 +186,10 @@ public class DefaultScannerWsClientTest {
   @Test
   public void call_whenMissingPermissions_shouldFailWithMsg() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse()
-      .setContent("Unauthorized")
-      .setCode(403);
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(aResponse()
+        .withStatus(403)
+        .withBody("Unauthorized")));
 
     DefaultScannerWsClient client = new DefaultScannerWsClient(wsClient, true,
       new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
@@ -197,12 +206,11 @@ public class DefaultScannerWsClientTest {
     String expirationDate = DateTimeFormatter
       .ofPattern(DATETIME_FORMAT)
       .format(fiveDaysLatter);
-    WsResponse response = newResponse()
-      .setCode(200)
-      .setExpirationDate(expirationDate);
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(ok()
+        .withHeader(SQ_TOKEN_EXPIRATION_HEADER, expirationDate)));
 
-    logTester.setLevel(LoggerLevel.DEBUG);
+    logTester.setLevel(Level.DEBUG);
     DefaultScannerWsClient underTest = new DefaultScannerWsClient(wsClient, false, new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
     underTest.call(request);
     // the second call should not add the same warning twice
@@ -218,10 +226,10 @@ public class DefaultScannerWsClientTest {
   @Test
   public void call_whenBadRequest_shouldFailWithMessage() {
     WsRequest request = newRequest();
-    WsResponse response = newResponse()
-      .setCode(400)
-      .setContent("{\"errors\":[{\"msg\":\"Boo! bad request! bad!\"}]}");
-    when(wsClient.wsConnector().call(request)).thenReturn(response);
+    server.stubFor(get(urlEqualTo(URL_ENDPOINT))
+      .willReturn(aResponse()
+        .withStatus(400)
+        .withBody("{\"errors\":[{\"msg\":\"Boo! bad request! bad!\"}]}")));
 
     DefaultScannerWsClient client = new DefaultScannerWsClient(wsClient, true,
       new GlobalAnalysisMode(new ScannerProperties(Collections.emptyMap())), analysisWarnings);
@@ -230,10 +238,6 @@ public class DefaultScannerWsClientTest {
       .hasMessage("Boo! bad request! bad!");
   }
 
-  private MockWsResponse newResponse() {
-    return new MockWsResponse().setRequestUrl("https://local/api/issues/search");
-  }
-
   private WsRequest newRequest() {
     return new GetRequest("api/issues/search");
   }

sonar-ws/build.gradle

@@ -14,6 +14,7 @@ dependencies {
 
   api 'com.google.protobuf:protobuf-java'
   api 'com.squareup.okhttp3:okhttp'
+  api 'com.squareup.okhttp3:logging-interceptor'
   api 'com.google.code.gson:gson'
   api 'org.sonarsource.api.plugin:sonar-plugin-api'
 

sonar-ws/src/main/java/org/sonarqube/ws/client/HttpConnector.java

@@ -91,6 +91,7 @@ public class HttpConnector implements WsConnector {
     okHttpClientBuilder.setSSLSocketFactory(builder.sslSocketFactory);
     okHttpClientBuilder.setTrustManager(builder.sslTrustManager);
     okHttpClientBuilder.acceptGzip(builder.acceptGzip);
+
     this.okHttpClient = okHttpClientBuilder.build();
     this.noRedirectOkHttpClient = newClientWithoutRedirect(this.okHttpClient);
   }

sonar-ws/src/main/java/org/sonarqube/ws/client/OkHttpClientBuilder.java

@@ -46,6 +46,9 @@ import okhttp3.Interceptor;
 import okhttp3.OkHttpClient;
 import okhttp3.Request;
 import okhttp3.Response;
+import okhttp3.logging.HttpLoggingInterceptor;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import static java.nio.charset.StandardCharsets.UTF_8;
 import static java.util.Arrays.asList;
@@ -58,6 +61,8 @@ import static org.sonarqube.ws.WsUtils.nullToEmpty;
  */
 public class OkHttpClientBuilder {
 
+  private static final Logger LOG = LoggerFactory.getLogger(OkHttpClientBuilder.class);
+
   private static final String NONE = "NONE";
   private static final String P11KEYSTORE = "PKCS11";
   private static final String PROXY_AUTHORIZATION = "Proxy-Authorization";
@@ -204,7 +209,7 @@ public class OkHttpClientBuilder {
       builder.callTimeout(responseTimeoutMs, TimeUnit.MILLISECONDS);
     }
     builder.addNetworkInterceptor(this::addHeaders);
-    if(!acceptGzip) {
+    if (!acceptGzip) {
       builder.addNetworkInterceptor(new GzipRejectorInterceptor());
     }
     if (proxyLogin != null) {
@@ -236,9 +241,17 @@ public class OkHttpClientBuilder {
     SSLSocketFactory sslFactory = sslSocketFactory != null ? sslSocketFactory : systemDefaultSslSocketFactory(trustManager);
     builder.sslSocketFactory(sslFactory, trustManager);
 
+    builder.addInterceptor(buildLoggingInterceptor());
+
     return builder.build();
   }
 
+  private static HttpLoggingInterceptor buildLoggingInterceptor() {
+    var logging = new HttpLoggingInterceptor(LOG::debug);
+    logging.setLevel(HttpLoggingInterceptor.Level.BASIC);
+    return logging;
+  }
+
   private Response addHeaders(Interceptor.Chain chain) throws IOException {
     Request.Builder newRequest = chain.request().newBuilder();
     if (userAgent != null) {