[bug] unify logging style using class attr

I changed most of the logger statements to use a class attribute, in
this way it's easier to identify which class it's logging them.

in some cases I leave a module-level logger, when we're either using
functions or when the module it's too small.

at the same time I did a general review and cleanup of the logging
statements.

5 files changed, 74 insertions, 88 deletions

diff --git a/src/leap/bitmask/vpn/_control.py b/src/leap/bitmask/vpn/_control.py
index 6d4db965..85e4911c 100644
--- a/src/leap/bitmask/vpn/_control.py
+++ b/src/leap/bitmask/vpn/_control.py
@@ -8,7 +8,7 @@ from twisted.logger import Logger
 from .process import VPNProcess
 from .constants import IS_MAC
 
-logger = Logger()
+log = Logger()
 
 # NOTE: We need to set a bigger poll time in OSX because it seems
 # openvpn malfunctions when you ask it a lot of things in a short
@@ -47,7 +47,7 @@ class VPNControl(object):
         self._port = socket_port
 
     def start(self):
-        logger.debug('VPN: start')
+        log.debug('VPN: start')
 
         self._user_stopped = False
         self._stop_pollers()
@@ -58,13 +58,13 @@ class VPNControl(object):
             restartfun=self.restart)
 
         if vpnproc.get_openvpn_process():
-            logger.info("Another vpn process is running. Will try to stop it.")
+            log.info('Another vpn process is running. Will try to stop it.')
             vpnproc.stop_if_already_running()
 
         try:
             cmd = vpnproc.getCommand()
         except Exception as e:
-            logger.error("Error while getting vpn command... {0!r}".format(e))
+            log.error('Error while getting vpn command... {0!r}'.format(e))
             raise
 
         env = os.environ
@@ -118,7 +118,7 @@ class VPNControl(object):
             reactor.callLater(
                 self.TERMINATE_WAIT, self._kill_if_left_alive)
         else:
-            logger.debug("VPN is not running.")
+            log.debug('VPN is not running.')
 
         return True
 
@@ -153,7 +153,7 @@ class VPNControl(object):
         """
         self._stop_pollers()
         if self._vpnproc is None:
-            logger.debug("There's no vpn process running to kill.")
+            log.debug("There's no vpn process running to kill.")
         else:
             self._vpnproc.aborted = True
             self._vpnproc.killProcess()
@@ -168,10 +168,9 @@ class VPNControl(object):
         """
         while tries < self.TERMINATE_MAXTRIES:
             if self._vpnproc.transport.pid is None:
-                logger.debug("Process has been happily terminated.")
                 return
             else:
