Merge pull request #3129 from xoriole/debug_pane_logs

Logs tab in debug pane

Tribler/Core/Modules/restapi/debug_endpoint.py

@@ -1,3 +1,4 @@
+import logging
 import os
 
 import datetime
@@ -20,7 +21,8 @@ def __init__(self, session):
 
         child_handler_dict = {"circuits": DebugCircuitsEndpoint, "open_files": DebugOpenFilesEndpoint,
                               "open_sockets": DebugOpenSocketsEndpoint, "threads": DebugThreadsEndpoint,
-                              "cpu": DebugCPUEndpoint, "memory": DebugMemoryEndpoint}
+                              "cpu": DebugCPUEndpoint, "memory": DebugMemoryEndpoint,
+                              "log": DebugLogEndpoint}
 
         for path, child_cls in child_handler_dict.iteritems():
             self.putChild(path, child_cls(session))
@@ -342,3 +344,92 @@ def render_GET(self, request):
         request.setHeader(b'content-type', 'application/json')
         request.setHeader(b'Content-Disposition', 'attachment; filename=tribler_memory_dump_%s.json' % date_str)
         return open(dump_file_path).read()
+
+
+class DebugLogEndpoint(resource.Resource):
+    """
+    This class handles the request for displaying the logs.
+    """
+
+    def __init__(self, session):
+        resource.Resource.__init__(self)
+        self.session = session
+
+    def render_GET(self, request):
+        """
+        .. http:get:: /debug/log?max_lines=<max_lines>
+
+        A GET request to this endpoint returns a json with content of log file & max_lines requested
+
+            **Example request**:
+
+            .. sourcecode:: none
+
+                curl -X GET http://localhost:8085/debug/log?max_lines=5
+
+            **Example response**:
+
+            A JSON with content of the log file & max_lines requested, for eg.
+            {
+                "max_lines" : 5,
+                "content" :"INFO    1506675301.76   sqlitecachedb:181   Reading database version...
+                            INFO    1506675301.76   sqlitecachedb:185   Current database version is 29
+                            INFO    1506675301.76   sqlitecachedb:203   Beginning the first transaction...
+                            INFO    1506675301.76         upgrade:93    tribler is in the latest version,...
+                            INFO    1506675302.08  LaunchManyCore:254   lmc: Starting Dispersy..."
+            }
+
+        """
+
+        # First, flush all the logs to make sure it is written to file
+        for handler in logging.getLogger().handlers:
+            handler.flush()
+
+        # Get the location of log file
+        log_file = os.path.join(self.session.get_state_dir(), 'logs', 'tribler-info.log')
+
+        # Default response
+        response = {'content': '', 'max_lines': 0}
+
+        # Check if log file exists and return last requested 'max_lines' of log
+        if os.path.exists(log_file):
+            try:
+                max_lines = int(request.args['max_lines'][0])
+                response['content'] = self.tail(open(log_file), max_lines)
+                response['max_lines'] = max_lines
+            except ValueError:
+                response['content'] = open(log_file).read()
+                response['max_lines'] = 0
+
+        return json.dumps(response)
+
+    def tail(self, file_handler, lines=1):
+        """Tail a file and get X lines from the end"""
+        # place holder for the lines found
+        lines_found = []
+        byte_buffer = 1024
+
+        # block counter will be multiplied by buffer
+        # to get the block size from the end
+        block_counter = -1
+
+        # loop until we find X lines
+        while len(lines_found) < lines:
+            try:
+                file_handler.seek(block_counter * byte_buffer, os.SEEK_END)
+            except IOError:  # either file is too small, or too many lines requested
+                file_handler.seek(0)
+                lines_found = file_handler.readlines()
+                break
+
+            lines_found = file_handler.readlines()
+
+            # we found enough lines, get out
+            if len(lines_found) > lines:
+                break
+
+            # decrement the block counter to get the
+            # next X bytes
+            block_counter -= 1
+
+        return ''.join(lines_found[-lines:])

Tribler/Test/Core/Modules/RestApi/test_debug_endpoint.py

@@ -1,10 +1,14 @@
+import logging
+import logging.config
+import os
+
 from twisted.internet.defer import inlineCallbacks
 
+import Tribler.Core.Utilities.json_util as json
 from Tribler.Test.Core.Modules.RestApi.base_api_test import AbstractApiTest
 from Tribler.Test.Core.base_test import MockObject
 from Tribler.Test.twisted_thread import deferred
 from Tribler.community.tunnel.hidden_community import HiddenTunnelCommunity
-import Tribler.Core.Utilities.json_util as json
 from Tribler.dispersy.dispersy import Dispersy
 from Tribler.dispersy.endpoint import ManualEnpoint
 from Tribler.dispersy.member import DummyMember
@@ -147,3 +151,44 @@ def verify_response(response):
 
         self.should_check_equality = False
         return self.do_request('debug/memory/dump', expected_code=200).addCallback(verify_response)
