chore: Improve and simplify logging

* Card ID: CCT-705

This patch will help us with identifying what is happening at given
times.

- Include phase, version and arguments on each phase load.
  Some of the information may not be necessary, as newer builds of
  insights-client contain logs that carry the information about phase
  and version. However, older builds do not, and these bits are valuable
  when debugging.

- Include payloads, headers and file attachments in the log message, if
  present. This should make it easier to debug PATCH calls.
  BASIC authentication credentials are not included in these headers,
  the library adds them later when constructing the request.

- Disable logging of HTTP responses for collection rules and checkin.
  They are verbose and do not need to be logged in a file every time.

Signed-off-by: mhorky <mhorky@redhat.com>

insights/client/__init__.py

@@ -50,6 +50,14 @@ def __init__(self, config=None, from_phase=True, **kwargs):
         if from_phase:
             _init_client_config_dirs()
             self.set_up_logging()
+            logger.debug(
+                "phase={phase}, version={version};{path}, arguments={arguments}".format(
+                    phase=os.getenv("INSIGHTS_PHASE", "unknown"),
+                    version=package_info.get("VERSION", "unknown"),
+                    path=client.__file__,
+                    arguments=" ".join(sys.argv[1:]),
+                )
+            )
             try_auto_configuration(self.config)
             self.initialize_tags()
         else:  # from wrapper

insights/client/collection_rules.py

@@ -183,7 +183,10 @@ def get_collection_rules(self, raw=False):
 
         try:
             req = self.conn.get(
-                self.collection_rules_url, headers=({'accept': 'text/plain'}))
+                self.collection_rules_url,
+                headers=({'accept': 'text/plain'}),
+                log_response_text=False,
+            )
 
             if req.status_code == 200:
                 logger.debug("Successfully downloaded collection rules")

insights/client/connection.py

@@ -170,13 +170,28 @@ def _http_request(self, url, method, log_response_text=True, **kwargs):
         Returns
             HTTP response object
         '''
-        logger.log(NETWORK, "%s %s", method, url)
+        log_message = "{method} {url}".format(method=method, url=url)
+        if "data" in kwargs.keys():
+            log_message += " data={data}".format(data=kwargs["data"])
+        if "json" in kwargs.keys():
+            log_message += " json={json}".format(json=json.dumps(kwargs["json"]))
+        if "headers" in kwargs.keys():
+            log_message += " headers={headers}".format(headers=kwargs["headers"])
+        if "files" in kwargs.keys():
+            attachments = []
+            for name, content in six.iteritems(kwargs["files"]):
+                if isinstance(content, tuple):
+                    attachments.append("{name}:{file}".format(name=name, file=content[0]))
+                else:
+                    attachments.append(name)
+            log_message += " attachments={files}".format(files=",".join(attachments))
+        logger.log(NETWORK, log_message)
         try:
             res = self.session.request(url=url, method=method, timeout=self.config.http_timeout, **kwargs)
         except Exception:
             raise
         logger.log(NETWORK, "HTTP Status: %d %s", res.status_code, res.reason)
-        if log_response_text or res.status_code != 200:
+        if log_response_text or res.status_code // 100 != 2:
             logger.log(NETWORK, "HTTP Response Text: %s", res.text)
         return res
 
@@ -733,7 +748,7 @@ def _fetch_system_by_machine_id(self):
                 url = self.base_url + '/platform/inventory/v1/hosts?insights_id=' + machine_id
             else:
                 url = self.inventory_url + '/hosts?insights_id=' + machine_id
-            res = self.get(url)
+            res = self.get(url, log_response_text=True)
         except REQUEST_FAILED_EXCEPTIONS as e:
             _api_request_failed(e)
             return None
@@ -1148,7 +1163,12 @@ def checkin(self):
         url = self.inventory_url + "/hosts/checkin"
         logger.debug("Sending check-in request to %s with %s" % (url, canonical_facts))
         try:
-            response = self.post(url, headers={"Content-Type": "application/json"}, data=json.dumps(canonical_facts))
+            response = self.post(
+                url,
+                headers={"Content-Type": "application/json"},
+                data=json.dumps(canonical_facts),
+                log_response_text=False,
+            )
             # Change to POST when the API is fixed.
         except REQUEST_FAILED_EXCEPTIONS as exception:
             _api_request_failed(exception)

insights/client/phase/v1.py

@@ -7,7 +7,6 @@
 import sys
 import runpy
 
-import insights
 from insights.client import InsightsClient
 from insights.client.config import InsightsConfig
 from insights.client.constants import InsightsConstants as constants
@@ -28,9 +27,6 @@ def _f():
             sys.stderr.write('ERROR: ' + str(e) + '\n')
             sys.exit(constants.sig_kill_bad)
 
-        logger.debug("Core path: %s", os.path.dirname(insights.__path__[0]))
-        logger.debug("Core version: %s", client.version())
-
         try:
             func(client, config)
         except Exception:

insights/tests/client/connection/test_checkin.py

@@ -47,7 +47,7 @@ def test_canonical_facts_request(get_proxies, post, get_canonical_facts, rm_conf
     expected_headers = {"Content-Type": "application/json"}
     expected_data = get_canonical_facts.return_value
     post.assert_called_once_with(
-        expected_url, headers=expected_headers, data=dumps(expected_data)
+        expected_url, headers=expected_headers, data=dumps(expected_data), log_response_text=False
     )
 
 
@@ -78,7 +78,7 @@ def test_canonical_facts_request_cleaned(get_proxies, post, get_canonical_facts,
     expected_data = get_canonical_facts.return_value
     expected_data = connection._clean_facts(expected_data)
     post.assert_called_once_with(
-        expected_url, headers=expected_headers, data=dumps(expected_data)
+        expected_url, headers=expected_headers, data=dumps(expected_data), log_response_text=False
     )
 
 
@@ -106,7 +106,7 @@ def test_insights_id_request(get_proxies, post, get_canonical_facts, generate_ma
     expected_headers = {"Content-Type": "application/json"}
     expected_data = {"insights_id": generate_machine_id.return_value}
     post.assert_called_once_with(
-        expected_url, headers=expected_headers, data=dumps(expected_data)
+        expected_url, headers=expected_headers, data=dumps(expected_data), log_response_text=False
     )