excepthandler.py

# -*- coding: utf-8 -*-
"""
This module defines a context in which we can run actions that are likely to
fail because they have intricate dependencies e.g. network connections,
file access, parsing certificates and validating their chains, etc., without
stopping execution of the application. Additionally it will log these errors
and depending on the nature of the error reschedule the task at a time that
seems reasonable, i.e.: we can reasonably expect the issue to be resolved by
that time.

It is generally considered bad practice to catch all remaining exceptions,
however this is a daemon. We can't afford it to get stuck or crashed. So in the
interest of staying alive, if an exception is not caught specifically, the
handler will catch it, generate a stack trace and save if in a file in the
current working directory. A log entry will be created explaining that there
was an exception, inform about the location of the stack trace dump and that
the context will be dropped. It will also kindly request the administrator to
contact the developers so the exception can be caught in a future release which
will probably increase stability and might result in a retry rather than just
dropping the context.

Dropping the context effectively means that a retry won't occur and since the
context will have no more references, it will be garbage collected.
There is however still a reference to the certificate model in
:attr:`core.daemon.run.models`. With no scheduled actions it will
just sit idle, until the finder detects that it is either removed – which will
cause the entry in :attr:`core.daemon.run.models` to be deleted, or
it is changed. If the certificate file is changed the finder will schedule
schedule a parsing action for it and it will be picked up again. Hopefully the
issue that caused the uncaught exception will be resolved, if not, if will be
caught again and the cycle continues.
"""

from contextlib import contextmanager
import datetime
import logging
import os
import errno
import traceback
from stapled.core.exceptions import OCSPBadResponse
from stapled.core.exceptions import RenewalRequirementMissing
from stapled.core.exceptions import CertFileAccessError
from stapled.core.exceptions import CertParsingError
from stapled.core.exceptions import CertValidationError
from stapled.core.exceptions import StapleAdderBadResponse
from stapled.core.exceptions import SocketError
from urllib.error import URLError

LOG = logging.getLogger(__name__)

#: This is a global variable that is overridden by stapled.__main__ with
#: the command line argument: ``--logdir``
LOG_DIR = "/var/log/stapled/"

STACK_TRACE_FILENAME = "stapled_exception{:%Y%m%d-%H%M%s%f}.trace"