+
+    @deferred(timeout=10)
+    def test_debug_pane_logs(self):
+        """
+        Test whether the API returns the logs
+        """
+
+        test_log_message = "This is the test log message"
+        max_lines = 100
+
+        import Tribler
+        project_root_dir = os.path.abspath(os.path.join(os.path.dirname(Tribler.__file__), ".."))
+        log_config = os.path.join(project_root_dir, "logger.conf")
+
+        # State directory for logs
+        state_log_dir = os.path.join(self.session.get_state_dir(), 'logs')
+        if not os.path.exists(state_log_dir):
+            os.makedirs(state_log_dir)
+
+        # Setup logging
+        logging.info_log_file = os.path.join(state_log_dir, 'tribler-info.log')
+        logging.error_log_file = os.path.join(state_log_dir, 'tribler-error.log')
+        logging.config.fileConfig(log_config, disable_existing_loggers=False)
+
+        def verify_log_exists(response):
+            json_response = json.loads(response)
+            logs = json_response['content'].strip().split("\n")
+
+            # Check number of logs returned is correct
+            self.assertEqual(len(logs), max_lines)
+
+            # Check if test log message is present in the logs, at least once
+            log_exists = any((True for log in logs if test_log_message in log))
+            self.assertTrue(log_exists, "Test log not found in the debug log response")
+
+        # write 100 test logs which is used to test for its presence in the response
+        for log_index in xrange(100):
+            logging.error("%s [%d]", test_log_message, log_index)
+
+        self.should_check_equality = False
+        return self.do_request('debug/log?max_lines=%d' % max_lines, expected_code=200).addCallback(verify_log_exists)

Tribler/Test/GUI/test_gui.py

@@ -7,7 +7,7 @@
 from PyQt5.QtCore import QPoint, Qt, QTimer
 from PyQt5.QtGui import QPixmap, QRegion
 from PyQt5.QtTest import QTest
-from PyQt5.QtWidgets import QApplication, QListWidget, QTreeWidget
+from PyQt5.QtWidgets import QApplication, QListWidget, QTreeWidget, QTextEdit
 
 from Tribler.Core.Utilities.network_utils import get_random_port
 import TriblerGUI.core_manager as core_manager
@@ -164,6 +164,16 @@ def on_signal(_):
 
         raise TimeoutException("Signal %s not raised within 10 seconds" % signal)
 
+    def wait_for_qtext_edit_populated(self, qtext_edit, timeout=10):
+        for _ in range(0, timeout * 1000, 100):
+            QTest.qWait(100)
+            if not isinstance(qtext_edit, QTextEdit):
+                return
+            if qtext_edit.toPlainText():
+                return
+
+        # QTextEdit was not populated in time, fail the test
+        raise TimeoutException("QTextEdit was not populated within 10 seconds")
 
 @skipUnless(os.environ.get("TEST_GUI") == "yes", "Not testing the GUI by default")
 class TriblerGUITest(AbstractTriblerGUITest):
@@ -494,6 +504,16 @@ def test_debug_pane(self):
         self.wait_for_list_populated(window.debug_window.threads_tree_widget)
         self.screenshot(window.debug_window, name="debug_panel_threads_tab")
 
+        # Logs shown in ui and from the debug endpoint should be same
+        window.debug_window.debug_tab_widget.setCurrentIndex(6)
+        self.wait_for_qtext_edit_populated(window.debug_window.log_display_area)
+        # Logs shown in ui
+        gui_logs = window.debug_window.log_display_area.toPlainText().strip()
+        # logs from FakeTriblerApi
+        fake_logs = ''.join(["Sample log [%d]\n" % i for i in xrange(10)]).strip()
+        self.assertEqual(gui_logs, fake_logs, "Logs in GUI are different from actual logs")
+        self.screenshot(window.debug_window, name="debug_panel_logs")
+
         window.debug_window.system_tab_widget.setCurrentIndex(3)
         QTest.qWait(1000)
         self.screenshot(window.debug_window, name="debug_panel_cpu_tab")

TriblerGUI/debug_window.py

@@ -5,7 +5,8 @@
 import datetime
 import matplotlib
 from PyQt5.QtCore import QTimer
-from PyQt5.QtWidgets import QFileDialog
+from PyQt5.QtGui import QTextCursor
+from PyQt5.QtWidgets import QFileDialog, QTextEdit
 from PyQt5.QtWidgets import QSizePolicy
 from TriblerGUI.dialogs.confirmationdialog import ConfirmationDialog
 from meliae import scanner
@@ -138,6 +139,9 @@ def __init__(self, settings):
         if not settings['multichain']['enabled']:
             self.window().debug_tab_widget.setTabEnabled(2, False)
 
+        # Refresh logs
+        self.window().log_refresh_button.clicked.connect(lambda: self.load_logs_tab())
+
     def tab_changed(self, index):
         if index == 0:
             self.load_general_tab()
@@ -151,6 +155,8 @@ def tab_changed(self, index):
             self.load_events_tab()
         elif index == 5:
             self.system_tab_changed(self.window().system_tab_widget.currentIndex())
+        elif index == 6:
+            self.load_logs_tab()
 
     def dispersy_tab_changed(self, index):
         if index == 0:
@@ -422,3 +428,29 @@ def closeEvent(self, close_event):
 
         if self.memory_plot_timer:
             self.memory_plot_timer.stop()
+
+    def load_logs_tab(self):
+        # Max lines from GUI
+        max_log_lines = self.window().max_lines_value.text()
+        self.request_mgr = TriblerRequestManager()
+        self.request_mgr.perform_request("debug/log?max_lines=%s" % max_log_lines, self.display_logs)
+
+    def display_logs(self, data):
+        log_display_widget = self.window().log_display_area
+        log_display_widget.moveCursor(QTextCursor.End)
+
+        key_content = u'content'
+        key_max_lines = u'max_lines'
+
+        if not key_content in data or not data[key_content]:
+            log_display_widget.setPlainText('No logs found')
+        else:
+            log_display_widget.setPlainText(data[key_content])
+
+        if not key_max_lines in data or not data[key_max_lines]:
+            self.window().max_lines_value.setText('')
+        else:
+            self.window().max_lines_value.setText(str(data[key_max_lines]))
+
+        sb = log_display_widget.verticalScrollBar()
+        sb.setValue(sb.maximum())