Merge pull request #7616 from kozlovsky/fix/on_tracker_reply_alert_un…

…icode_decode_error

Fixes #7598: Use safe_repr function to display alert reprs; catch UnicodeDecodeError in all alert handlers

src/tribler/core/components/libtorrent/download_manager/download.py

@@ -29,7 +29,7 @@
 from tribler.core.utilities.path_util import Path
 from tribler.core.utilities.simpledefs import DOWNLOAD, DownloadStatus
 from tribler.core.utilities.unicode import ensure_unicode, hexlify
-from tribler.core.utilities.utilities import bdecode_compat
+from tribler.core.utilities.utilities import bdecode_compat, safe_repr
 
 
 class Download(TaskManager):
@@ -184,7 +184,7 @@ def get_atp(self) -> Dict:
         return atp
 
     def on_add_torrent_alert(self, alert: lt.add_torrent_alert):
-        self._logger.info(f'On add torrent alert: {alert}')
+        self._logger.info(f'On add torrent alert: {safe_repr(alert)}')
 
         if hasattr(alert, 'error') and alert.error.value():
             self._logger.error("Failed to add torrent (%s)", self.tdef.get_name_as_unicode())
@@ -241,23 +241,27 @@ def post_alert(self, alert_type: str, alert_dict: Optional[Dict] = None):
     def process_alert(self, alert: lt.torrent_alert, alert_type: str):
         try:
             if alert.category() in [lt.alert.category_t.error_notification, lt.alert.category_t.performance_warning]:
-                self._logger.debug("Got alert: %s", alert)
+                self._logger.debug(f"Got alert: {safe_repr(alert)}")
 
             for handler in self.alert_handlers.get(alert_type, []):
-                handler(alert)
+                try:
+                    handler(alert)
+                except UnicodeDecodeError as e:
+                    self._logger.warning(f"UnicodeDecodeError in {handler.__name__}: {e}")
 
             for future, future_setter, getter in self.futures.pop(alert_type, []):
                 if not future.done():
                     future_setter(getter(alert) if getter else alert)
         except Exception as e:
-            self._logger.exception(f'Failed process alert: {e}')
+            self._logger.exception(f'process_alert failed with {e.__class__.__name__}: {e} '
+                                   f'for alert {safe_repr(alert)}')
             raise NoCrashException from e
 
     def on_torrent_error_alert(self, alert: lt.torrent_error_alert):
-        self._logger.error(f'On torrent error alert: {alert}')
+        self._logger.error(f'On torrent error alert: {safe_repr(alert)}')
 
     def on_state_changed_alert(self, alert: lt.state_changed_alert):
-        self._logger.info(f'On state changed alert: {alert}')
+        self._logger.info(f'On state changed alert: {safe_repr(alert)}')
 
         if not self.handle:
             return
@@ -276,7 +280,7 @@ def on_save_resume_data_alert(self, alert: lt.save_resume_data_alert):
         Callback for the alert that contains the resume data of a specific download.
         This resume data will be written to a file on disk.
         """
-        self._logger.debug('On save resume data alert: %s', alert)
+        self._logger.debug(f'On save resume data alert: {safe_repr(alert)}')
         if self.checkpoint_disabled:
             return
 
@@ -307,7 +311,7 @@ def on_save_resume_data_alert(self, alert: lt.save_resume_data_alert):
             self._logger.debug(f'Resume data has been saved to: {filename}')
 
     def on_tracker_reply_alert(self, alert: lt.tracker_reply_alert):
-        self._logger.info(f'On tracker reply alert: {alert}')
+        self._logger.info(f'On tracker reply alert: {safe_repr(alert)}')
 
         self.tracker_status[alert.url] = [alert.num_peers, 'Working']
 
@@ -318,26 +322,23 @@ def on_tracker_error_alert(self, alert: lt.tracker_error_alert):
         """
         # The try-except block is added as a workaround to suppress UnicodeDecodeError in `repr(alert)`,
         # `alert.url` and `alert.msg`. See https://github.com/arvidn/libtorrent/issues/143
-        try:
-            self._logger.error(f'On tracker error alert: {alert}')
-            url = alert.url
-
-            if alert.msg:
-                status = 'Error: ' + alert.msg
-            elif alert.status_code > 0:
-                status = 'HTTP status code %d' % alert.status_code
-            elif alert.status_code == 0:
-                status = 'Timeout'
-            else:
-                status = 'Not working'
+        self._logger.error(f'On tracker error alert: {safe_repr(alert)}')
+        url = alert.url
+
+        if alert.msg:
+            status = 'Error: ' + alert.msg
+        elif alert.status_code > 0:
+            status = 'HTTP status code %d' % alert.status_code
+        elif alert.status_code == 0:
+            status = 'Timeout'
+        else:
+            status = 'Not working'
 