-                logger.debug("Process did not die, waiting...")
+                log.debug('Process did not die, waiting...')
 
             tries += 1
             reactor.callLater(self.TERMINATE_WAIT,
@@ -179,11 +178,11 @@ class VPNControl(object):
             return
 
         # after running out of patience, we try a killProcess
-        logger.debug("Process did not died. Sending a SIGKILL.")
+        log.debug('Process did not die. Sending a SIGKILL.')
         try:
             self._killit()
         except OSError:
-            logger.error("Could not kill process!")
+            log.error('Could not kill process!')
 
     def _start_pollers(self):
         """
diff --git a/src/leap/bitmask/vpn/_management.py b/src/leap/bitmask/vpn/_management.py
index 8bf3cc78..453b042c 100644
--- a/src/leap/bitmask/vpn/_management.py
+++ b/src/leap/bitmask/vpn/_management.py
@@ -18,9 +18,6 @@ except ImportError:
 from ._telnet import UDSTelnet
 
 
-logger = Logger()
-
-
 class OpenVPNAlreadyRunning(Exception):
     message = ("Another openvpn instance is already running, and could "
                "not be stopped.")
@@ -41,6 +38,7 @@ class VPNManagement(object):
 
       zcat `dpkg -L openvpn | grep management`
     """
+    log = Logger()
 
     # Timers, in secs
     CONNECTION_RETRY_TIME = 1
@@ -56,7 +54,7 @@ class VPNManagement(object):
         try:
             self._tn.read_eager()
         except EOFError:
-            logger.debug("Could not read from socket. Assuming it died.")
+            self.log.debug('Could not read from socket. Assuming it died.')
             return
 
     def _send_command(self, command, until=b"END"):
@@ -89,23 +87,21 @@ class VPNManagement(object):
         except socket.error:
             # XXX should get a counter and repeat only
             # after mod X times.
-            logger.warn('socket error (command was: "%s")' % (command,))
+            self.log.warn('Socket error (command was: "%s")' % (command,))
             self._close_management_socket(announce=False)
-            logger.debug('trying to connect to management again')
+            self.log.debug('Trying to connect to management again')
             self.try_to_connect_to_management(max_retries=5)
             return []
 
-        # XXX should move this to a errBack!
         except Exception as e:
-            logger.warn("Error sending command %s: %r" %
-                        (command, e))
+            self.log.warn("Error sending command %s: %r" %
+                          (command, e))
         return []
 
     def _close_management_socket(self, announce=True):
         """
         Close connection to openvpn management interface.
         """
-        logger.debug('closing socket')
         if announce:
             self._tn.write("quit\n")
             self._tn.read_all()
@@ -141,9 +137,8 @@ class VPNManagement(object):
             if self._tn:
                 self._tn.read_eager()
 
-        # XXX move this to the Errback
         except Exception as e:
-            logger.warn("Could not connect to OpenVPN yet: %r" % (e,))
+            self.log.warn('Could not connect to OpenVPN yet: %r' % (e,))
             self._tn = None
 
     def _connectCb(self, *args):
@@ -152,10 +147,8 @@ class VPNManagement(object):
 
         :param args: not used
         """
-        if self._tn:
-            logger.info('Connected to management')
-        else:
-            logger.debug('Cannot connect to management...')
+        if not self._tn:
+            self.log.warn('Cannot connect to management...')
 
     def _connectErr(self, failure):
         """
@@ -163,7 +156,7 @@ class VPNManagement(object):
 
         :param failure: Failure
         """
-        logger.warn(failure)
+        self.log.failure('Error while connecting to management!')
 
     def connect_to_management(self, host, port):
         """
@@ -200,17 +193,17 @@ class VPNManagement(object):
         :type retry: int
         """
         if max_retries and retry > max_retries:
-            logger.warn("Max retries reached while attempting to connect "
-                        "to management. Aborting.")
+            self.log.warn(
+                'Max retries reached while attempting to connect '
+                'to management. Aborting.')
             self.aborted = True
             return
 
         # _alive flag is set in the VPNProcess class.
         if not self._alive:
-            logger.debug('Tried to connect to management but process is '
-                         'not alive.')
+            self.log.debug('Tried to connect to management but process is '
+                           'not alive.')
             return
-        logger.debug('trying to connect to management')
         if not self.aborted and not self.is_connected():
             self.connect_to_management(self._socket_host, self._socket_port)
             reactor.callLater(
@@ -268,7 +261,7 @@ class VPNManagement(object):
             try:
                 text, value = parts
             except ValueError:
-                logger.debug("Could not parse %s" % parts)
+                self.log.debug('Could not parse %s' % parts)
                 return
             # text can be:
             #   "TUN/TAP read bytes"
@@ -329,13 +322,14 @@ class VPNManagement(object):
         under normal circumstances, we should be able to delete.
         """
         if self._socket_port == "unix":
-            logger.debug('cleaning socket file temp folder')
+            self.log.debug('Cleaning socket file temp folder')
             tempfolder = _first(os.path.split(self._socket_host))
             if tempfolder and os.path.isdir(tempfolder):
                 try:
                     shutil.rmtree(tempfolder)
                 except OSError:
-                    logger.error('could not delete tmpfolder %s' % tempfolder)
+                    self.log.error(
+                        'Could not delete tmpfolder %s' % tempfolder)
 
     def get_openvpn_process(self):
         """
@@ -380,11 +374,11 @@ class VPNManagement(object):
         """
         process = self.get_openvpn_process()
         if not process:
-            logger.debug('Could not find openvpn process while '
-                         'trying to stop it.')
+            self.log.debug('Could not find openvpn process while '
+                           'trying to stop it.')
             return
 
-        logger.debug("OpenVPN is already running, trying to stop it...")
+        self.log.debug('OpenVPN is already running, trying to stop it...')
         cmdline = process.cmdline
 
         manag_flag = "--management"
@@ -400,16 +394,16 @@ class VPNManagement(object):
                 return "leap" in s and "providers" in s
 
             if not any(map(smellslikeleap, cmdline)):
-                logger.debug("We cannot stop this instance since we do not "
-                             "recognise it as a leap invocation.")
+                self.log.debug("We cannot stop this instance since we do not "
+                               "recognise it as a leap invocation.")
                 raise AlienOpenVPNAlreadyRunning
 
             try:
                 index = cmdline.index(manag_flag)
                 host = cmdline[index + 1]
                 port = cmdline[index + 2]
-                logger.debug("Trying to connect to %s:%s"
-                             % (host, port))
+                self.log.debug("Trying to connect to %s:%s"
+                               % (host, port))
                 self.connect_to_management(host, port)
 
                 # XXX this has a problem with connections to different
@@ -421,19 +415,18 @@ class VPNManagement(object):
                 # However, that should be a rare case right now.
                 self._send_command("signal SIGTERM")
                 self._close_management_socket(announce=True)
-            except (Exception, AssertionError) as e:
-                logger.warn("Problem trying to terminate OpenVPN: %r"
-                            % (e,))
+            except (Exception, AssertionError):
+                self.log.failure('Problem trying to terminate OpenVPN')
         else:
-            logger.debug("Could not find the expected openvpn command line.")
+            self.log.debug('Could not find the expected openvpn command line.')
 
         process = self.get_openvpn_process()
         if process is None:
-            logger.debug("Successfully finished already running "
-                         "openvpn process.")
+            self.log.debug('Successfully finished already running '
+                           'openvpn process.')
             return True
         else:
-            logger.warn("Unable to terminate OpenVPN")
+            self.log.warn('Unable to terminate OpenVPN')
             raise OpenVPNAlreadyRunning
 
 
diff --git a/src/leap/bitmask/vpn/launcher.py b/src/leap/bitmask/vpn/launcher.py
index 3006d6da..fa9923a8 100644
--- a/src/leap/bitmask/vpn/launcher.py
+++ b/src/leap/bitmask/vpn/launcher.py
@@ -33,7 +33,7 @@ from leap.bitmask.vpn.constants import IS_LINUX
 from leap.bitmask.vpn.utils import force_eval
 
 
-logger = Logger()
+log = Logger()
 
 
 flags_STANDALONE = False
@@ -62,18 +62,18 @@ def _has_updown_scripts(path, warn=True):
     """
     is_file = os.path.isfile(path)
     if warn and not is_file:
-        logger.error("Could not find up/down script %s. "
-                     "Might produce DNS leaks." % (path,))
+        log.error('Could not find up/down script %s. '
+                  'Might produce DNS leaks.' % (path,))
 
     # XXX check if applies in win
     is_exe = False
     try:
         is_exe = (stat.S_IXUSR & os.stat(path)[stat.ST_MODE] != 0)
     except OSError as e:
-        logger.warn("%s" % (e,))
+        log.warn("%s" % (e,))
     if warn and not is_exe:
-        logger.error("Up/down script %s is not executable. "
-                     "Might produce DNS leaks." % (path,))
+        log.error('Up/down script %s is not executable. '
+                  'Might produce DNS leaks.' % (path,))
     return is_file and is_exe
 
 
@@ -91,8 +91,8 @@ def _has_other_files(path, warn=True):
     """
     is_file = os.path.isfile(path)
     if warn and not is_file:
-        logger.warning("Could not find file during checks: %s. " % (
-            path,))
+        log.warn('Could not find file during checks: %s. ' % (
+                 path,))
     return is_file
 
 
@@ -109,6 +109,7 @@ class VPNLauncher(object):
 
     PREFERRED_PORTS = ("443", "80", "53", "1194")
 
+    # FIXME -- dead code?
     @classmethod
     @abstractmethod
     def get_gateways(kls, vpnconfig, providerconfig):
@@ -138,7 +139,7 @@ class VPNLauncher(object):
             gws = [gateway_conf]
 
         if not gws:
-            logger.error('No gateway was found!')
+            log.error('No gateway was found!')
             raise VPNLauncherException('No gateway was found!')
 
         for idx, gw in enumerate(gws):
@@ -156,7 +157,7 @@ class VPNLauncher(object):
 
             gateways.append((gw, the_port))
 
-        logger.debug("Using gateways (ip, port): {0!r}".format(gateways))
+        log.debug('Using gateways (ip, port): {0!r}'.format(gateways))
         return gateways
 
     @classmethod
@@ -198,8 +199,8 @@ class VPNLauncher(object):
         openvpn_path = force_eval(kls.OPENVPN_BIN_PATH)
 
         if not os.path.isfile(openvpn_path):
-            logger.warning("Could not find openvpn bin in path %s" % (
-                openvpn_path))
+            log.warn('Could not find openvpn bin in path %s' % (
+                     openvpn_path))
             raise OpenVPNNotFoundException()
 
         args = []
@@ -321,11 +322,6 @@ class VPNLauncher(object):
 
         :rtype: list
         """
-        # leap_assert(kls.OTHER_FILES is not None,
-        #             "Need to define OTHER_FILES for this particular "
-        #             "auncher before calling this method")
-
-        # TODO assert vs except?
         if kls.OTHER_FILES is None:
             raise Exception(
                 "Need to define OTHER_FILES for this particular "
diff --git a/src/leap/bitmask/vpn/privilege.py b/src/leap/bitmask/vpn/privilege.py
index 135acbb8..9666a943 100644
--- a/src/leap/bitmask/vpn/privilege.py
+++ b/src/leap/bitmask/vpn/privilege.py
@@ -31,7 +31,7 @@ from abc import ABCMeta, abstractmethod
 from twisted.logger import Logger
 from twisted.python.procutils import which
 
-logger = Logger()
+log = Logger()
 
 
 flags_STANDALONE = False
@@ -71,8 +71,8 @@ def is_missing_policy_permissions():
     if not policy_checker:
         # it is true that we miss permission to escalate
         # privileges without asking for password each time.
-        logger.debug("we could not find a policy checker implementation "
-                     "for %s" % (_system,))
+        log.debug('we could not find a policy checker implementation '
+                  'for %s' % (_system,))
         return True
     return policy_checker().is_missing_policy_permissions()
 
@@ -146,18 +146,15 @@ class LinuxPolicyChecker(PolicyChecker):
                 time.sleep(2)
             if self.is_up():
                 pkexec_possibilities = which(self.PKEXEC_BIN)
-                # leap_assert(len(pkexec_possibilities) > 0,
-                #             "We couldn't find pkexec")
                 if not pkexec_possibilities:
-                    logger.error("We couldn't find pkexec")
                     raise Exception("We couldn't find pkexec")
                 return pkexec_possibilities
             else:
-                logger.warn("No polkit auth agent found. pkexec " +
-                            "will use its own auth agent.")
+                log.warn('No polkit auth agent found. pkexec ' +
+                         'will use its own auth agent.')
                 raise NoPolkitAuthAgentAvailable()
         else:
-            logger.warn("System has no pkexec")
+            log.warn('System has no pkexec')
             raise NoPkexecAvailable()
 
     @classmethod
@@ -178,11 +175,11 @@ class LinuxPolicyChecker(PolicyChecker):
             # will do "sh -c 'foo'", so if we do not quoute it we'll end
             # up with a invocation to the python interpreter. And that
             # is bad.
-            logger.debug("Trying to launch polkit agent")
+            log.debug('Trying to launch polkit agent')
             subprocess.call(["python -m leap.bitmask.util.polkit_agent"],
                             shell=True, env=env)
-        except Exception as exc:
-            logger.error(str(exc))
+        except Exception:
+            log.failure('Error while launching vpn')
 
     @classmethod
     def is_up(self):
diff --git a/src/leap/bitmask/vpn/process.py b/src/leap/bitmask/vpn/process.py
index 6096a473..e136e5bb 100644
--- a/src/leap/bitmask/vpn/process.py
+++ b/src/leap/bitmask/vpn/process.py
@@ -32,20 +32,21 @@ from leap.bitmask.vpn.utils import get_vpn_launcher
 from leap.bitmask.vpn import _status
 from leap.bitmask.vpn import _management
 
-logger = Logger()
-
 
 # OpenVPN verbosity level - from flags.py
 OPENVPN_VERBOSITY = 1
 
 
 class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement):
+
     """
     A ProcessProtocol class that can be used to spawn a process that will
     launch openvpn and connect to its management interface to control it
     programmatically.
     """
 
+    log = Logger()
+
     # TODO do we really need the vpnconfig/providerconfig objects in here???
 
     def __init__(self, vpnconfig, providerconfig, socket_host, socket_port,
@@ -123,7 +124,7 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement):
         line = data[:-1]
         if 'SIGTERM[soft,ping-restart]' in line:
             self.restarting = True
-        logger.info(line)
+        self.log.info(line)
         self._status.watch(line)
 
     def processExited(self, failure):
@@ -140,9 +141,9 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement):
         elif err == internet_error.ProcessTerminated:
             status, errmsg = 'failure', failure.value.exitCode
             if errmsg:
-                logger.debug("processExited, status %d" % (errmsg,))
+                self.log.debug('processExited, status %d' % (errmsg,))
             else:
-                logger.warn('%r' % failure.value)
+                self.log.warn('%r' % failure.value)
 
         self._status.set_status(status, errmsg)
         self._alive = False
@@ -156,9 +157,9 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement):
         """
         exit_code = reason.value.exitCode
         if isinstance(exit_code, int):
-            logger.debug("processEnded, status %d" % (exit_code,))
+            self.log.debug('processEnded, status %d' % (exit_code,))
             if self.restarting:
-                logger.debug('Restarting VPN process')
+                self.log.debug('Restarting VPN process')
                 reactor.callLater(2, self._restartfun)
 
     # polling
@@ -202,8 +203,8 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement):
             if not isinstance(c, str):
                 command[i] = c.encode(encoding)
 
-        logger.debug("Running VPN with command: ")
-        logger.debug("{0}".format(" ".join(command)))
+        self.log.debug("Running VPN with command: ")
+        self.log.debug("{0}".format(" ".join(command)))
         return command
 
     def getGateways(self):
@@ -227,4 +228,4 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement):
         try:
             self.transport.signalProcess('KILL')
         except internet_error.ProcessExitedAlready:
-            logger.debug('Process Exited Already')
+            self.log.debug('Process Exited Already')