Merge branch 'logging' into development

6 files changed, 202 insertions, 69 deletions

diff --git a/bazarr/get_settings.py b/bazarr/get_settings.py
index ebe291686..038cbb583 100644
--- a/bazarr/get_settings.py
+++ b/bazarr/get_settings.py
@@ -39,10 +39,10 @@ def get_general_settings():
         else:
             path_mappings = '[]'
 
-        if cfg.has_option('general', 'log_level'):
-            log_level = cfg.get('general', 'log_level')
+        if cfg.has_option('general', 'debug'):
+            debug = cfg.getboolean('general', 'debug')
         else:
-            log_level = 'INFO'
+            debug = False
 
         if cfg.has_option('general', 'branch'):
             branch = cfg.get('general', 'branch')
@@ -154,7 +154,7 @@ def get_general_settings():
         port = '6767'
         base_url = '/'
         path_mappings = '[]'
-        log_level = 'INFO'
+        debug = False
         branch = 'master'
         auto_update = True
         single_language = False
@@ -177,7 +177,7 @@ def get_general_settings():
         only_monitored = False
         adaptive_searching = False
 
-    return [ip, port, base_url, path_mappings, log_level, branch, auto_update, single_language, minimum_score, use_scenename, use_postprocessing, postprocessing_cmd, use_sonarr, use_radarr, path_mappings_movie, serie_default_enabled, serie_default_language, serie_default_hi, movie_default_enabled,movie_default_language, movie_default_hi, page_size, minimum_score_movie, use_embedded_subs, only_monitored, adaptive_searching]
+    return [ip, port, base_url, path_mappings, debug, branch, auto_update, single_language, minimum_score, use_scenename, use_postprocessing, postprocessing_cmd, use_sonarr, use_radarr, path_mappings_movie, serie_default_enabled, serie_default_language, serie_default_hi, movie_default_enabled,movie_default_language, movie_default_hi, page_size, minimum_score_movie, use_embedded_subs, only_monitored, adaptive_searching]
 
 
 def get_auth_settings():
@@ -450,7 +450,7 @@ ip = result[0]
 port = result[1]
 base_url = result[2]
 path_mappings = ast.literal_eval(result[3])
-log_level = result[4]
+debug = result[4]
 branch = result[5]
 automatic = result[6]
 single_language = result[7]
diff --git a/bazarr/init.py b/bazarr/init.py
index 8078a48a1..633b9347b 100644
--- a/bazarr/init.py
+++ b/bazarr/init.py
@@ -66,6 +66,13 @@ if cfg.has_section('auth'):
         cfg.remove_option('auth', 'enabled')
         with open(config_file, 'w+') as configfile:
             cfg.write(configfile)
+            
+if cfg.has_section('general'):
+    if cfg.has_option('general', 'log_level'):
+        cfg.remove_option('general', 'log_level')
+        cfg.set('general', 'debug', 'False')
+        with open(config_file, 'w+') as configfile:
+            cfg.write(configfile)
 
 from cork import Cork
 import time