-            peers = 0  # If there is a tracker error, alert.num_peers is not available. So resetting peer count to zero.
-            self.tracker_status[url] = [peers, status]
-        except UnicodeDecodeError as e:
-            self._logger.warning(f'UnicodeDecodeError in on_tracker_error_alert: {e}')
+        peers = 0  # If there is a tracker error, alert.num_peers is not available. So resetting peer count to zero.
+        self.tracker_status[url] = [peers, status]
 
     def on_tracker_warning_alert(self, alert: lt.tracker_warning_alert):
-        self._logger.warning(f'On tracker warning alert: {alert}')
+        self._logger.warning(f'On tracker warning alert: {safe_repr(alert)}')
 
         peers = self.tracker_status[alert.url][0] if alert.url in self.tracker_status else 0
         status = 'Warning: ' + str(alert.message())
@@ -346,7 +347,7 @@ def on_tracker_warning_alert(self, alert: lt.tracker_warning_alert):
 
     @check_handle()
     def on_metadata_received_alert(self, alert: lt.metadata_received_alert):
-        self._logger.info(f'On metadata received alert: {alert}')
+        self._logger.info(f'On metadata received alert: {safe_repr(alert)}')
 
         torrent_info = get_info_from_handle(self.handle)
         if not torrent_info:
@@ -382,7 +383,7 @@ def on_metadata_received_alert(self, alert: lt.metadata_received_alert):
         self.checkpoint()
 
     def on_performance_alert(self, alert: lt.performance_alert):
-        self._logger.info(f'On performance alert: {alert}')
+        self._logger.info(f'On performance alert: {safe_repr(alert)}')
 
         if self.get_anon_mode() or self.download_manager.ltsessions is None:
             return
@@ -405,13 +406,13 @@ def on_performance_alert(self, alert: lt.performance_alert):
                 self.download_manager.set_session_settings(self.download_manager.get_session(), settings)
 
     def on_torrent_removed_alert(self, alert: lt.torrent_removed_alert):
-        self._logger.info(f'On torrent remove alert: {alert}')
+        self._logger.info(f'On torrent remove alert: {safe_repr(alert)}')
 
         self._logger.debug("Removing %s", self.tdef.get_name())
         self.handle = None
 
     def on_torrent_checked_alert(self, alert: lt.torrent_checked_alert):
-        self._logger.info(f'On torrent checked alert: {alert}')
+        self._logger.info(f'On torrent checked alert: {safe_repr(alert)}')
 
         if self.pause_after_next_hashcheck:
             self.pause_after_next_hashcheck = False
@@ -422,7 +423,7 @@ def on_torrent_checked_alert(self, alert: lt.torrent_checked_alert):
 
     @check_handle()
     def on_torrent_finished_alert(self, alert: lt.torrent_finished_alert):
-        self._logger.info(f'On torrent finished alert: {alert}')
+        self._logger.info(f'On torrent finished alert: {safe_repr(alert)}')
         self.update_lt_status(self.handle.status())
         self.checkpoint()
         downloaded = self.get_state().get_total_transferred(DOWNLOAD)

src/tribler/core/components/libtorrent/tests/test_download.py

@@ -1,6 +1,6 @@
 from asyncio import Future, sleep
 from pathlib import Path
-from unittest.mock import MagicMock, Mock, patch
+from unittest.mock import MagicMock, Mock, PropertyMock, patch
 
 import libtorrent as lt
 import pytest
@@ -240,11 +240,59 @@ def test_process_error_alert(test_download):
 
 
 def test_tracker_error_alert_unicode_decode_error(test_download: Download, caplog: LogCaptureFixture):
-    exception = UnicodeDecodeError('utf-8', b'\xc3\x28', 0, 1, 'invalid continuation byte')
-    mock_alert = MagicMock(__repr__=Mock(side_effect=exception))
+    # This exception in alert.__repr__() should be handled by the safe_repr() function
+    exception1 = UnicodeDecodeError('utf-8', b'\xc3\x28', 0, 1, 'invalid continuation byte (exception in __repr__)')
+
+    # Another exception in alert.url should be handled by the Download.process_alert() code
+    exception2 = UnicodeDecodeError('utf-8', b'\xc3\x28', 0, 1, 'invalid continuation byte (exception in .url)')
+
+    mock_alert = MagicMock(__repr__=Mock(side_effect=exception1))
+    type(mock_alert).url=PropertyMock(side_effect=exception2)
+
     test_download.process_alert(mock_alert, 'tracker_error_alert')