@contextmanager
def stapled_except_handle(ctx=None):
    """
    Handle lots of potential errors and reschedule failed action contexts.
    """
    # pylint: disable=too-many-branches,too-many-statements
    try:
        yield  # do the "with stapled_except_handle(ctx):" code block
    except (CertFileAccessError, StapleAdderBadResponse) as exc:
        # Can't access the certificate file or the response from HAPRoxy was
        # not "OCSP Response updated", we can try again a bit later..
        err_count = ctx.set_last_exception(str(exc))
        if err_count < 4:
            LOG.error(exc)
            ctx.reschedule(60 * err_count)  # every err_count minutes
        elif err_count < 7:
            LOG.error(exc)
            ctx.reschedule(3600)  # every hour
        else:
            LOG.critical("%s, giving up..", exc)
    except (SocketError, BrokenPipeError) as exc:
        # This is a fatal exception that can occur during initialisation of a
        # StapleAdder or when an StapleAdder uses a socket that consistently has a
        # broken pipe
        LOG.critical(exc)
    except (RenewalRequirementMissing,
            CertValidationError,
            CertParsingError) as exc:
        # Can't parse or validate the certificate file, or a requirement for
        # OCSP renewal is missing.
        # We can't do anything until the certificate file is changed which
        # means we should not reschedule, when the certificate file changes,
        # the certfinder will add it to the parsing queue anyway..
        if isinstance(exc, CertValidationError):
            # If the certificate validation failed, we probably better not
            # serve the staple because it may make the server unavailable,
            # while not serving it only makes things slightly slower.
            delete_ocsp_for_context(ctx)
        if isinstance(exc, CertParsingError):
            if exc.log_level:
                LOG.log(exc.log_level, exc)
            else:
                LOG.critical(exc)
        else:
            LOG.critical(exc)
    except OCSPBadResponse as exc:
        # The OCSP response is empty, invalid or the status is not "good", we
        # can try again, maybe there's server side problem.
        err_count = ctx.set_last_exception(str(exc))
        if err_count < 4:
            LOG.error(exc)
            ctx.reschedule(60 * err_count)  # every err_count minutes
        elif err_count < 7:
            LOG.error(exc)
            ctx.reschedule(3600)  # every hour
        else:
            LOG.critical(exc)
            ctx.reschedule(43200)  # twice a day
    except (URLError) as exc:
        LOG.error(
            "Can't open URL: %s, reason: %s",
            ctx.model.ocsp_urls[ctx.model.url_index],
            exc.reason
        )

        # Iterate over the available OCSP URLs while rescheduling
        len_ocsp_urls = len(ctx.model.ocsp_urls)
        ctx.model.url_index += 1
        if ctx.model.url_index >= len_ocsp_urls:
            ctx.model.url_index = 0

        # Reschedule every 10 seconds (3x), then every hour (3x),
        # then twice a day, *per* URL so if we have 3 urls we will run:
        #  - every 10 seconds (9x), 3 per url
        #  - every hour (9x), 3 per url
        #  - twice a day per url
        err_count = ctx.set_last_exception(str(exc))
        if err_count < (3 * len_ocsp_urls) + 1:
            ctx.reschedule(10)  # every err_count minutes
        elif err_count < (6 * len_ocsp_urls) + 1:
            ctx.reschedule(3600)  # every hour
        else:
            ctx.reschedule(43200 // len_ocsp_urls)  # twice a day per url
        LOG.debug(
            "This exception %d in a row, context.model.ocsp_urls has %d "
            "entries",
            err_count, len_ocsp_urls
        )
    except (IOError, OSError) as exc:
        LOG.critical(handle_file_error(exc))


    # the show must go on..
    except Exception as exc:  # pylint: disable=broad-except
        dump_stack_trace(ctx, exc)

def handle_file_error(exc):
    """
    Wrapper for handling IOError and OSError logging..

    Can't use FileNotFoundError and PermissionError because they don't exist in
    Python 2.7.x yet. This won't be required after we remove Python 2.7.x
    support.
    :param Exception exc: OSError or IOError to handle logging for.
    :return str: Reason for OSError/IOError.
    """
    if exc.errno == errno.EPERM or exc.errno == errno.EACCES:
        reason = "Permission error"
    elif exc.errno == errno.ENOENT:
        reason = "File not found error"
    elif isinstance(exc, IOError):
        reason = "I/O Error"
    else:
        reason = "OS Error"
    return "{}: {}".format(reason, str(exc))


def delete_ocsp_for_context(ctx):
    """
    When something bad happens, sometimes it is good to delete a related bad
    OCSP file so it can't be served any more.

    .. TODO:: Check that HAProxy doesn't cache this, it probably does, we need
        to be able to tell it not to remember it.
    """
    LOG.info("Zero-ing any OCSP staple: \"%s.ocsp\" if it exists.", ctx.model)
    try:
        ocsp_file = "{}.ocsp".format(ctx.model.filename)
        with open(ocsp_file, 'w') as ocsp_file_obj:
            ocsp_file_obj.write("")
    except (IOError, OSError) as exc:
        LOG.debug(
            "Can't replace OCSP staple \"%s\" by an empty stub, reason: %s",
            ocsp_file,
            handle_file_error(exc)
        )


def dump_stack_trace(ctx, exc):
    """
    Examine the last exception and dump a stack trace to a file, if it fails
    due to an IOError or OSError, log that it failed so the a sysadmin
    may make the directory writeable.
    """
    trace_file = STACK_TRACE_FILENAME.format(datetime.datetime.now())
    trace_file = os.path.join(LOG_DIR, trace_file)
    try:
        with open(trace_file, "w") as file_handle:
            traceback.print_exc(file=file_handle)
        LOG.critical(
            "Prevented thread from being killed by uncaught exception: %s\n"
            "Context %s will be dropped as a result of the exception.\n"
            "A stack trace has been saved in %s\n"
            "Please report this error to the developers so the exception can "
            "be handled in a future release, thank you!",
            exc,
            ctx,
            trace_file
        )
    except (IOError, OSError) as trace_exc:
        LOG.critical(
            "Prevented thread from being killed by uncaught exception: %s\n"
            "Context %s will be dropped as a result of the exception.\n"
            "Couldn't dump stack trace to: %s reason: %s\n"
            "Please report this error to the developers so the exception can "
            "be handled in a future release, thank you!",
            exc,
            ctx,
            trace_file,
            trace_exc
        )