Improve logging

CHANGELOG.md

@@ -23,6 +23,10 @@ The format is based on [Keep a Changelog].
   an exception is raised. Also, `IBMQBackend.status()` now raises a 
   `IBMQBackendApiProtocolError` exception, instead of a general `LookupError`, 
   if there was an issue with validating the status. (\#572)
+- The IBM Quantum Provider now has a logger component named `qiskit.providers.ibmq`.
+  The logger's level may be set using the `QSIKIT_IBMQ_PROVIDER_LOG_LEVEL` 
+  environment variable. Also, logged messages may be written to a file, instead of 
+  the screen, using the `QISKIT_IBMQ_PROVIDER_LOG_FILE` environment variable. (\#579)
 
 ## [0.5.0] - 2020-02-26
 

qiskit/providers/ibmq/__init__.py

@@ -21,6 +21,18 @@
 
 Modules representing the IBM Quantum Provider.
 
+Environment Variables
+=====================
+The following environment variables are used by the IBM Quantum Provider:
+
+    * ``QISKIT_IBMQ_PROVIDER_LOG_LEVEL``: Specifies the log level to use, for the
+      provider modules, when logging to the screen. If an invalid level is set, the
+      log level defaults to ``WARNING``. The valid log levels are ``DEBUG``, ``INFO``,
+      ``WARNING``, ``ERROR``, and ``CRITICAL`` (case-insensitive).
+    * ``QISKIT_IBMQ_PROVIDER_LOG_FILE``: Specifies the name of the logfile to create,
+      which will contain the logs. If it is not specified, a logfile will not be created,
+      but the message will still be logged to the screen.
+
 Functions
 =========
 .. autosummary::
@@ -58,6 +70,7 @@
     IBMQProviderError
 """
 
+import logging
 from typing import List
 
 from .ibmqfactory import IBMQFactory
@@ -68,9 +81,14 @@
 from .backendjoblimit import BackendJobLimit
 from .exceptions import *
 from .ibmqbackendservice import IBMQBackendService
+from .utils.utils import setup_logger
 
 from .version import __version__
 
+# Setup the logger for the IBM Quantum Provider package.
+logger = logging.getLogger(__name__)
+setup_logger(logger)
+
 IBMQ = IBMQFactory()
 """A global instance of an account manager that is used as the entry point for convenience."""
 

qiskit/providers/ibmq/api/clients/websocket.py

@@ -261,8 +261,7 @@ def get_job_status(
                                 timeout = original_timeout - (time.time() - start_time)
                             else:
                                 response_raw = yield from websocket.recv()
-                        logger.debug('Received message from websocket: %s',
-                                     response_raw)
+                        logger.debug('Received message from websocket: %s', response_raw)
 
                         response = WebsocketResponseMethod.from_bytes(response_raw)
                         last_status = response.data

qiskit/providers/ibmq/api/session.py

@@ -15,6 +15,7 @@
 """Session customized for IBM Quantum Experience access."""
 
 import os
+import logging
 from typing import Dict, Optional, Any, Tuple, Union
 from requests import Session, RequestException, Response
 from requests.adapters import HTTPAdapter
@@ -31,6 +32,7 @@
 )
 CLIENT_APPLICATION = 'ibmqprovider/' + ibmq_provider_version
 CUSTOM_HEADER_ENV_VAR = 'QE_CUSTOM_CLIENT_APP_HEADER'
+logger = logging.getLogger(__name__)
 
 
 class PostForcelistRetry(Retry):
@@ -218,6 +220,9 @@ def request(  # type: ignore[override]
         try:
             response = super().request(method, final_url, **kwargs)
             response.raise_for_status()
+            # Only log if the endpoint is not `/users` or `/version`
+            if not url.startswith(('/users', '/version')):
+                logger.debug('Endpoint: %s. Method: %s. Request Data: %s.', url, method, kwargs)
         except RequestException as ex:
             # Wrap the requests exceptions into a IBM Q custom one, for
             # compatibility.

qiskit/providers/ibmq/ibmqbackend.py

@@ -229,6 +229,7 @@ def _submit_job(
         })
         try:
             job = IBMQJob.from_dict(submit_info)
+            logger.debug('Job %s successfully submitted to backend %s.', job.job_id(), self.name())
         except ModelValidationError as err:
             raise IBMQBackendApiProtocolError('Unexpected return value received from the server '
                                               'when submitting job: {}'.format(str(err))) from err

qiskit/providers/ibmq/job/ibmqjob.py

@@ -270,6 +270,8 @@ def cancel(self) -> bool:
         try:
             response = self._api.job_cancel(self.job_id())
             self._cancelled = get_cancel_status(response)
+            logger.debug('Job %s cancel status is "%s". Response data: %s.',
+                         self.job_id(), self._cancelled, response)
             return self._cancelled
         except ApiError as error:
             self._cancelled = False

qiskit/providers/ibmq/utils/utils.py

@@ -14,9 +14,12 @@
 
 """General utility functions."""
 
+import os
 import re
+import logging
 import keyword
 from typing import List, Optional, Type
+from logging import Logger
 
 
 def to_python_identifier(name: str) -> str:
@@ -56,3 +59,46 @@ def validate_job_tags(job_tags: Optional[List[str]], exception: Type[Exception])
     if job_tags and (not isinstance(job_tags, list) or
                      not all(isinstance(tag, str) for tag in job_tags)):
         raise exception("job_tags needs to be a list or strings.")
+
+
+def setup_logger(logger: Logger) -> None:
+    """Setup the logger for the provider modules with the appropriate level.
+
+    It involves:
+        * Use the `QISKIT_IBMQ_PROVIDER_LOG_LEVEL` environment variable to
+            determine the log level for the provider modules. If it is set, the
+            provider uses the specified level. If it is set to an invalid level,
+            the log level defaults to `WARNING`. The valid log levels are ``DEBUG``,
+            ``INFO``, ``WARNING``, ``ERROR``, and ``CRITICAL`` (case-insensitive).
+        * Use the `QISKIT_IBMQ_PROVIDER_LOG_FILE` environment variable to
+            specify the filename to use for logging the logs to a file. If it is
+            not set, the logs will not be logged to a file, but the messages will
+            still be logged to the screen.
+    """
+    log_level = os.getenv('QISKIT_IBMQ_PROVIDER_LOG_LEVEL', '')
+    log_file = os.getenv('QISKIT_IBMQ_PROVIDER_LOG_FILE', '')
+
+    # Set the logging level, if specified.
+    if log_level:
+        # Default to `WARNING` if the specified level is not valid.
+        level = logging.getLevelName(log_level.upper())
+        if not isinstance(level, int):
+            level = logging.WARNING
+        logger.setLevel(level)
+
+    # Setup the formatter for the log messages.
+    log_fmt = ('{}.%(module)s.%(funcName)s:%(levelname)s:%(asctime)s:'
+               ' %(message)s'.format(logger.name))
+    formatter = logging.Formatter(log_fmt)
+
+    # Log messages to a file (if specified), otherwise log to the screen (default).
+    if log_file:
+        # Setup the file handler.
+        file_handler = logging.FileHandler(log_file)
+        file_handler.setFormatter(formatter)
+        logger.addHandler(file_handler)
+    else:
+        # Setup the stream handler, for logging to console, with the given format.
+        stream_handler = logging.StreamHandler()
+        stream_handler.setFormatter(formatter)
+        logger.addHandler(stream_handler)

test/ibmq/test_ibmq_logger.py

@@ -0,0 +1,177 @@
+# -*- coding: utf-8 -*-
+
+# This code is part of Qiskit.
+#
+# (C) Copyright IBM 2020.
+#
+# This code is licensed under the Apache License, Version 2.0. You may
+# obtain a copy of this license in the LICENSE.txt file in the root directory
+# of this source tree or at http://www.apache.org/licenses/LICENSE-2.0.
+#
+# Any modifications or derivative works of this code must retain this
+# copyright notice, and modified files need to carry a notice indicating
+# that they have been altered from the originals.
+
+"""Tests related to logger setup via ``setup_logger()``."""
+
+import os
+import logging
+from unittest.mock import patch
+
+from qiskit.providers.ibmq.utils.utils import setup_logger
+
+from ..ibmqtestcase import IBMQTestCase
+
+
+class TestLogger(IBMQTestCase):
+    """Tests related to logger setup via ``setup_logger()``."""
+    log_level_env = 'QISKIT_IBMQ_PROVIDER_LOG_LEVEL'
+    log_file_env = 'QISKIT_IBMQ_PROVIDER_LOG_FILE'
+
+    @classmethod
+    def setUpClass(cls):
+        """Get a logger to test. Also, cache the initial log level and a file name.
+
+        Note:
+            The initial log level is cached in order to restore the log level
+            back to the original in `tearDown`.
+        """
+        cls.logger = logging.getLogger(__name__)
+        cls.initial_logger_level = cls.logger.level
+        cls.log_file = '{}.log'.format(cls.logger.name)
+
+    def tearDown(self):
+        """Restore the original log level and remove the logger handlers.
+
+        Note:
+            This essentially "resets" the logger, so it is set back into its
+            initial state again for each test.
+        """
+        self.logger.setLevel(self.initial_logger_level)
+        for handler in self.logger.handlers:
+            handler.close()
+        self.logger.handlers.clear()
+
+    def test_no_log_level(self):
+        """Test setting up a logger without a log level.
+
+        Note:
+            The log level should default to `NOTSET` when no level is specified.
+        """
+        default_level_not_set = logging.NOTSET
+
+        with patch.dict('os.environ'):
+            if self.log_level_env in os.environ:
+                del os.environ[self.log_level_env]
+            setup_logger(self.logger)
+            self.assertEqual(self.logger.level, default_level_not_set,
+                             'The logger level was set to {}, but it should '
+                             'be {}'.format(self.logger.level, logging.NOTSET))
+
+    def test_empty_log_level(self):
+        """Test setting up a logger with an empty string log level.
+
+        Note:
+            The log level should default to `NOTSET` when an empty string is specified.
+        """
+        default_level_not_set = logging.NOTSET
+
+        with patch.dict('os.environ', {self.log_level_env: ''}):
+            setup_logger(self.logger)
+            self.assertEqual(self.logger.level, default_level_not_set,
+                             'The logger level was set to {}, but it should '
+                             'be {}.'.format(self.logger.level, logging.NOTSET))
+
+    def test_invalid_log_level(self):
+        """Test setting up a logger with invalid log levels, should default to `WARNING`.
+
+        Note:
+              The log level should default to `WARNING` when an invalid level is specified.
+        """
+        default_level_invalid = logging.WARNING
+
+        invalid_log_levels = ['invalid', 'debugs', 'WarNinGs']
+        for invalid_log_level in invalid_log_levels:
+            with patch.dict('os.environ', {self.log_level_env: invalid_log_level}):
+                setup_logger(self.logger)
+                self.assertEqual(self.logger.level, default_level_invalid,
+                                 'The logger level was set to {}, but it should '
+                                 'be {}.'.format(self.logger.level, logging.WARNING))
+
+    def test_mixed_casing_log_level(self):
+        """Test setting up a logger with valid log levels, case insensitive."""
+        level_to_set = logging.INFO
+        valid_log_levels = ['INFO', 'info', 'InFo']
+
+        for valid_log_level in valid_log_levels:
+            with patch.dict('os.environ', {self.log_level_env: valid_log_level}):
+                setup_logger(self.logger)
+                self.assertEqual(self.logger.level, level_to_set,
+                                 'The logger level was set to {}, but it should '
+                                 'be {}.'.format(self.logger.level, logging.INFO))
+
+    def test_valid_log_levels(self):
+        """Test setting up a logger with all valid levels, case insensitive."""
+        all_valid_log_levels = {
+            'debug': logging.DEBUG, 'iNFo': logging.INFO,
+            'WARNING': logging.WARNING, 'error': logging.ERROR,
+            'CRITICAL': logging.CRITICAL}
+
+        for level_name, level_value in all_valid_log_levels.items():
+            with patch.dict('os.environ', {self.log_level_env: level_name}):
+                setup_logger(self.logger)
+                self.assertEqual(self.logger.level, level_value,
+                                 'The logger level was set to {}, but it should '
+                                 'be {}.'.format(self.logger.level, level_value))
+
+    def test_log_file(self):
+        """Test setting up a logger by specifying a file and log level."""
+        log_level_warning = ('WARNING', logging.WARNING)
+        env_vars_to_patch = {self.log_level_env: log_level_warning[0],
+                             self.log_file_env: self.log_file}
+
+        with patch.dict('os.environ', env_vars_to_patch):
+            setup_logger(self.logger)
+            self.assertEqual(self.logger.level, log_level_warning[1],
+                             'The logger level was set to {}, but it should '
+                             'be {}.'.format(self.logger.level, log_level_warning[1]))
+
+            # Assert the file handler was created.
+            self.assertTrue(self.logger.handlers,
+                            'A file handler should have been setup, but it was not.')
+            self.assertEqual(len(self.logger.handlers), 1,
+                             'Many handlers were setup {}, but it should have only '
+                             'been one.'.format(self.logger.handlers))
+
+            # Note that only messages >= `WARNING` will be logged.
+            self.logger.debug('This is a debug message that should not be logged in the file.')
+            self.logger.warning('This is a warning message that should be logged in the file.')
+            self.logger.error('This is a error message that should be logged in the file.')
+
+            # Retrieve the file handler.
+            file_handler = self.logger.handlers[0]
+            file_path = file_handler.baseFilename
+
+            # Assert the file exists.
+            self.assertTrue(os.path.exists(file_path),
+                            'The file {} does not exist.'.format(file_path))
+
+            # Assert the messages were logged.
+            with open(file_path) as file_:
+                content_as_str = file_.read()
+                substrings_to_check = {'debug message': False, 'warning message': True,
+                                       'error message': True}
+
+                # Check whether the appropriate substrings are in the file.
+                for substring, in_file in substrings_to_check.items():
+                    if in_file:
+                        self.assertIn(substring, content_as_str,
+                                      'The substring "{}" was not found in the file {}({}).'
+                                      .format(substring, self.log_file, file_path))
+                    else:
+                        self.assertNotIn(substring, content_as_str,
+                                         'The substring "{}" was found in the file {}({}).'
+                                         .format('debug message', self.log_file, file_path))
+
+            # Delete the file.
+            os.remove(file_path)