From 54cd860c1394181ab49bf80990788a91ad79de56 Mon Sep 17 00:00:00 2001
From: JonnyWong16 <JonnyWong16@users.noreply.github.com>
Date: Sat, 30 Sep 2017 16:42:25 -0700
Subject: [PATCH] Separate API and websocket logging

---
 data/interfaces/default/logs.html | 105 +++++++++++++++++++++++-------
 plexpy/api2.py                    |  22 +++----
 plexpy/logger.py                  |  54 +++++++++++++--
 plexpy/web_socket.py              |   1 +
 plexpy/webserve.py                |  47 +++++++++----
 5 files changed, 178 insertions(+), 51 deletions(-)

diff --git a/data/interfaces/default/logs.html b/data/interfaces/default/logs.html
index 51fbe958..f82dfd59 100644
--- a/data/interfaces/default/logs.html
+++ b/data/interfaces/default/logs.html
@@ -55,16 +55,18 @@
     </div>
     <div class='table-card-back'>
         <div>
-            <ul class="nav nav-pills" role="tablist">
-                <li role="presentation" class="active"><a id="plexpy-logs-btn" href="#tabs-1" aria-controls="tabs-1" role="tab" data-toggle="tab">PlexPy Logs</a></li>
-                <li role="presentation"><a id="plex-logs-btn" href="#tabs-2" aria-controls="tabs-2" role="tab" data-toggle="tab">Plex Media Server Logs</a></li>
-                <li role="presentation"><a id="plex-scanner-logs-btn" href="#tabs-3" aria-controls="tabs-3" role="tab" data-toggle="tab">Plex Media Scanner Logs</a></li>
-                <li role="presentation"><a id="notification-logs-btn" href="#tabs-4" aria-controls="tabs-4" role="tab" data-toggle="tab">Notification Logs</a></li>
-                <li role="presentation"><a id="login-logs-btn" href="#tabs-5" aria-controls="tabs-5" role="tab" data-toggle="tab">Login Logs</a></li>
+            <ul id="log_tabs" class="nav nav-pills" role="tablist">
+                <li role="presentation" class="active"><a id="plexpy-logs-btn" href="#tabs-plexpy_log" aria-controls="tabs-plexpy_log" role="tab" data-toggle="tab">PlexPy Logs</a></li>
+                <li role="presentation"><a id="plexpy-api-logs-btn" href="#tabs-plexpy_api_log" aria-controls="tabs-plexpy_api_log" role="tab" data-toggle="tab">PlexPy API Logs</a></li>
+                <li role="presentation"><a id="plexpy-websocket-logs-btn" href="#tabs-plexpy_websocket_log" aria-controls="tabs-plexpy_websocket_log" role="tab" data-toggle="tab">PlexPy Websocket Logs</a></li>
+                <li role="presentation"><a id="plex-logs-btn" href="#tabs-plex_log" aria-controls="tabs-plex_log" role="tab" data-toggle="tab">Plex Media Server Logs</a></li>
+                <li role="presentation"><a id="plex-scanner-logs-btn" href="#tabs-plex_scanner_log" aria-controls="tabs-plex_scanner_log" role="tab" data-toggle="tab">Plex Media Scanner Logs</a></li>
+                <li role="presentation"><a id="notification-logs-btn" href="#tabs-notification_log" aria-controls="tabs-notification_log" role="tab" data-toggle="tab">Notification Logs</a></li>
+                <li role="presentation"><a id="login-logs-btn" href="#tabs-login_log" aria-controls="tabs-login_log" role="tab" data-toggle="tab">Login Logs</a></li>
             </ul>
             <div class="tab-content">
-                <div role="tabpanel" class="tab-pane active" id="tabs-1">
-                    <table class="display" id="log_table" width="100%">
+                <div role="tabpanel" class="tab-pane active" id="tabs-plexpy_log" data-logfile="plexpy">
+                    <table class="display" id="plexpy_log_table" width="100%">
                         <thead>
                             <tr>
                                 <th class="min-tablet" align="left" id="timestamp">Timestamp</th>
@@ -75,7 +77,31 @@
                         <tbody></tbody>
                     </table>
                 </div>
