Merge pull request #192 from mtxr/feature/fix-logging

Use python core logging for logs

Author: tkopets

SQLTools.py

@@ -3,13 +3,13 @@
 import sys
 import os
 import re
+import logging
 
 import sublime
 from sublime_plugin import WindowCommand, EventListener, TextCommand
 from Default.paragraph import expand_to_paragraph
 
 from .SQLToolsAPI import Utils
-from .SQLToolsAPI.Log import Log, Logger
 from .SQLToolsAPI.Storage import Storage, Settings
 from .SQLToolsAPI.Connection import Connection
 from .SQLToolsAPI.History import History
@@ -35,6 +35,19 @@
 connections                  = None
 history                      = None
 
+# create pluggin logger
+DEFAULT_LOG_LEVEL = logging.WARNING
+plugin_logger = logging.getLogger(__package__)
+# some plugins are not playing by the rules and configure the root loger
+plugin_logger.propagate = False
+if not plugin_logger.handlers:
+    plugin_logger_handler = logging.StreamHandler()
+    plugin_logger_formatter = logging.Formatter("[{name}] {levelname}: {message}", style='{')
+    plugin_logger_handler.setFormatter(plugin_logger_formatter)
+    plugin_logger.addHandler(plugin_logger_handler)
+plugin_logger.setLevel(DEFAULT_LOG_LEVEL)
+logger = logging.getLogger(__name__)
+
 
 def getSublimeUserFolder():
     return os.path.join(sublime.packages_path(), 'User')
@@ -60,27 +73,30 @@ def startPlugin():
     try:
         settings    = Settings(SETTINGS_FILENAME, default=SETTINGS_FILENAME_DEFAULT)
     except Exception as e:
-        msg = __package__ + ": Failed to parse " + SQLTOOLS_SETTINGS_FILE + " file"
-        print(msg + "\nError: " + str(e))
+        msg = '{0}: Failed to parse {1} file'.format(__package__, SQLTOOLS_SETTINGS_FILE)
+        logging.error(msg + "\nError: " + str(e))
         Window().status_message(msg)
 
     try:
         connections = Settings(CONNECTIONS_FILENAME, default=CONNECTIONS_FILENAME_DEFAULT)
     except Exception as e:
-        msg = __package__ + ": Failed to parse " + SQLTOOLS_CONNECTIONS_FILE + " file"
-        print(msg + "\nError: " + str(e))
+        msg = '{0}: Failed to parse {1} file'.format(__package__, SQLTOOLS_CONNECTIONS_FILE)
+        logging.error(msg + "\nError: " + str(e))
         Window().status_message(msg)
 
     queries     = Storage(QUERIES_FILENAME, default=QUERIES_FILENAME_DEFAULT)
     history     = History(settings.get('history_size', 100))
 
-    Logger.setPackageVersion(__version__)
-    Logger.setPackageName(__package__)
-    Logger.setLogging(settings.get('debug', True))
+    if settings.get('debug', False):
+        plugin_logger.setLevel(logging.DEBUG)
+    else:
+        plugin_logger.setLevel(DEFAULT_LOG_LEVEL)
+
     Connection.setTimeout(settings.get('thread_timeout', 15))
     Connection.setHistoryManager(history)
 
-    Log(__package__ + " Loaded!")
+    logger.info('plugin (re)loaded')
+    logger.info('version %s', __version__)
 
 
 def getConnections():
@@ -122,7 +138,6 @@ def loadDefaultConnection():
     default = connections.get('default', False)
     if not default:
         return
-    Log('Default database set to ' + default + '. Loading options and auto complete.')
     return default
 
 
@@ -308,11 +323,15 @@ def checkDefaultConnection():
         default = loadDefaultConnection()
         if not default:
             return
+
+        logger.info('default connection is set to "%s"', default)
+
         try:
-            ST.conn = ST.connectionList.get(default)
+            ST.conn = ST.connectionList[default]
+        except KeyError as e:
+            logger.error('connection "%s" set as default, but it does not exists', default)
+        else:
             ST.loadConnectionData()
-        except Exception:
-            Log("Invalid connection setted")
 
     @staticmethod
     def loadConnectionData(tablesCallback=None, columnsCallback=None, functionsCallback=None):