diff --git a/bazarr/logger.py b/bazarr/logger.py
new file mode 100644
index 000000000..1a7e34f29
--- /dev/null
+++ b/bazarr/logger.py
@@ -0,0 +1,157 @@
+import os
+import sys
+import logging
+import re
+
+from logging.handlers import TimedRotatingFileHandler
+from get_argv import config_dir
+from get_settings import get_general_settings
+
+logger = logging.getLogger()
+
+debug = get_general_settings()[4]
+if debug is False:
+    log_level = "INFO"
+else:
+    log_level = "DEBUG"
+
+class OneLineExceptionFormatter(logging.Formatter):
+    def formatException(self, exc_info):
+        """
+        Format an exception so that it prints on a single line.
+        """
+        result = super(OneLineExceptionFormatter, self).formatException(exc_info)
+        return repr(result)  # or format into one line however you want to
+    
+    def format(self, record):
+        s = super(OneLineExceptionFormatter, self).format(record)
+        if record.exc_text:
+            s = s.replace('\n', '') + '|'
+        return s
+
+
+class NoExceptionFormatter(logging.Formatter):
+    def format(self, record):
+        record.exc_text = ''  # ensure formatException gets called
+        return super(NoExceptionFormatter, self).format(record)
+    
+    def formatException(self, record):
+        return ''
+
+
+def configure_logging():
+    logger.handlers = []
+    
+    logger.setLevel(log_level)
+
+    # Console logging
+    ch = logging.StreamHandler()
+    cf = NoExceptionFormatter('%(asctime)-15s - %(name)-32s (%(thread)x) :  %(levelname)s (%(module)s:%(lineno)d) '
+                               '- %(message)s')
+    ch.setFormatter(cf)
+
+    ch.setLevel(log_level)
+    # ch.addFilter(MyFilter())
+    logger.addHandler(ch)
+    
+    #File Logging
+    global fh
+    fh = TimedRotatingFileHandler(os.path.join(config_dir, 'log/bazarr.log'), when="midnight", interval=1,
+                                  backupCount=7)
+    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)-8s|%(name)-32s|%(message)s|',
+                                  '%d/%m/%Y %H:%M:%S')
+    fh.setFormatter(f)
+    fh.addFilter(BlacklistFilter())
+    fh.addFilter(PublicIPFilter())
+
+    if debug is True:
+        logging.getLogger("apscheduler").setLevel(logging.DEBUG)
+        logging.getLogger("subliminal").setLevel(logging.DEBUG)
+        logging.getLogger("git").setLevel(logging.DEBUG)
+        logging.getLogger("apprise").setLevel(logging.DEBUG)
+    else:
+        logging.getLogger("apscheduler").setLevel(logging.WARNING)
+        logging.getLogger("subliminal").setLevel(logging.CRITICAL)
+        
+    logging.getLogger("enzyme").setLevel(logging.CRITICAL)
+    logging.getLogger("guessit").setLevel(logging.WARNING)
+    logging.getLogger("rebulk").setLevel(logging.WARNING)
+    logging.getLogger("stevedore.extension").setLevel(logging.CRITICAL)
+    fh.setLevel(log_level)
+    logger.addHandler(fh)
+    
+
+class MyFilter(logging.Filter):
+    def __init__(self):
+        pass
+    
+    def filter(self, record):
+        if record.name != 'root':
+            return False
+        return True
+    
+
+class BlacklistFilter(logging.Filter):
+    """
+    Log filter for blacklisted tokens and passwords
+    """
+    def __init__(self):
+        pass
+
+    def filter(self, record):
+        try:
+            apikeys = re.findall(r'apikey(?:=|%3D)([a-zA-Z0-9]+)', record.msg)
+            for apikey in apikeys:
+                record.msg = record.msg.replace(apikey, 8 * '*' + apikey[-2:])
+    
+            args = []
+            for arg in record.args:
+                apikeys = re.findall(r'apikey(?:=|%3D)([a-zA-Z0-9]+)', arg) if isinstance(arg, basestring) else []
+                for apikey in apikeys:
+                    arg = arg.replace(apikey, 8 * '*' + apikey[-2:])
+                args.append(arg)
+            record.args = tuple(args)
+        except:
+            pass
+        return True
+
+
+class PublicIPFilter(logging.Filter):
+    """
+    Log filter for public IP addresses
+    """
+    def __init__(self):
+        pass
+
+    def filter(self, record):
+        try:
+            # Currently only checking for ipv4 addresses
+            ipv4 = re.findall(r'[0-9]+(?:\.[0-9]+){3}(?!\d*-[a-z0-9]{6})', record.msg)
+            for ip in ipv4:
+                record.msg = record.msg.replace(ip, ip.partition('.')[0] + '.***.***.***')
+
+            args = []
+            for arg in record.args:
+                ipv4 = re.findall(r'[0-9]+(?:\.[0-9]+){3}(?!\d*-[a-z0-9]{6})', arg) if isinstance(arg, basestring) else []
+                for ip in ipv4:
+                    arg = arg.replace(ip, ip.partition('.')[0] + '.***.***.***')
+                args.append(arg)
+            record.args = tuple(args)
+        except:
+            pass
+
+        return True
+
+
+def empty_log():
+    fh.doRollover()
+    
+
+def update_settings(debug):
+    if debug == 'False':
+        level = "INFO"
+    else:
+        level = "DEBUG"
+    logger.setLevel(level)
+    for handler in logger.handlers:
+        handler.setLevel(level)
diff --git a/bazarr/main.py b/bazarr/main.py
index c62d94cea..4c0269b38 100644
--- a/bazarr/main.py
+++ b/bazarr/main.py
@@ -23,42 +23,7 @@ update_notifier()
 
 from get_settings import get_general_settings, get_proxy_settings
 import logging