-                <div role="tabpanel" class="tab-pane" id="tabs-2">
+                <div role="tabpanel" class="tab-pane" id="tabs-plexpy_api_log" data-logfile="plexpy_api">
+                    <table class="display" id="plexpy_api_log_table" width="100%">
+                        <thead>
+                            <tr>
+                                <th class="min-tablet" align="left" id="timestamp">Timestamp</th>
+                                <th class="desktop" align="left" id="level">Level</th>
+                                <th class="all" align="left" id="message">Message</th>
+                            </tr>
+                        </thead>
+                        <tbody></tbody>
+                    </table>
+                </div>
+                <div role="tabpanel" class="tab-pane" id="tabs-plexpy_websocket_log" data-logfile="plexpy_websocket">
+                    <table class="display" id="plexpy_websocket_log_table" width="100%">
+                        <thead>
+                            <tr>
+                                <th class="min-tablet" align="left" id="timestamp">Timestamp</th>
+                                <th class="desktop" align="left" id="level">Level</th>
+                                <th class="all" align="left" id="message">Message</th>
+                            </tr>
+                        </thead>
+                        <tbody></tbody>
+                    </table>
+                </div>
+                <div role="tabpanel" class="tab-pane" id="tabs-plex_log">
                     <table class="display" id="plex_log_table" width="100%">
                         <thead>
                             <tr>
@@ -87,7 +113,7 @@
                         <tbody></tbody>
                     </table>
                 </div>
-                <div role="tabpanel" class="tab-pane" id="tabs-3">
+                <div role="tabpanel" class="tab-pane" id="tabs-plex_scanner_log">
                     <table class="display" id="plex_scanner_log_table" width="100%">
                         <thead>
                             <tr>
@@ -99,7 +125,7 @@
                         <tbody></tbody>
                     </table>
                 </div>
-                <div role="tabpanel" class="tab-pane" id="tabs-4">
+                <div role="tabpanel" class="tab-pane" id="tabs-notification_log">
                     <table class="display" id="notification_log_table" width="100%">
                         <thead>
                             <tr>
@@ -115,7 +141,7 @@
                         <tbody></tbody>
                     </table>
                 </div>
-                <div role="tabpanel" class="tab-pane" id="tabs-5">
+                <div role="tabpanel" class="tab-pane" id="tabs-login_log">
                     <table class="display login_log_table" id="login_log_table" width="100%">
                         <thead>
                             <tr>
@@ -168,8 +194,8 @@
 <script>
 
         $(document).ready(function() {
-            loadPlexPyLogs(selected_log_level);
-            clearSearchButton('log_table', log_table);
+            loadPlexPyLogs('plexpy', selected_log_level);
+            clearSearchButton('plexpy_log_table', log_table);
         });
 
         var log_levels = ['DEBUG', 'INFO', 'WARN', 'ERROR'];
@@ -200,18 +226,19 @@
         }
 
         var selected_log_level = null;