@@ -372,7 +391,7 @@ def setConnection(index, tablesCallback=None, columnsCallback=None, functionsCal
         connListNames.sort()
         ST.conn = ST.connectionList.get(connListNames[index])
         ST.loadConnectionData(tablesCallback, columnsCallback, functionsCallback)
-        Log('Connection {0} selected'.format(ST.conn))
+        logger.info('Connection "{0}" selected'.format(ST.conn))
 
     @staticmethod
     def selectConnection(tablesCallback=None, columnsCallback=None, functionsCallback=None):
@@ -452,7 +471,7 @@ def on_query_completions(view, prefix, locations):
             lineStr = view.substr(lineStartToLocation)
             prefix = re.split('[^`\"\w.\$]+', lineStr).pop()
         except Exception as e:
-            Log(e)
+            logger.debug(e)
 
         # use current paragraph as sql text to parse
         sqlRegion = expand_to_paragraph(view, currentPoint)
@@ -732,7 +751,6 @@ def reload():
         imp.reload(sys.modules[__package__ + ".SQLToolsAPI.Completion"])
         imp.reload(sys.modules[__package__ + ".SQLToolsAPI.Storage"])
         imp.reload(sys.modules[__package__ + ".SQLToolsAPI.History"])
-        imp.reload(sys.modules[__package__ + ".SQLToolsAPI.Log"])
         imp.reload(sys.modules[__package__ + ".SQLToolsAPI.Command"])
         imp.reload(sys.modules[__package__ + ".SQLToolsAPI.Connection"])
     except Exception as e:
@@ -760,9 +778,9 @@ def plugin_loaded():
         from package_control import events
 
         if events.install(__name__):
-            Log('Installed %s!' % events.install(__name__))
+            logger.info('Installed %s!' % events.install(__name__))
         elif events.post_upgrade(__name__):
-            Log('Upgraded to %s!' % events.post_upgrade(__name__))
+            logger.info('Upgraded to %s!' % events.post_upgrade(__name__))
             sublime.message_dialog(('{0} was upgraded.' +
                                     'If you have any problem,' +
                                     'just restart your Sublime Text.'
@@ -774,3 +792,8 @@ def plugin_loaded():
 
     startPlugin()
     reload()
+
+
+def plugin_unloaded():
+    if plugin_logger.handlers:
+        plugin_logger.handlers.pop()

SQLToolsAPI/Command.py

@@ -2,10 +2,11 @@
 import signal
 import subprocess
 import time
+import logging
 
 from threading import Thread, Timer
-from .Log import Log
 
+logger = logging.getLogger(__name__)
 
 class Command(object):
     timeout = 15
@@ -175,8 +176,9 @@ def stop(self):
             os.kill(self.process.pid, sig)
             self.process = None
 
-            Log("Your command is taking too long to run. Process killed")
-            self.callback("Command execution time exceeded 'thread_timeout'.\nProcess killed!\n\n")
+            logger.info("command execution exceeded timeout (%s s), process killed", self.timeout)
+            self.callback("Command execution time exceeded 'thread_timeout' ({0} s).\nProcess killed!\n\n"
+                          .format(self.timeout))
         except Exception:
             pass
 

SQLToolsAPI/Completion.py

@@ -1,10 +1,11 @@
 import re
+import logging
 from collections import namedtuple
 
 from .ParseUtils import extractTables
 
-_join_cond_regex_pattern = r"\s+?JOIN\s+?[\w\.`\"]+\s+?(?:AS\s+)?(\w+)\s+?ON\s+?(?:[\w\.]+)?$"
-JOIN_COND_REGEX = re.compile(_join_cond_regex_pattern, re.IGNORECASE)
+JOIN_COND_PATTERN = r"\s+?JOIN\s+?[\w\.`\"]+\s+?(?:AS\s+)?(\w+)\s+?ON\s+?(?:[\w\.]+)?$"
+JOIN_COND_REGEX = re.compile(JOIN_COND_PATTERN, re.IGNORECASE)
 
 keywords_list = [
     'SELECT', 'UPDATE', 'DELETE', 'INSERT', 'INTO', 'FROM',
@@ -13,6 +14,8 @@
     'LIMIT', 'DISTINCT', 'SET'
 ]
 
+logger = logging.getLogger(__name__)
+
 
 # this function is generously used in completions code to get rid
 # of all sorts of leading and trailing quotes in RDBMS identifiers
@@ -28,7 +31,7 @@ def _stripQuotesOnDemand(ident, doStrip=True):
 
 
 def _startsWithQuote(ident):
-    # str.startswith can be matched against a tuple
+    # ident is matched against any of the possible ident quotes
     quotes = ('`', '"')
     return ident.startswith(quotes)
 
@@ -45,24 +48,23 @@ def _escapeDollarSign(ident):
 
 
 class CompletionItem(namedtuple('CompletionItem', ['type', 'ident'])):
-    """
-    Represents a potential or actual completion item.
-      * type - Type of item e.g. (Table, Function, Column)
-      * ident - identifier e.g. ("tablename.column", "database.table", "alias")
+    """Represents a potential or actual completion item.
+      * type - type of item (Table, Function, Column)
+      * ident - identifier (table.column, schema.table, alias)
     """
     __slots__ = ()
 
-    # parent of identifier, e.g. "table" from "table.column"
     @property
     def parent(self):
+        """Parent of identifier, e.g. "table" from "table.column" """
         if self.ident.count('.') == 0:
             return None
         else:
             return self.ident.partition('.')[0]
 
-    # name of identifier, e.g. "column" from "table.column"
     @property
     def name(self):
+        """Name of identifier, e.g. "column" from "table.column" """
         return self.ident.split('.').pop()
 
     # for functions - strip open bracket "(" and everything after that
@@ -281,7 +283,8 @@ def _getAutoCompleteListSmart(self, prefix, sql, sqlToCursor):
         try:
             identifiers = extractTables(sql)
         except Exception as e:
-            print(e)
+            logger.debug('Failed to extact the list identifiers from SQL:\n {}'.format(sql),
+                         exc_info=True)
 
         # joinAlias is set only if user is editing join condition with alias. E.g.
         # SELECT a.* from tbl_a a inner join tbl_b b ON |
@@ -292,7 +295,8 @@ def _getAutoCompleteListSmart(self, prefix, sql, sqlToCursor):
                 if joinCondMatch:
                     joinAlias = joinCondMatch.group(1)
             except Exception as e:
-                print(e)
+                logger.debug('Failed search of join condition, SQL:\n {}'.format(sqlToCursor),
+                             exc_info=True)
 
         autocompleteList = []
         inhibit = False

SQLToolsAPI/Connection.py

@@ -1,12 +1,14 @@
 import shutil
 import shlex
 import codecs
+import logging
 import sqlparse
 
-from .Log import Log
 from . import Utils as U
 from . import Command as C
 
+logger = logging.getLogger(__name__)
+
 
 def _encoding_exists(enc):
     try:
@@ -17,8 +19,8 @@ def _encoding_exists(enc):
 
 
 class Connection(object):
-    DB_CLI_NOT_FOUND_MESSAGE = """'{0}' could not be found.
-Please set the path to '{0}' binary in your SQLTools settings before continuing.
+    DB_CLI_NOT_FOUND_MESSAGE = """DB CLI '{0}' could not be found.
+Please set the path to DB CLI '{0}' binary in your SQLTools settings before continuing.
 Example of "cli" section in SQLTools.sublime-settings:
     /* ...  (note the use of forward slashes) */
     "cli" : {{
@@ -72,7 +74,7 @@ def __init__(self, name, options, settings=None, commandClass='ThreadCommand'):
 
         cli_path = shutil.which(self.cli)
         if cli_path is None:
-            Log(self.DB_CLI_NOT_FOUND_MESSAGE.format(self.cli))
+            logger.info(self.DB_CLI_NOT_FOUND_MESSAGE.format(self.cli))
             raise FileNotFoundError(self.DB_CLI_NOT_FOUND_MESSAGE.format(self.cli))
 
     def __str__(self):
@@ -207,7 +209,7 @@ def execute(self, queries, callback, stream=None):
         args = self.buildArgs(queryName)
         env = self.buildEnv()
 
-        Log("Query: " + str(queryToRun))
+        logger.debug("Query: %s", str(queryToRun))
 
         self.Command.createAndRun(args=args,
                                   env=env,
@@ -297,7 +299,7 @@ def buildArgs(self, queryName=None):
         mainArgs = mainArgs.format(**self.options)
         args = args + shlex.split(mainArgs)
 
-        Log('Using cli args ' + ' '.join(args))
+        logger.debug('CLI args (%s): %s', str(queryName), ' '.join(args))
         return args
 
     def buildEnv(self):
@@ -322,7 +324,7 @@ def buildEnv(self):
                     if formattedValue:
                         env.update({var: formattedValue})
 
-        Log('Environment for command: ' + str(env))
+        logger.debug('CLI environment: %s', str(env))
         return env
 
     def getOptionsForSgdbCli(self):
@@ -342,9 +344,10 @@ def formatOptionalArgument(argument, formatOptions):
     @staticmethod
     def setTimeout(timeout):
         Connection.timeout = timeout
-        Log('Connection timeout set to {0} seconds'.format(timeout))
+        logger.info('Connection timeout set to {0} seconds'.format(timeout))
 
     @staticmethod
     def setHistoryManager(manager):
         Connection.history = manager
-        Log('Connection history defined with max size {0}'.format(manager.getMaxSize()))
+        size = manager.getMaxSize()
+        logger.info('Connection history size is {0}'.format(size))

SQLToolsAPI/Log.py

@@ -1,8 +1,7 @@
-__version__ = "v0.2.5"
+__version__ = "v0.3.0"
 
 
 __all__ = [
-    'Log',
     'Utils',
     'Completion',
     'Command',