Measure http requests duration (#1379)

* Clarify log on released version

* Fixes #1374

* Update docs

* Compute URL in log only once

Author: okorach

doc/what-is-new.md

@@ -1,4 +1,6 @@
-# Next version yet unreleased
+# Version 3.5
+
+- Display HTTP request durations in DEBUG logs
 
 # Version 3.4
 

migration/README.md

@@ -111,8 +111,11 @@ When sonar-migration complete successfully they return exit code 0. En case of f
 ## Version 0.3
 
 - Robustness: Handle `connectionError` errors in project extract threads
-- Added option `--skipIssues` to skip expensive issue count extraction task from the extract which may be necessary on large platforms extracts
-- Added export of analysis history
+- Added option `--skipIssues` to skip expensive issue count extraction task from the extract (To speed up extract on very large platforms)
+- Added export of analysis history of each branch
+- Support of incremental dump of projects extracts
+- Display of HTTP requests duration in DEBUG logs
+- Fixes in documentation
 
 ## Version 0.2
 

migration/what-is-new.md

@@ -1,8 +1,11 @@
 # Version 0.3
 
 - Robustness: Handle `connectionError` errors in project extract threads
-- Added option `--skipIssues` to skip expensive issue count extraction task from the extract which may be necessary on large platforms extracts
-- Added export of analysis history
+- Added option `--skipIssues` to skip expensive issue count extraction task from the extract (To speed up extract on very large platforms)
+- Added export of analysis history of each branch
+- Support of incremental dump of projects extracts
+- Display of HTTP requests duration in DEBUG logs
+- Fixes in documentation
 
 # Version 0.2
 

sonar/platform.py

@@ -32,6 +32,7 @@
 import datetime
 import json
 import tempfile
+import logging
 import requests
 import jprops
 from requests.exceptions import HTTPError
@@ -221,12 +222,15 @@ def __run_request(
             headers["Authorization"] = f"Bearer {self.__token}"
             if kwargs.get("with_organization", True):
                 params["organization"] = self.organization
-        req_type = getattr(request, "__name__", repr(request)).upper()
-        log.debug("%s: %s", req_type, self.__urlstring(api, params))
+        if log.get_level() >= logging.DEBUG:
+            req_type = getattr(request, "__name__", repr(request)).upper()
+            url = self.__urlstring(api, params)
+            log.debug("%s: %s", req_type, url)
 
         try:
             retry = True
             while retry:
+                start = time.perf_counter_ns()
                 r = request(
                     url=self.url + api,
                     auth=self.__credentials(),
@@ -236,6 +240,7 @@ def __run_request(
                     timeout=self.http_timeout,
                 )
                 (retry, new_url) = _check_for_retry(r)
+                log.debug("%s: %s took %d ms", req_type, url, (time.perf_counter_ns() - start) // 1000000)
                 if retry:
                     self.url = new_url
             r.raise_for_status()

sonar/utilities.py

@@ -57,7 +57,7 @@ def check_last_version(package_url: str) -> None:
         return
     txt_version = json.loads(r.text)["versions"][-1]
     package_name = package_url.split("/")[-1]
-    log.info("Latest %s version is %s", package_name, txt_version)
+    log.info("Latest %s released version is %s", package_name, txt_version)
     if tuple(".".split(txt_version)) > tuple(".".split(version.PACKAGE_VERSION)):
         log.warning("A more recent version of %s (%s) is available, your are advised to upgrade", package_name, txt_version)