From fd322ba3b62117d8509a67e467f6cbaf679f863b Mon Sep 17 00:00:00 2001 From: Alan Hamlett Date: Thu, 1 Sep 2016 11:49:12 +0200 Subject: [PATCH] improve traceback logging and non-utf8 handling --- tests/test_logging.py | 32 ++++++++++--- tests/test_main.py | 42 +++++++++++++++- wakatime/compat.py | 4 +- wakatime/dependencies/__init__.py | 3 +- wakatime/logger.py | 56 +++++++--------------- wakatime/main.py | 2 +- wakatime/offlinequeue.py | 6 +-- wakatime/projects/git.py | 4 +- wakatime/projects/mercurial.py | 4 +- wakatime/projects/wakatime_project_file.py | 4 +- wakatime/session_cache.py | 10 ++-- wakatime/stats.py | 2 +- 12 files changed, 101 insertions(+), 68 deletions(-) diff --git a/tests/test_logging.py b/tests/test_logging.py index b78fee8..1018f7d 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,8 +1,10 @@ # -*- coding: utf-8 -*- +from wakatime.compat import is_py3, u from wakatime.main import execute from wakatime.packages import requests +from wakatime.packages.requests.models import Response import logging import os @@ -10,8 +12,6 @@ import tempfile import time import sys from testfixtures import log_capture -from wakatime.compat import u -from wakatime.packages.requests.models import Response from . import utils @@ -139,9 +139,9 @@ class LoggingTestCase(utils.TestCase): self.assertEquals(sys.stdout.getvalue(), '') self.assertEquals(sys.stderr.getvalue(), '') - output = u("\n").join([u(' ').join(x) for x in logs.actual()]) - self.assertIn(u('WakaTime DEBUG Traceback (most recent call last):'), output) - self.assertIn(u('Exception: FooBar'), output) + log_output = u("\n").join([u(' ').join(x) for x in logs.actual()]) + self.assertIn(u('WakaTime DEBUG Traceback (most recent call last):'), log_output) + self.assertIn(u('Exception: FooBar'), log_output) @log_capture() def test_exception_traceback_not_logged_normally(self, logs): @@ -164,5 +164,23 @@ class LoggingTestCase(utils.TestCase): self.assertEquals(sys.stdout.getvalue(), '') self.assertEquals(sys.stderr.getvalue(), '') - output = u("\n").join([u(' ').join(x) for x in logs.actual()]) - self.assertEquals(u(''), output) + log_output = u("\n").join([u(' ').join(x) for x in logs.actual()]) + self.assertEquals(u(''), log_output) + + @log_capture() + def test_can_log_invalid_utf8(self, logs): + logging.disable(logging.NOTSET) + + data = bytes('\xab', 'utf-16') if is_py3 else '\xab' + + with self.assertRaises(UnicodeDecodeError): + data.decode('utf8') + + logger = logging.getLogger('WakaTime') + logger.error(data) + + found = False + for msg in list(logs.actual())[0]: + if u(msg) == u(data): + found = True + self.assertTrue(found) diff --git a/tests/test_main.py b/tests/test_main.py index 1a83733..c4144d0 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -867,8 +867,12 @@ class MainTestCase(utils.TestCase): shutil.copy(entity, os.path.join(tempdir, 'emptyfile.txt')) entity = os.path.realpath(os.path.join(tempdir, 'emptyfile.txt')) - timezone = tzlocal.get_localzone() - timezone.zone = 'tz汉语' if is_py3 else 'tz\xe6\xb1\x89\xe8\xaf\xad' + class TZ(object): + @property + def zone(self): + return 'tz汉语' if is_py3 else 'tz\xe6\xb1\x89\xe8\xaf\xad' + timezone = TZ() + with utils.mock.patch('wakatime.packages.tzlocal.get_localzone') as mock_getlocalzone: mock_getlocalzone.return_value = timezone @@ -887,6 +891,40 @@ class MainTestCase(utils.TestCase): headers = self.patched['wakatime.packages.requests.adapters.HTTPAdapter.send'].call_args[0][0].headers self.assertEquals(headers.get('TimeZone'), u(timezone.zone).encode('utf-8') if is_py3 else timezone.zone) + def test_timezone_with_invalid_encoding(self): + response = Response() + response.status_code = 201 + self.patched['wakatime.packages.requests.adapters.HTTPAdapter.send'].return_value = response + + with utils.TemporaryDirectory() as tempdir: + entity = 'tests/samples/codefiles/emptyfile.txt' + shutil.copy(entity, os.path.join(tempdir, 'emptyfile.txt')) + entity = os.path.realpath(os.path.join(tempdir, 'emptyfile.txt')) + + class TZ(object): + @property + def zone(self): + return bytes('\xab', 'utf-16') if is_py3 else '\xab' + timezone = TZ() + + with self.assertRaises(UnicodeDecodeError): + timezone.zone.decode('utf8') + + with utils.mock.patch('wakatime.packages.tzlocal.get_localzone') as mock_getlocalzone: + mock_getlocalzone.return_value = timezone + + config = 'tests/samples/configs/has_everything.cfg' + args = ['--file', entity, '--config', config, '--timeout', '15'] + retval = execute(args) + self.assertEquals(retval, SUCCESS) + + self.patched['wakatime.session_cache.SessionCache.get'].assert_called_once_with() + self.patched['wakatime.session_cache.SessionCache.delete'].assert_not_called() + self.patched['wakatime.session_cache.SessionCache.save'].assert_called_once_with(ANY) + + self.patched['wakatime.offlinequeue.Queue.push'].assert_not_called() + self.patched['wakatime.offlinequeue.Queue.pop'].assert_called_once_with() + def test_tzlocal_exception(self): response = Response() response.status_code = 201 diff --git a/wakatime/compat.py b/wakatime/compat.py index cbd3946..857609f 100644 --- a/wakatime/compat.py +++ b/wakatime/compat.py @@ -31,7 +31,7 @@ if is_py2: # pragma: nocover try: return unicode(text) except: - return text + return text.decode('utf-8', 'replace') open = codecs.open basestring = basestring @@ -52,7 +52,7 @@ elif is_py3: # pragma: nocover try: return str(text) except: - return text + return text.decode('utf-8', 'replace') open = open basestring = (str, bytes) diff --git a/wakatime/dependencies/__init__.py b/wakatime/dependencies/__init__.py index 7a1e972..261eba3 100644 --- a/wakatime/dependencies/__init__.py +++ b/wakatime/dependencies/__init__.py @@ -12,7 +12,6 @@ import logging import re import sys -import traceback from ..compat import u, open, import_module from ..exceptions import NotYetImplemented @@ -120,7 +119,7 @@ class DependencyParser(object): except AttributeError: log.debug('Module {0} is missing class {1}'.format(module.__name__, class_name)) except ImportError: - log.debug(traceback.format_exc()) + log.traceback(logging.DEBUG) def parse(self): if self.parser: diff --git a/wakatime/logger.py b/wakatime/logger.py index cdb12d4..5a5c195 100644 --- a/wakatime/logger.py +++ b/wakatime/logger.py @@ -25,23 +25,6 @@ except (ImportError, SyntaxError): # pragma: nocover import json -class CustomEncoder(json.JSONEncoder): - - def encode(self, obj): - try: - return super(CustomEncoder, self).encode(obj) - except UnicodeDecodeError: - obj = u(obj) - return super(CustomEncoder, self).encode(obj) - - def default(self, obj): - try: - return super(CustomEncoder, self).default(obj) - except TypeError: - obj = u(obj) - return super(CustomEncoder, self).default(obj) - - class JsonFormatter(logging.Formatter): def setup(self, timestamp, is_write, entity, version, plugin, verbose, @@ -58,33 +41,28 @@ class JsonFormatter(logging.Formatter): data = OrderedDict([ ('now', self.formatTime(record, self.datefmt)), ]) - data['version'] = self.version - data['plugin'] = self.plugin + data['version'] = u(self.version) + if self.plugin: + data['plugin'] = u(self.plugin) data['time'] = self.timestamp if self.verbose: - data['caller'] = record.pathname + data['caller'] = u(record.pathname) data['lineno'] = record.lineno - data['is_write'] = self.is_write - data['file'] = self.entity - if not self.is_write: - del data['is_write'] + if self.is_write: + data['is_write'] = self.is_write + data['file'] = u(self.entity) data['level'] = record.levelname - data['message'] = record.getMessage() if self.warnings else record.msg - if not self.plugin: - del data['plugin'] - return CustomEncoder().encode(data) + data['message'] = u(record.getMessage() if self.warnings else record.msg) + return json.dumps(data) + def traceback(self, lvl=None): + logger = logging.getLogger('WakaTime') + if not lvl: + lvl = logger.getEffectiveLevel() + logger.log(lvl, traceback.format_exc()) -def traceback_formatter(*args, **kwargs): - level = kwargs.get('level', args[0] if len(args) else None) - if level: - level = level.lower() - if level == 'warn' or level == 'warning': - logging.getLogger('WakaTime').warning(traceback.format_exc()) - elif level == 'debug': - logging.getLogger('WakaTime').debug(traceback.format_exc()) - else: - logging.getLogger('WakaTime').error(traceback.format_exc()) + def formatException(self, exc_info): + raise RuntimeError('Use traceback method instead.') def set_log_level(logger, args): @@ -117,7 +95,7 @@ def setup_logging(args, version): logger.addHandler(handler) # add custom traceback logging method - logger.traceback = traceback_formatter + logger.traceback = formatter.traceback warnings_formatter = JsonFormatter(datefmt='%Y/%m/%d %H:%M:%S %z') warnings_formatter.setup( diff --git a/wakatime/main.py b/wakatime/main.py index c0969b3..ac0eb81 100644 --- a/wakatime/main.py +++ b/wakatime/main.py @@ -545,6 +545,6 @@ def execute(argv=None): return retval except: - log.traceback() + log.traceback(logging.ERROR) print(traceback.format_exc()) return UNKNOWN_ERROR diff --git a/wakatime/offlinequeue.py b/wakatime/offlinequeue.py index dcf9b13..dddc0f2 100644 --- a/wakatime/offlinequeue.py +++ b/wakatime/offlinequeue.py @@ -80,7 +80,7 @@ class Queue(object): try: conn, c = self.connect() except sqlite3.Error: - log.traceback('debug') + log.traceback(logging.DEBUG) return None loop = True while loop and tries > -1: @@ -118,11 +118,11 @@ class Queue(object): } loop = False except sqlite3.Error: # pragma: nocover - log.traceback('debug') + log.traceback(logging.DEBUG) sleep(wait) tries -= 1 try: conn.close() except sqlite3.Error: # pragma: nocover - log.traceback('debug') + log.traceback(logging.DEBUG) return heartbeat diff --git a/wakatime/projects/git.py b/wakatime/projects/git.py index e42b702..7263a4c 100644 --- a/wakatime/projects/git.py +++ b/wakatime/projects/git.py @@ -44,9 +44,9 @@ class Git(BaseProject): with open(head, 'r', encoding=sys.getfilesystemencoding()) as fh: return self._get_branch_from_head_file(fh.readline()) except: - log.traceback('warn') + log.traceback(logging.WARNING) except IOError: # pragma: nocover - log.traceback('warn') + log.traceback(logging.WARNING) return u('master') def _project_base(self): diff --git a/wakatime/projects/mercurial.py b/wakatime/projects/mercurial.py index 4369ddb..2a77489 100644 --- a/wakatime/projects/mercurial.py +++ b/wakatime/projects/mercurial.py @@ -42,9 +42,9 @@ class Mercurial(BaseProject): with open(branch_file, 'r', encoding=sys.getfilesystemencoding()) as fh: return u(fh.readline().strip().rsplit('/', 1)[-1]) except: - log.traceback('warn') + log.traceback(logging.WARNING) except IOError: # pragma: nocover - log.traceback('warn') + log.traceback(logging.WARNING) return u('default') def _find_hg_config_dir(self, path): diff --git a/wakatime/projects/wakatime_project_file.py b/wakatime/projects/wakatime_project_file.py index 8ec4ccf..770861c 100644 --- a/wakatime/projects/wakatime_project_file.py +++ b/wakatime/projects/wakatime_project_file.py @@ -41,9 +41,9 @@ class WakaTimeProjectFile(BaseProject): self._project_name = u(fh.readline().strip()) self._project_branch = u(fh.readline().strip()) except: - log.traceback('warn') + log.traceback(logging.WARNING) except IOError: # pragma: nocover - log.traceback('warn') + log.traceback(logging.WARNING) return True return False diff --git a/wakatime/session_cache.py b/wakatime/session_cache.py index e20beae..a958825 100644 --- a/wakatime/session_cache.py +++ b/wakatime/session_cache.py @@ -57,7 +57,7 @@ class SessionCache(object): conn.commit() conn.close() except: # pragma: nocover - log.traceback('debug') + log.traceback(logging.DEBUG) def get(self): @@ -72,7 +72,7 @@ class SessionCache(object): try: conn, c = self.connect() except: - log.traceback('debug') + log.traceback(logging.DEBUG) return requests.session() session = None @@ -83,12 +83,12 @@ class SessionCache(object): if row is not None: session = pickle.loads(row[0]) except: # pragma: nocover - log.traceback('debug') + log.traceback(logging.DEBUG) try: conn.close() except: # pragma: nocover - log.traceback('debug') + log.traceback(logging.DEBUG) return session if session is not None else requests.session() @@ -105,4 +105,4 @@ class SessionCache(object): conn.commit() conn.close() except: - log.traceback('debug') + log.traceback(logging.DEBUG) diff --git a/wakatime/stats.py b/wakatime/stats.py index af5069f..4448f2d 100644 --- a/wakatime/stats.py +++ b/wakatime/stats.py @@ -236,5 +236,5 @@ def get_file_head(file_name): with open(file_name, 'r', encoding=sys.getfilesystemencoding()) as fh: text = fh.read(512000) # pragma: nocover except: - log.traceback('debug') + log.traceback(logging.DEBUG) return text