-        function loadPlexPyLogs(selected_log_level) {
+        function loadPlexPyLogs(logfile, selected_log_level) {
             log_table_options.ajax = {
                 url: "get_log",
                 type: 'post',
                 data: function (d) {
                     return {
+                        logfile: logfile,
                         json_data: JSON.stringify(d),
                         log_level: selected_log_level
                     };
                 }
             }
-            log_table = $('#log_table').DataTable(log_table_options);
+            log_table = $('#' + logfile + '_log_table').DataTable(log_table_options);
 
             $('#plexpy-log-level-filter').on('change', function () {
                 selected_log_level = $(this).val() || null;
@@ -269,8 +296,34 @@
             $("#download-plexscannerlog").hide()
             $("#clear-notify-logs").hide();
             $("#clear-login-logs").hide();
-            loadPlexPyLogs(selected_log_level);
-            clearSearchButton('log_table', log_table);
+            loadPlexPyLogs('plexpy', selected_log_level);
+            clearSearchButton('plexpy_log_table', log_table);
+        });
+
+        $("#plexpy-api-logs-btn").click(function () {
+            $("#plexpy-log-levels").show();
+            $("#plex-log-levels").hide();
+            $("#clear-logs").show();
+            $("#download-plexpylog").show()
+            $("#download-plexserverlog").hide()
+            $("#download-plexscannerlog").hide()
+            $("#clear-notify-logs").hide();
+            $("#clear-login-logs").hide();
+            loadPlexPyLogs('plexpy_api', selected_log_level);
+            clearSearchButton('plexpy_api_log_table', log_table);
+        });
+
+        $("#plexpy-websocket-logs-btn").click(function () {
+            $("#plexpy-log-levels").show();
+            $("#plex-log-levels").hide();
+            $("#clear-logs").show();
+            $("#download-plexpylog").show()
+            $("#download-plexserverlog").hide()
+            $("#download-plexscannerlog").hide()
+            $("#clear-notify-logs").hide();
+            $("#clear-login-logs").hide();
+            loadPlexPyLogs('plexpy_websocket', selected_log_level);
+            clearSearchButton('plexpy_websocket_log_table', log_table);
         });
 
         $("#plex-logs-btn").click(function () {
@@ -330,12 +383,15 @@
         });
 
         $("#clear-logs").click(function () {
+            var logfile = $(".tab-pane.active").data('logfile')
+
             $("#confirm-message").text("Are you sure you want to clear the PlexPy logs?");
             $('#confirm-modal').modal();
             $('#confirm-modal').one('click', '#confirm-button', function () {
                 $.ajax({
                     url: 'delete_logs',
                     type: 'POST',
+                    data: { logfile: logfile },
                     complete: function (xhr, status) {
                         result = $.parseJSON(xhr.responseText);
                         msg = result.message;
@@ -351,7 +407,8 @@
         });
 
         $("#download-plexpylog").click(function () {
-            window.location.href = "download_log";
+            var logfile = $(".tab-pane.active").data('logfile');
+            window.location.href = "download_log?logfile=" + logfile;
         });
 
         $("#download-plexserverlog").click(function () {
@@ -417,15 +474,15 @@
                 if(refreshrate.value != 0)
                 {
                     timer = setInterval(function() {
-                        if ($("#tabs-1").hasClass("active")) {
+                        if ($("#tabs-plexpy_log").hasClass("active") || $("#tabs-plexpy_api_log").hasClass("active") || $("#tabs-plexpy_websocket_log").hasClass("active")) {
                             log_table.ajax.reload();
-                        } else if ($("#tabs-2").hasClass("active")) {
+                        } else if ($("#tabs-plex_log").hasClass("active")) {
                             plex_log_table.ajax.reload();
-                        } else if ($("#tabs-3").hasClass("active")) {
+                        } else if ($("#tabs-plex_scanner_log").hasClass("active")) {
                             plex_scanner_log_table.ajax.reload();
-                        } else if ($("#tabs-4").hasClass("active")) {
+                        } else if ($("#tabs-notificaiton_log").hasClass("active")) {
                             notification_log_table.ajax.reload();
-                        } else if ($("#tabs-5").hasClass("active")) {
+                        } else if ($("#tabs-login_log").hasClass("active")) {
                             login_log_table.ajax.reload();
                         }
                     }, 1000*refreshrate.value);
diff --git a/plexpy/api2.py b/plexpy/api2.py
index aae44580..aeaf8b52 100644
--- a/plexpy/api2.py
+++ b/plexpy/api2.py
@@ -122,9 +122,9 @@ class API2:
             self._api_kwargs = kwargs
 
         if self._api_msg:
-            logger.debug(u'PlexPy APIv2 :: %s.' % self._api_msg)
+            logger.api_debug(u'PlexPy APIv2 :: %s.' % self._api_msg)
 
-        logger.debug(u'PlexPy APIv2 :: Cleaned kwargs: %s' % self._api_kwargs)
+        logger.api_debug(u'PlexPy APIv2 :: Cleaned kwargs: %s' % self._api_kwargs)
 
         return self._api_kwargs
 
@@ -162,7 +162,7 @@ class API2:
         end = int(kwargs.get('end', 0))
 
         if regex:
-            logger.debug(u'PlexPy APIv2 :: Filtering log using regex %s' % regex)
+            logger.api_debug(u'PlexPy APIv2 :: Filtering log using regex %s' % regex)
             reg = re.compile('u' + regex, flags=re.I)
 
         for line in open(logfile, 'r').readlines():
@@ -194,15 +194,15 @@ class API2:
                 templog.append(d)
 
         if end > 0 or start > 0:
-                logger.debug(u'PlexPy APIv2 :: Slicing the log from %s to %s' % (start, end))
+                logger.api_debug(u'PlexPy APIv2 :: Slicing the log from %s to %s' % (start, end))
                 templog = templog[start:end]
 
         if sort:
-            logger.debug(u'PlexPy APIv2 :: Sorting log based on %s' % sort)
+            logger.api_debug(u'PlexPy APIv2 :: Sorting log based on %s' % sort)
             templog = sorted(templog, key=lambda k: k[sort])
 
         if search:
-            logger.debug(u'PlexPy APIv2 :: Searching log values for %s' % search)
+            logger.api_debug(u'PlexPy APIv2 :: Searching log values for %s' % search)
             tt = [d for d in templog for k, v in d.items() if search.lower() in v.lower()]
 
             if len(tt):
@@ -509,7 +509,7 @@ General optional parameters:
                     out = self._api_callback + '(' + out + ');'
             # if we fail to generate the output fake an error
             except Exception as e:
-                logger.info(u'PlexPy APIv2 :: ' + traceback.format_exc())
+                logger.api_exception(u'PlexPy APIv2 :: ' + traceback.format_exc())
                 out['message'] = traceback.format_exc()
                 out['result'] = 'error'
 
@@ -518,14 +518,14 @@ General optional parameters:
             try:
                 out = xmltodict.unparse(out, pretty=True)
             except Exception as e:
-                logger.error(u'PlexPy APIv2 :: Failed to parse xml result')
+                logger.api_error(u'PlexPy APIv2 :: Failed to parse xml result')
                 try:
                     out['message'] = e
                     out['result'] = 'error'
                     out = xmltodict.unparse(out, pretty=True)
 
                 except Exception as e:
-                    logger.error(u'PlexPy APIv2 :: Failed to parse xml result error message %s' % e)
+                    logger.api_error(u'PlexPy APIv2 :: Failed to parse xml result error message %s' % e)
                     out = '''<?xml version="1.0" encoding="utf-8"?>
                                 <response>
                                     <message>%s</message>
@@ -540,7 +540,7 @@ General optional parameters:
         """ handles the stuff from the handler """
 
         result = {}
-        logger.debug(u'PlexPy APIv2 :: API called with kwargs: %s' % kwargs)
+        logger.api_debug(u'PlexPy APIv2 :: API called with kwargs: %s' % kwargs)
 
         self._api_validate(**kwargs)
 
@@ -558,7 +558,7 @@ General optional parameters:
 
                 result = call(**self._api_kwargs)
             except Exception as e:
-                logger.error(u'PlexPy APIv2 :: Failed to run %s with %s: %s' % (self._api_cmd, self._api_kwargs, e))
+                logger.api_error(u'PlexPy APIv2 :: Failed to run %s with %s: %s' % (self._api_cmd, self._api_kwargs, e))
                 if self._api_debug:
                     cherrypy.request.show_tracebacks = True
                     # Reraise the exception so the traceback hits the browser
diff --git a/plexpy/logger.py b/plexpy/logger.py
index dc24d0ed..69fb08be 100644
--- a/plexpy/logger.py
+++ b/plexpy/logger.py
@@ -31,6 +31,8 @@ import helpers
 
 # These settings are for file logging only
 FILENAME = "plexpy.log"
+FILENAME_API = "plexpy_api.log"
+FILENAME_WEBSOCKET = "plexpy_websocket.log"
 MAX_SIZE = 5000000  # 5 MB
 MAX_FILES = 5
 
@@ -38,6 +40,10 @@ _BLACKLIST_WORDS = []
 
 # PlexPy logger
 logger = logging.getLogger("plexpy")
+# PlexPy API logger
+logger_api = logging.getLogger("plexpy_api")
+# PlexPy websocket logger
+logger_websocket = logging.getLogger("plexpy_websocket")
 
 # Global queue for multiprocessing logging
 queue = None
@@ -184,7 +190,7 @@ def initLogger(console=False, log_dir=False, verbose=False):
 
     # Close and remove old handlers. This is required to reinit the loggers
     # at runtime
-    for handler in logger.handlers[:]:
+    for handler in logger.handlers[:] + logger_api.handlers[:] + logger_websocket.handlers[:]:
         # Just make sure it is cleaned up.
         if isinstance(handler, handlers.RotatingFileHandler):
             handler.close()
@@ -192,22 +198,45 @@ def initLogger(console=False, log_dir=False, verbose=False):
             handler.flush()
 
         logger.removeHandler(handler)
+        logger_api.removeHandler(handler)
+        logger_websocket.removeHandler(handler)
 
     # Configure the logger to accept all messages
     logger.propagate = False
     logger.setLevel(logging.DEBUG if verbose else logging.INFO)
+    logger_api.propagate = False
+    logger_api.setLevel(logging.DEBUG if verbose else logging.INFO)
+    logger_websocket.propagate = False
+    logger_websocket.setLevel(logging.DEBUG if verbose else logging.INFO)
 
     # Setup file logger
     if log_dir:
-        filename = os.path.join(log_dir, FILENAME)
-
         file_formatter = logging.Formatter('%(asctime)s - %(levelname)-7s :: %(threadName)s : %(message)s', '%Y-%m-%d %H:%M:%S')
+
+        # Main PlexPy logger
+        filename = os.path.join(log_dir, FILENAME)
         file_handler = handlers.RotatingFileHandler(filename, maxBytes=MAX_SIZE, backupCount=MAX_FILES)
         file_handler.setLevel(logging.DEBUG)
         file_handler.setFormatter(file_formatter)
 
         logger.addHandler(file_handler)
 
+        # PlexPy API logger
+        filename = os.path.join(log_dir, FILENAME_API)
+        file_handler = handlers.RotatingFileHandler(filename, maxBytes=MAX_SIZE, backupCount=MAX_FILES)
+        file_handler.setLevel(logging.DEBUG)
+        file_handler.setFormatter(file_formatter)
+
+        logger_api.addHandler(file_handler)
+
+        # PlexPy websocket logger
+        filename = os.path.join(log_dir, FILENAME_WEBSOCKET)
+        file_handler = handlers.RotatingFileHandler(filename, maxBytes=MAX_SIZE, backupCount=MAX_FILES)
+        file_handler.setLevel(logging.DEBUG)
+        file_handler.setFormatter(file_formatter)
+
+        logger_websocket.addHandler(file_handler)
+
     # Setup console logger
     if console:
         console_formatter = logging.Formatter('%(asctime)s - %(levelname)s :: %(threadName)s : %(message)s', '%Y-%m-%d %H:%M:%S')
@@ -221,7 +250,7 @@ def initLogger(console=False, log_dir=False, verbose=False):
     # Only add filters after the config file has been initialized
     # Nothing prior to initialization should contain sensitive information
     if not plexpy.DEV and plexpy.CONFIG:
-        for handler in logger.handlers:
+        for handler in logger.handlers + logger_api.handlers + logger_websocket.handlers:
             handler.addFilter(BlacklistFilter())
             handler.addFilter(PublicIPFilter())
 
@@ -278,9 +307,26 @@ def initHooks(global_exceptions=True, thread_exceptions=True, pass_original=True
         threading.Thread.__init__ = new_init
 
 # Expose logger methods
+# Main PlexPy logger
 info = logger.info
 warn = logger.warn
 error = logger.error
 debug = logger.debug
 warning = logger.warning
 exception = logger.exception
+
+# PlexPy API logger
+api_info = logger_api.info
+api_warn = logger_api.warn
+api_error = logger_api.error
+api_debug = logger_api.debug
+api_warning = logger_api.warning
+api_exception = logger_api.exception
+
+# PlexPy websocket logger
+websocket_info = logger_websocket.info
+websocket_warn = logger_websocket.warn
+websocket_error = logger_websocket.error
+websocket_debug = logger_websocket.debug
+websocket_warning = logger_websocket.warning
+websocket_exception = logger_websocket.exception
diff --git a/plexpy/web_socket.py b/plexpy/web_socket.py
index 1fba8720..d74512f5 100644
--- a/plexpy/web_socket.py
+++ b/plexpy/web_socket.py
@@ -172,6 +172,7 @@ def process(opcode, data):
         return False
 
     try:
+        logger.websocket_debug(data)
         info = json.loads(data)
     except Exception as e:
         logger.warn(u"PlexPy WebSocket :: Error decoding message from websocket: %s" % e)
diff --git a/plexpy/webserve.py b/plexpy/webserve.py
index 7a635afe..7eb123f4 100644
--- a/plexpy/webserve.py
+++ b/plexpy/webserve.py
@@ -2278,7 +2278,7 @@ class WebInterface(object):
 
     @cherrypy.expose
     @requireAuth(member_of("admin"))
-    def get_log(self, **kwargs):
+    def get_log(self, logfile='', **kwargs):
         json_data = helpers.process_json_kwargs(json_kwargs=kwargs.get('json_data'))
         log_level = kwargs.get('log_level', "")
 
@@ -2292,7 +2292,15 @@ class WebInterface(object):
         filt = []
         filtered = []
         fa = filt.append
-        with open(os.path.join(plexpy.CONFIG.LOG_DIR, logger.FILENAME)) as f:
+
+        if logfile == "plexpy_api":
+            filename = logger.FILENAME_API
+        elif logfile == "plexpy_websocket":
+            filename = logger.FILENAME_WEBSOCKET
+        else:
+            filename = logger.FILENAME
+
+        with open(os.path.join(plexpy.CONFIG.LOG_DIR, filename)) as f:
             for l in f.readlines():
                 try:
                     temp_loglevel_and_time = l.split(' - ', 1)
@@ -2487,17 +2495,23 @@ class WebInterface(object):
     @cherrypy.expose
     @cherrypy.tools.json_out()
     @requireAuth(member_of("admin"))
-    def delete_logs(self, **kwargs):
-        log_file = logger.FILENAME
+    def delete_logs(self, logfile='', **kwargs):
+        if logfile == "plexpy_api":
+            filename = logger.FILENAME_API
+        elif logfile == "plexpy_websocket":
+            filename = logger.FILENAME_WEBSOCKET
+        else:
+            filename = logger.FILENAME
+
         try:
-            open(os.path.join(plexpy.CONFIG.LOG_DIR, log_file), 'w').close()
+            open(os.path.join(plexpy.CONFIG.LOG_DIR, filename), 'w').close()
             result = 'success'
-            msg = 'Cleared the %s file.' % log_file
+            msg = 'Cleared the %s file.' % filename
             logger.info(msg)
         except Exception as e:
             result = 'error'
-            msg = 'Failed to clear the %s file.' % log_file
-            logger.exception(u'Failed to clear the %s file: %s.' % (log_file, e))
+            msg = 'Failed to clear the %s file.' % filename
+            logger.exception(u'Failed to clear the %s file: %s.' % (filename, e))
 
         return {'result': result, 'message': msg}
 
@@ -3737,15 +3751,24 @@ class WebInterface(object):
     @cherrypy.expose
     @requireAuth(member_of("admin"))
     @addtoapi()
-    def download_log(self, **kwargs):
+    def download_log(self, logfile='', **kwargs):
         """ Download the PlexPy log file. """
-        log_file = logger.FILENAME
+        if logfile == "plexpy_api":
+            filename = logger.FILENAME_API
+            log = logger.logger
+        elif logfile == "plexpy_websocket":
+            filename = logger.FILENAME_WEBSOCKET
+            log = logger.logger_api
+        else:
+            filename = logger.FILENAME
+            log = logger.logger_websocket
+
         try:
-            logger.logger.flush()
+            log.flush()
         except:
             pass
 
-        return serve_download(os.path.join(plexpy.CONFIG.LOG_DIR, log_file), name=log_file)
+        return serve_download(os.path.join(plexpy.CONFIG.LOG_DIR, filename), name=filename)
 
     @cherrypy.expose
     @requireAuth(member_of("admin"))