Implemented various fixes to logging (fixes #207) (#208)

* replaced logging.basicConfig with appropriate handler

* fixed logger in client.file

* fixed logging in client.api

* fixed logging in client.container

* fixed logging in client.dockerm

* fixed logging in client.bug

* fixed logging in mgr.container

* fixed logging in mgr.coverage

* fixed logging in mgr.source

* added null handler to __init__.py

* added missing import

* tidied up compiler module and fixed a latent bug

* fixed bugs found by mypy

bugzoo/__init__.py

@@ -4,3 +4,6 @@
 from bugzoo.core import Language, Patch
 from bugzoo.core.container import Container
 from bugzoo.core.bug import Bug
+
+import logging
+logging.getLogger(__name__).addHandler(logging.NullHandler())

bugzoo/client/__init__.py

@@ -1,10 +1,14 @@
+import logging
+
 from .api import APIClient
 from .bug import BugManager
 from .container import ContainerManager
 from .file import FileManager
 from .dockerm import DockerManager
 from ..exceptions import ConnectionFailure
 
+logger = logging.getLogger(__name__)  # type: logging.Logger
+
 __all__ = ['Client']
 
 

bugzoo/client/api.py

@@ -9,6 +9,10 @@
 
 from ..exceptions import ConnectionFailure, UnexpectedResponse, BugZooException
 
+logger = logging.getLogger(__name__)  # type: logging.Logger
+
+__all__ = ['APIClient']
+
 
 class APIClient(object):
     def __init__(self,
@@ -32,27 +36,33 @@ def __init__(self,
         """
         assert timeout_connection > 0
 
-        logging.basicConfig(level=logging.DEBUG)
-        self.__logger = logging.getLogger('api')
         self.__base_url = base_url
 
         # attempt to establish a connection
+        logging.info("Attempting to establish connection to %s within %d seconds",  # noqa: pycodestyle
+                     base_url,
+                     timeout_connection)
         url = self._url("status")
         time_started = timer()
         connected = False
         while not connected:
             time_running = timer() - time_started
             time_left = timeout_connection - time_running
             if time_left <= 0.0:
+                logger.error("Failed to establish connection to server: %s",
+                             base_url)
                 raise ConnectionFailure
             try:
                 r = requests.get(url, timeout=time_left)
                 connected = r.status_code == 204
             except requests.exceptions.ConnectionError:
                 time.sleep(1.0)
             except requests.exceptions.Timeout:
+                logger.error("Failed to establish connection to server: %s",
+                             base_url)
                 raise ConnectionFailure
             time.sleep(0.05)
+        logging.info("Established connection to server: %s", base_url)
 
     def _url(self, path: str) -> str:
         """
@@ -84,7 +94,7 @@ def get(self,
             json: Optional[Any] = None
             ) -> requests.Response:
         url = self._url(path)
-        self.__logger.info('GET: %s', url)
+        logger.info('GET: %s', url)
         return requests.get(url, json=json)
 
     def post(self,
@@ -93,12 +103,12 @@ def post(self,
              json: Optional[Any] = None
              ) -> requests.Response:
         url = self._url(path)
-        self.__logger.info('POST: %s', url)
+        logger.info('POST: %s', url)
         return requests.post(url, json=json)
 
     def put(self, path: str, **kwargs) -> requests.Response:
         url = self._url(path)
-        self.__logger.info('PUT: %s', url)
+        logger.info('PUT: %s', url)
         return requests.put(url, **kwargs)
 
     def patch(self,
@@ -107,7 +117,7 @@ def patch(self,
               **kwargs
               ) -> requests.Response:
         url = self._url(path)
-        self.__logger.info('PATCH: %s', url)
+        logger.info('PATCH: %s', url)
         return requests.patch(url, data=data, **kwargs)
 
     def delete(self,
@@ -116,5 +126,5 @@ def delete(self,
                json: Optional[Any] = None
                ) -> requests.Response:
         url = self._url(path)
-        self.__logger.info('DELETE: %s', url)
+        logger.info('DELETE: %s', url)
         return requests.delete(url, json=json)

bugzoo/client/bug.py

@@ -5,24 +5,26 @@
 from ..core.bug import Bug
 from ..core.coverage import TestSuiteCoverage
 
+logger = logging.getLogger(__name__)  # type: logging.Logger
+
+__all__ = ['BugManager']
+
 
 class BugManager(object):
     def __init__(self, api: APIClient) -> None:
-        logging.basicConfig(level=logging.DEBUG)
-        self.__logger = logging.getLogger('bug')
         self.__api = api
 
     def __getitem__(self, name: str) -> Bug:
-        self.__logger.info("Fetching information for bug: %s", name)
+        logger.info("Fetching information for bug: %s", name)
         r = self.__api.get('bugs/{}'.format(name))
 
         if r.status_code == 200:
             return Bug.from_dict(r.json())
         if r.status_code == 404:
-            self.__logger.info("Bug not found: %s", name)
+            logger.info("Bug not found: %s", name)
             raise KeyError("no bug found with given name: {}".format(name))
 
-        self.__logger.info("Unexpected API response when retrieving bug: %s", name)
+        logger.info("Unexpected API response when retrieving bug: %s", name)
         self.__api.handle_erroneous_response(r)
 
     def __iter__(self) -> Iterator[str]:

bugzoo/client/container.py

@@ -10,11 +10,13 @@
 from ..testing import TestCase, TestOutcome
 from ..cmd import ExecResponse
 
+logger = logging.getLogger(__name__)  # type: logging.Logger
+
+__all__ = ['ContainerManager']
+
 
 class ContainerManager(object):
     def __init__(self, api: APIClient) -> None:
-        logging.basicConfig(level=logging.DEBUG)
-        self.__logger = logging.getLogger('container')
         self.__api = api
 
     def __getitem__(self, uid: str) -> Container:
@@ -93,12 +95,12 @@ def __iter__(self) -> Iterator[str]:
         self.__api.handle_erroneous_response(r)
 
     def provision(self, bug: Bug) -> Container:
-        self.__logger.info("provisioning container for bug: %s", bug.name)
+        logger.info("provisioning container for bug: %s", bug.name)
         r = self.__api.post('bugs/{}/provision'.format(bug.name))
 
         if r.status_code == 200:
             container = Container.from_dict(r.json())
-            self.__logger.info("provisioned container (id: %s) for bug: %s",
+            logger.info("provisioned container (id: %s) for bug: %s",
                                container.uid,
                                bug.name)
             return container

bugzoo/client/dockerm.py

@@ -1,5 +1,9 @@
+import logging
+
 from .api import APIClient
 
+logger = logging.getLogger(__name__)  # type: logging.Logger
+
 __all__ = ['DockerManager']
 
 
@@ -17,7 +21,14 @@ def delete_image(self, name: str) -> None:
         Parameters:
             name: the name of the Docker image.
         """
+        logger.info("Deleting Docker image: %s", name)
         path = "/docker/images/{}".format(name)
         response = self.__api.delete(path)
         if response.status_code != 204:
-            self.__api.handle_erroneous_response(response)
+            try:
+                self.__api.handle_erroneous_response(response)
+            except Exception:
+                logger.exception("Failed to delete Docker image: %s", name)
+                raise
+        else:
+            logger.info("Deleted Docker image: %s", name)

bugzoo/client/file.py

@@ -6,14 +6,16 @@
 from .bug import BugManager
 from ..core.container import Container
 
+logger = logging.getLogger(__name__)  # type: logging.Logger
+
+__all__ = ['FileManager']
+
 
 class FileManager(object):
     def __init__(self,
                  api: APIClient,
                  mgr_bug: BugManager
                  ) -> None:
-        logging.basicConfig(level=logging.DEBUG)
-        self.__logger = logging.getLogger('files')
         self.__api = api
         self.__mgr_bug = mgr_bug
 

bugzoo/cmd.py

@@ -1,6 +1,10 @@
-import docker
+from typing import Optional
 import sys
 
+import docker
+
+__all__ = ['PendingExecResponse', 'ExecResponse']
+
 
 class PendingExecResponse(object):
     def __init__(self, exec_response, output) -> None:
@@ -21,7 +25,7 @@ def output(self):
         return self.__output
 
     @property
-    def exit_code(self) -> int:
+    def exit_code(self) -> Optional[int]:
         if self.running:
             return None
         client = docker.from_env()

bugzoo/compiler/__init__.py

@@ -1,5 +1,6 @@
 from typing import Optional
-from bugzoo.cmd import ExecResponse
+
+from ..cmd import ExecResponse
 
 
 class CompilationOutcome(object):
@@ -140,7 +141,7 @@ def __init__(self,
         self.__time_limit = time_limit
 
     @property
-    def context(self) -> str:
+    def context(self) -> Optional[str]:
         """
         The directory from which the compilation command is called.
         """
@@ -191,7 +192,10 @@ def compile(self, # type: ignore
         """
         See `Compiler.compile`
         """
-        return self.__compile(manager_container, container, self.__command, verbose)
+        return self.__compile(manager_container,
+                              container,
+                              self.__command,
+                              verbose)
 
     def compile_with_coverage_instrumentation(self, # type: ignore
                                               manager_container,
@@ -243,7 +247,7 @@ def __init__(self,
                          time_limit=time_limit)
 
     @property
-    def workspace(self) -> str:
+    def workspace(self) -> Optional[str]:
         return self.context
 
     def to_dict(self):

bugzoo/core/build.py

@@ -44,7 +44,7 @@ def source(self) -> Optional[str]:
         return self.__source
 
     @property
-    def depends_on(self) -> str:
+    def depends_on(self) -> Optional[str]:
         """
         The name of the Docker image that the construction of the image
         associated with these build instructions depends on. If no such

bugzoo/manager.py

@@ -1,6 +1,7 @@
 from typing import Iterator
 import os
 import logging
+import logging.handlers
 import time
 
 from docker import DockerClient
@@ -14,6 +15,10 @@
 from .mgr.coverage import CoverageManager
 from .mgr.file import FileManager
 
+logger = logging.getLogger(__name__)
+
+__all__ = ['BugZoo']
+
 
 class BugZoo(object):
     """
@@ -31,7 +36,7 @@ def __init__(self, path=None) -> None:
         """
         # TODO support windows
         if path is None:
-            default_path = os.path.join(os.environ.get('HOME'), '.bugzoo')
+            default_path = os.path.join(os.environ['HOME'], '.bugzoo')
             path = os.environ.get('BUGZOO_PATH', default_path)
         self.__path = path
         path_logs = os.path.join(path, 'logs')
@@ -46,15 +51,14 @@ def __init__(self, path=None) -> None:
 
         # enable logging
         # TODO allow users to control output and verbosity
+        # TODO move to server?
         timestamp = time.strftime('%Y%m%d-%H%M%S', time.gmtime())
         log_fn = 'logs/{}.bugzoo.log'.format(timestamp)
         log_fn = os.path.join(self.__path, log_fn)
-        logging.basicConfig(filename=log_fn,
-                            filemode='w',
-                            level=logging.INFO)
-        self.__logger = logging.getLogger('bugzoo')
-        self.__logger.setLevel(logging.DEBUG)
-        self.__logger.info('Logging to: %s', log_fn)
+        log_fn_handler = logging.handlers.WatchedFileHandler(log_fn)
+
+        bz_log = logging.getLogger('bugzoo')  # type: logging.Logger
+        bz_log.addHandler(log_fn_handler)
 
         self.__docker = docker_client_from_env(timeout=120)
         self.__mgr_build = BuildManager(self.__docker)
@@ -72,13 +76,6 @@ def docker(self) -> DockerClient:
         """
         return self.__docker
 
-    @property
-    def logger(self) -> logging.Logger:
-        """
-        The root logging mechanism for BugZoo.
-        """
-        return self.__logger
-
     @property
     def path(self) -> str:
         """