-    assert caplog.messages == ["UnicodeDecodeError in on_tracker_error_alert: "
-                               "'utf-8' codec can't decode byte 0xc3 in position 0: invalid continuation byte"]
+
+    mock_expected_safe_repr = (f"<Repr of {object.__repr__(mock_alert)} raises UnicodeDecodeError: "
+                               "'utf-8' codec can't decode byte 0xc3 in position 0: invalid continuation byte "
+                               "(exception in __repr__)>")
+
+    assert len(caplog.messages) == 2
+
+    # The first exception in self._logger.error(f'On tracker error alert: {safe_repr(alert)}')
+    # is converted to the following warning message:
+    assert caplog.messages[0] == f'On tracker error alert: {mock_expected_safe_repr}'
+
+    # The second exception in alert.url is converted to the following error message:
+    assert caplog.messages[1] == ("UnicodeDecodeError in on_tracker_error_alert: "
+                                  "'utf-8' codec can't decode byte 0xc3 in position 0: invalid continuation byte "
+                                  "(exception in .url)")
+
+
+def test_tracker_error_alert_has_msg(test_download: Download):
+    alert = MagicMock(__repr__=Mock(return_value='<ALERT_REPR>'), url='<ALERT_URL>', msg='<ALERT_MSG>')
+    assert alert.url not in test_download.tracker_status
+    test_download.on_tracker_error_alert(alert)
+    assert test_download.tracker_status[alert.url] == [0, 'Error: <ALERT_MSG>']
+
+
+def test_tracker_error_alert_has_positive_status_code(test_download: Download):
+    alert = MagicMock(__repr__=Mock(return_value='<ALERT_REPR>'), url='<ALERT_URL>', msg=None, status_code=123)
+    assert alert.url not in test_download.tracker_status
+    test_download.on_tracker_error_alert(alert)
+    assert test_download.tracker_status[alert.url] == [0, 'HTTP status code 123']
+
+
+def test_tracker_error_alert_has_status_code_zero(test_download: Download):
+    alert = MagicMock(__repr__=Mock(return_value='<ALERT_REPR>'), url='<ALERT_URL>', msg=None, status_code=0)
+    assert alert.url not in test_download.tracker_status
+    test_download.on_tracker_error_alert(alert)
+    assert test_download.tracker_status[alert.url] == [0, 'Timeout']
+
+
+def test_tracker_error_alert_has_negative_status_code(test_download: Download):
+    alert = MagicMock(__repr__=Mock(return_value='<ALERT_REPR>'), url='<ALERT_URL>', msg=None, status_code=-1)
+    assert alert.url not in test_download.tracker_status
+    test_download.on_tracker_error_alert(alert)
+    assert test_download.tracker_status[alert.url] == [0, 'Not working']
 
 
 def test_tracker_warning_alert(test_download):

src/tribler/core/utilities/tests/test_utilities.py

@@ -11,7 +11,7 @@
 from tribler.core.utilities.utilities import (Query, extract_tags, get_normally_distributed_number_with_zero_mean,
                                               get_normally_distributed_positive_integers, is_channel_public_key,
                                               is_infohash, is_simple_match_query, is_valid_url, parse_magnetlink,
-                                              parse_query, random_infohash, show_system_popup, to_fts_query)
+                                              parse_query, random_infohash, safe_repr, show_system_popup, to_fts_query)
 
 
 # pylint: disable=import-outside-toplevel, import-error
@@ -330,3 +330,18 @@ def test_get_normally_distributed_positive_integers():
 
     with pytest.raises(ValueError):
         _ = get_normally_distributed_positive_integers(size=11, upper_limit=10)
+
+
+def test_safe_repr_successful():
+    obj = [1, 2, 3]
+    result = safe_repr(obj)
+    assert result == repr(obj)
+
+
+def test_safe_repr_exception():
+    class MyException(Exception):
+        pass
+
+    obj = MagicMock(__repr__=Mock(side_effect=MyException("exception text")))
+    result = safe_repr(obj)
+    assert result == f'<Repr of {object.__repr__(obj)} raises MyException: exception text>'

src/tribler/core/utilities/utilities.py

@@ -336,3 +336,10 @@ def fragile_exception_handler(_, context):
         os._exit(1)  # pylint: disable=protected-access
 
     loop.set_exception_handler(fragile_exception_handler)
+
+
+def safe_repr(obj):
+    try:
+        return repr(obj)
+    except Exception as e:  # pylint: disable=broad-except
+        return f'<Repr of {object.__repr__(obj)} raises {e.__class__.__name__}: {e}>'