-from logging.handlers import TimedRotatingFileHandler
-
-log_level = get_general_settings()[4]
-if log_level is None:
-    log_level = "INFO"
-
-class OneLineExceptionFormatter(logging.Formatter):
-    def formatException(self, exc_info):
-        """
-        Format an exception so that it prints on a single line.
-        """
-        result = super(OneLineExceptionFormatter, self).formatException(exc_info)
-        return repr(result) # or format into one line however you want to
-
-    def format(self, record):
-        s = super(OneLineExceptionFormatter, self).format(record)
-        if record.exc_text:
-            s = s.replace('\n', '') + '|'
-        return s
-
-def configure_logging():
-    global fh
-    fh = TimedRotatingFileHandler(os.path.join(config_dir, 'log/bazarr.log'), when="midnight", interval=1, backupCount=7)
-    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
-                                  '%d/%m/%Y %H:%M:%S')
-    fh.setFormatter(f)
-    logging.getLogger("enzyme").setLevel(logging.CRITICAL)
-    logging.getLogger("apscheduler").setLevel(logging.WARNING)
-    logging.getLogger("subliminal").setLevel(logging.CRITICAL)
-    logging.getLogger("guessit").setLevel(logging.WARNING)
-    logging.getLogger("rebulk").setLevel(logging.WARNING)
-    logging.getLogger("stevedore.extension").setLevel(logging.CRITICAL)
-    root = logging.getLogger()
-    root.setLevel(log_level)
-    root.addHandler(fh)
-
+from logger import configure_logging, empty_log, update_settings
 configure_logging()
 
 import requests
@@ -228,7 +193,7 @@ def restart():
         except Exception as e:
             logging.error('BAZARR Cannot create bazarr.restart file.')
         else:
-            print 'Bazarr is being restarted...'
+            # print 'Bazarr is being restarted...'
             logging.info('Bazarr is being restarted...')
             restart_file.write('')
             restart_file.close()
@@ -454,7 +419,7 @@ def emptylog():
     authorize()
     ref = request.environ['HTTP_REFERER']
 
-    fh.doRollover()
+    empty_log()
     logging.info('BAZARR Log file emptied')
 
     redirect(ref)
@@ -1069,7 +1034,11 @@ def save_settings():
     settings_general_baseurl = request.forms.get('settings_general_baseurl')
     if settings_general_baseurl.endswith('/') is False:
         settings_general_baseurl += '/'
-    settings_general_loglevel = request.forms.get('settings_general_loglevel')
+    settings_general_debug = request.forms.get('settings_general_debug')
+    if settings_general_debug is None:
+        settings_general_debug = 'False'
+    else:
+        settings_general_debug = 'True'
     settings_general_sourcepath = request.forms.getall('settings_general_sourcepath')
     settings_general_destpath = request.forms.getall('settings_general_destpath')
     settings_general_pathmapping = []
@@ -1131,8 +1100,8 @@ def save_settings():
 
     settings_general = get_general_settings()
 
-    before = (unicode(settings_general[0]), int(settings_general[1]), unicode(settings_general[2]), unicode(settings_general[4]), unicode(settings_general[3]), unicode(settings_general[12]), unicode(settings_general[13]), unicode(settings_general[14]))
-    after = (unicode(settings_general_ip), int(settings_general_port), unicode(settings_general_baseurl), unicode(settings_general_loglevel), unicode(settings_general_pathmapping), unicode(settings_general_use_sonarr), unicode(settings_general_use_radarr), unicode(settings_general_pathmapping_movie))
+    before = (unicode(settings_general[0]), int(settings_general[1]), unicode(settings_general[2]), unicode(settings_general[3]), unicode(settings_general[12]), unicode(settings_general[13]), unicode(settings_general[14]))
+    after = (unicode(settings_general_ip), int(settings_general_port), unicode(settings_general_baseurl), unicode(settings_general_pathmapping), unicode(settings_general_use_sonarr), unicode(settings_general_use_radarr), unicode(settings_general_pathmapping_movie))
     from six import text_type
 
     cfg = ConfigParser()
@@ -1144,7 +1113,7 @@ def save_settings():
     cfg.set('general', 'port', text_type(settings_general_port))
     cfg.set('general', 'base_url', text_type(settings_general_baseurl))
     cfg.set('general', 'path_mappings', text_type(settings_general_pathmapping))
