-
-
Notifications
You must be signed in to change notification settings - Fork 627
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
create singleton ExceptionSink object to centralize logging of fatal errors #6533
Changes from all commits
a15c240
ec29017
c562a49
9ecf77a
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,88 @@ | ||
# coding=utf-8 | ||
# Copyright 2018 Pants project contributors (see CONTRIBUTORS.md). | ||
# Licensed under the Apache License, Version 2.0 (see LICENSE). | ||
|
||
from __future__ import absolute_import, division, print_function, unicode_literals | ||
|
||
import datetime | ||
import logging | ||
import os | ||
import sys | ||
from builtins import object | ||
|
||
from pants.util.dirutil import is_writable_dir, safe_open | ||
|
||
|
||
logger = logging.getLogger(__name__) | ||
|
||
|
||
class ExceptionSink(object): | ||
"""A mutable singleton object representing where exceptions should be logged to.""" | ||
|
||
_destination = os.getcwd() | ||
|
||
def __new__(cls, *args, **kwargs): | ||
raise TypeError('Instances of {} are not allowed to be constructed!' | ||
.format(cls.__name__)) | ||
|
||
class ExceptionSinkError(Exception): pass | ||
|
||
@classmethod | ||
def set_destination(cls, dir_path): | ||
if not is_writable_dir(dir_path): | ||
# TODO: when this class sets up excepthooks, raising this should be safe, because we always | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This could just be a note. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I can see you've removed it in #6539, sounds great. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. If you need any of this in your next PR, let me know and I can backport it. Or feel free to just cherry-pick to your branch. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Alternatively, I could land #6539 with the test marked There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I'll cherry-pick whatever I need, I was thinking -- the changes are mostly orthogonal to what I have now. Landing with it marked xfail is a-ok to me as long as the changes don't break other tests (wouldn't think so). |
||
# have a destination to log to (os.getcwd() if not otherwise set). | ||
raise cls.ExceptionSinkError( | ||
"The provided exception sink path at '{}' is not a writable directory." | ||
.format(dir_path)) | ||
cls._destination = dir_path | ||
|
||
@classmethod | ||
def get_destination(cls): | ||
return cls._destination | ||
|
||
@classmethod | ||
def _exceptions_log_path(cls, for_pid=None): | ||
intermediate_filename_component = '.{}'.format(for_pid) if for_pid else '' | ||
return os.path.join( | ||
cls.get_destination(), | ||
'logs', | ||
'exceptions{}.log'.format(intermediate_filename_component)) | ||
|
||
@classmethod | ||
def _iso_timestamp_for_now(cls): | ||
return datetime.datetime.now().isoformat() | ||
|
||
# NB: This includes a trailing newline, but no leading newline. | ||
_EXCEPTION_LOG_FORMAT = """\ | ||
timestamp: {timestamp} | ||
args: {args} | ||
pid: {pid} | ||
{message} | ||
""" | ||
|
||
@classmethod | ||
def _format_exception_message(cls, msg, pid): | ||
return cls._EXCEPTION_LOG_FORMAT.format( | ||
timestamp=cls._iso_timestamp_for_now(), | ||
args=sys.argv, | ||
pid=pid, | ||
message=msg, | ||
) | ||
|
||
@classmethod | ||
def log_exception(cls, msg): | ||
try: | ||
pid = os.getpid() | ||
fatal_error_log_entry = cls._format_exception_message(msg, pid) | ||
# We care more about this log than the shared log, so completely write to it first. This | ||
# avoids any errors with concurrent modification of the shared log affecting the per-pid log. | ||
with safe_open(cls._exceptions_log_path(for_pid=pid), 'a') as pid_error_log: | ||
pid_error_log.write(fatal_error_log_entry) | ||
# TODO: we should probably guard this against concurrent modification somehow. | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think that because this is a single There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The implication from a few minutes of searching is that people have lots of ways to create a file atomically, but appending atomically is a less common use case. I might check the CPython source for fun later. My first question would be: if I open a file to append with mode |
||
with safe_open(cls._exceptions_log_path(), 'a') as shared_error_log: | ||
shared_error_log.write(fatal_error_log_entry) | ||
except Exception as e: | ||
# TODO: If there is an error in writing to the exceptions log, we may want to consider trying | ||
# to write to another location (e.g. the cwd, if that is not already the destination). | ||
logger.error('Problem logging original exception: {}'.format(e)) |
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,87 @@ | ||
# coding=utf-8 | ||
# Copyright 2018 Pants project contributors (see CONTRIBUTORS.md). | ||
# Licensed under the Apache License, Version 2.0 (see LICENSE). | ||
|
||
from __future__ import absolute_import, division, print_function, unicode_literals | ||
|
||
import logging | ||
import os | ||
import re | ||
from builtins import open, str | ||
|
||
from pants.base.exception_sink import ExceptionSink | ||
from pants.util.collections import assert_single_element | ||
from pants.util.contextutil import temporary_dir | ||
from pants.util.dirutil import touch | ||
from pants_test.test_base import TestBase | ||
|
||
|
||
class TestExceptionSink(TestBase): | ||
|
||
def _gen_sink_subclass(self): | ||
# Avoid modifying global state by generating a subclass. | ||
class AnonymousSink(ExceptionSink): pass | ||
return AnonymousSink | ||
|
||
def test_unset_destination(self): | ||
self.assertEqual(os.getcwd(), self._gen_sink_subclass().get_destination()) | ||
|
||
def test_set_invalid_destination(self): | ||
sink = self._gen_sink_subclass() | ||
err_rx = re.escape( | ||
"The provided exception sink path at '/does/not/exist' is not a writable directory.") | ||
with self.assertRaisesRegexp(ExceptionSink.ExceptionSinkError, err_rx): | ||
sink.set_destination('/does/not/exist') | ||
err_rx = re.escape( | ||
"The provided exception sink path at '/' is not a writable directory.") | ||
with self.assertRaisesRegexp(ExceptionSink.ExceptionSinkError, err_rx): | ||
sink.set_destination('/') | ||
|
||
def test_retrieve_destination(self): | ||
sink = self._gen_sink_subclass() | ||
|
||
with temporary_dir() as tmpdir: | ||
sink.set_destination(tmpdir) | ||
self.assertEqual(tmpdir, sink.get_destination()) | ||
|
||
def test_log_exception(self): | ||
sink = self._gen_sink_subclass() | ||
pid = os.getpid() | ||
with temporary_dir() as tmpdir: | ||
# Check that tmpdir exists, and log an exception into that directory. | ||
sink.set_destination(tmpdir) | ||
sink.log_exception('XXX') | ||
# This should have created two log files, one specific to the current pid. | ||
self.assertEqual(os.listdir(tmpdir), ['logs']) | ||
cur_process_error_log_path = os.path.join(tmpdir, 'logs', 'exceptions.{}.log'.format(pid)) | ||
self.assertTrue(os.path.isfile(cur_process_error_log_path)) | ||
shared_error_log_path = os.path.join(tmpdir, 'logs', 'exceptions.log') | ||
self.assertTrue(os.path.isfile(shared_error_log_path)) | ||
# We only logged a single error, so the files should both contain only that single log entry. | ||
err_rx = """\ | ||
timestamp: ([^\n]+) | ||
args: ([^\n]+) | ||
pid: {pid} | ||
XXX | ||
""".format(pid=re.escape(str(pid))) | ||
with open(cur_process_error_log_path, 'r') as cur_pid_file: | ||
self.assertRegexpMatches(cur_pid_file.read(), err_rx) | ||
with open(shared_error_log_path, 'r') as shared_log_file: | ||
self.assertRegexpMatches(shared_log_file.read(), err_rx) | ||
|
||
def test_backup_logging_on_fatal_error(self): | ||
sink = self._gen_sink_subclass() | ||
with self.captured_logging(level=logging.ERROR) as captured: | ||
with temporary_dir() as tmpdir: | ||
exc_log_path = os.path.join(tmpdir, 'logs', 'exceptions.log') | ||
touch(exc_log_path) | ||
# Make the exception log file unreadable. | ||
os.chmod(exc_log_path, 0) | ||
sink.set_destination(tmpdir) | ||
sink.log_exception('XXX') | ||
single_error_logged = str(assert_single_element(captured.errors())) | ||
expected_rx_str = ( | ||
re.escape("pants.base.exception_sink: Problem logging original exception: [Errno 13] Permission denied: '") + | ||
'.*' + | ||
re.escape("/logs/exceptions.log'")) | ||
self.assertRegexpMatches(single_error_logged, expected_rx_str) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Should probably explain why we do this ("blah blah increase the chances that if an exception occurs early in initialization we still record it somewhere").
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Absolutely agree, this is highly mysterious as is.