-    cfg.set('general', 'log_level', text_type(settings_general_loglevel))
+    cfg.set('general', 'debug', text_type(settings_general_debug))
     cfg.set('general', 'branch', text_type(settings_general_branch))
     cfg.set('general', 'auto_update', text_type(settings_general_automatic))
     cfg.set('general', 'single_language', text_type(settings_general_single_language))
@@ -1160,6 +1129,8 @@ def save_settings():
     cfg.set('general', 'use_embedded_subs', text_type(settings_general_embedded))
     cfg.set('general', 'only_monitored', text_type(settings_general_only_monitored))
     cfg.set('general', 'adaptive_searching', text_type(settings_general_adaptive_searching))
+    
+    update_settings(settings_general_debug)
 
     if after != before:
         configured()
@@ -1754,7 +1725,7 @@ warnings.simplefilter("ignore", DeprecationWarning)
 server = CherryPyWSGIServer((str(ip), int(port)), app)
 try:
     logging.info('BAZARR is started and waiting for request on http://' + str(ip) + ':' + str(port) + str(base_url))
-    print 'Bazarr is started and waiting for request on http://' + str(ip) + ':' + str(port) + str(base_url)
+    # print 'Bazarr is started and waiting for request on http://' + str(ip) + ':' + str(port) + str(base_url)
     server.start()
 except KeyboardInterrupt:
     shutdown()
diff --git a/views/logs.tpl b/views/logs.tpl
index ea8fe473f..b8ec92f0a 100644
--- a/views/logs.tpl
+++ b/views/logs.tpl
@@ -34,25 +34,27 @@
 					%line = log.split('|')
 					<tr class='log' data-message="\\
 %try:
-{{line[2]}}\\
+{{line[3]}}\\
 %except:
 \\
 %end
 " data-exception="\\
 %try:
-{{line[3]}}\\
+{{line[4]}}\\
 %except:
 \\
 %end
 ">
 						<td class="collapsing"><i class="\\
 %try:
-%if line[1] == 'INFO':
+%if line[1] == 'INFO    ':
 blue info circle icon \\
-%elif line[1] == 'WARNING':
+%elif line[1] == 'WARNING ':
 yellow warning circle icon \\
-%elif line[1] == 'ERROR':
+%elif line[1] == 'ERROR   ':
 red bug icon \\
+%elif line[1] == 'DEBUG   ':
+bug icon \\
 %end
 %except:
 %pass
@@ -60,7 +62,7 @@ red bug icon \\
 "></i></td>
 						<td>\\
 %try:
-{{line[2]}}\\
+{{line[3]}}\\
 %except:
 \\
 %end
diff --git a/views/settings.tpl b/views/settings.tpl
index 40e86878a..212b32dd9 100644
--- a/views/settings.tpl
+++ b/views/settings.tpl
@@ -138,22 +138,12 @@
 
                         <div class="middle aligned row">
                             <div class="right aligned four wide column">
-                                <label>Log Level</label>
+                                <label>Enable debug logging</label>
                             </div>
                             <div class="five wide column">
-                                <select name="settings_general_loglevel" id="settings_loglevel" class="ui fluid selection dropdown">
-                                    <option value="">Log Level</option>
-                                    <option value="DEBUG">Debug</option>
-                                    <option value="INFO">Info</option>
-                                    <option value="WARNING">Warning</option>
-                                    <option value="ERROR">Error</option>
-                                    <option value="CRITICAL">Critical</option>
-                                </select>
-                            </div>
-
-                            <div class="collapsed center aligned column">
-                                <div class="ui basic icon" data-tooltip="Requires restart to take effect" data-inverted="">
-                                    <i class="yellow warning sign icon"></i>
+                                <div id="settings_debug" class="ui toggle checkbox" data-debug={{settings_general[4]}}>
+                                    <input name="settings_general_debug" type="checkbox">
+                                    <label></label>
                                 </div>
                             </div>
                             <div class="collapsed center aligned column">
@@ -1413,6 +1403,12 @@
                 $("#settings_automatic_div").checkbox('uncheck');
             }
 
+    if ($('#settings_debug').data("debug") == "True") {
+                $("#settings_debug").checkbox('check');
+            } else {
+                $("#settings_debug").checkbox('uncheck');
+            }
+
     if ($('#settings_single_language').data("single-language") == "True") {
                 $("#settings_single_language").checkbox('check');
             } else {