OperationalLogger.py 14.6 KB
Newer Older
1
#!/usr/bin/env python
Trevor Cappallo's avatar
Trevor Cappallo committed
2

3 4 5 6 7
"""Utilities to provide logging and email notification for an operational product."""

import sys
import os
import logging
8
import logging.handlers
9
import itertools
Trevor Cappallo's avatar
Trevor Cappallo committed
10 11 12 13 14
import subprocess
import socket
import atexit
import datetime
import StringIO
15
import inspect
Trevor Cappallo's avatar
Trevor Cappallo committed
16
import json
17
import traceback
Trevor Cappallo's avatar
Trevor Cappallo committed
18

19 20 21
import OperationalMail


Trevor Cappallo's avatar
Trevor Cappallo committed
22
def __exit_handler(logger, notify):
23
    """Email given addresses if there are any buffered errors."""
Trevor Cappallo's avatar
Trevor Cappallo committed
24 25 26
    for level in 'ERROR', 'CRITICAL':
        if level not in notify:
            notify[level] = []
27

Trevor Cappallo's avatar
Trevor Cappallo committed
28
    # add the last uncaught exception that has occurred as an error, if present
29 30
    try:
        tb_lines = traceback.format_exception(sys.last_type, sys.last_value, sys.last_traceback)
Trevor Cappallo's avatar
tweak  
Trevor Cappallo committed
31
        tb_str = '\n'.join([line.strip() for line in tb_lines])
Trevor Cappallo's avatar
Trevor Cappallo committed
32
        logging.critical("Uncaught exception detected! Traceback follows:\n%s", tb_str)
33
    except AttributeError:
Trevor Cappallo's avatar
Trevor Cappallo committed
34
        pass
35

Trevor Cappallo's avatar
Trevor Cappallo committed
36 37 38 39
    if logger.has_errors():
        addresses = notify['ERROR']
        if logger.has_critical():
            addresses = addresses.extend(notify['CRITICAL'])
40
        if not addresses:
Trevor Cappallo's avatar
Trevor Cappallo committed
41
            logging.warning('There were errors, but no recipients specified. No email sent.')
42
        else:
Trevor Cappallo's avatar
Trevor Cappallo committed
43
            addresses = list(set(addresses))
Trevor Cappallo's avatar
Trevor Cappallo committed
44
            logger.email_log(addresses)
45 46
    elif 'DEBUG' in notify and notify['DEBUG']:
        addresses = list(set(notify['DEBUG']))
Trevor Cappallo's avatar
Trevor Cappallo committed
47
        logger.email_log(addresses, level=logging.DEBUG)
Trevor Cappallo's avatar
Trevor Cappallo committed
48
    else:
Trevor Cappallo's avatar
Trevor Cappallo committed
49
        logging.debug('No errors found, no email sent. All is well.')
Trevor Cappallo's avatar
Trevor Cappallo committed
50 51


52 53 54 55
class OperationalLogger:

    """Main class for Operational Logging."""

Trevor Cappallo's avatar
Trevor Cappallo committed
56 57 58 59 60 61
    DEFAULT_LOG_FORMAT_FILE = '[%(asctime)s][%(levelname)5s][p%(process)d][%(filename)s:%(lineno)d]  %(message)s'
    DEFAULT_LOG_FORMAT_CONSOLE = '%(asctime)s (%(levelname)5s) [%(filename)s:%(lineno)d]  %(message)s'
    DEFAULT_DATE_FORMAT_FILE = '%Y-%m-%d %H:%M:%S'
    DEFAULT_DATE_FORMAT_CONSOLE = '%H:%M:%S'
    DEFAULT_FROM_ADDRESS = 'no-reply@aer.com'

Trevor Cappallo's avatar
Trevor Cappallo committed
62 63 64 65 66 67 68 69 70 71 72 73
#    logger = OperationalLogger(
#        log_filename=os.path.join(log_directory, log_filename), logger_name=logger_name,
#        from_address=from_address, notify=notify, log_level=log_level, console_level=console_level,
#        log_format_file=log_format_file, date_format_file=date_format_file,
#        log_format_console=log_format_console, date_format_console=date_format_console
#    )
    def __init__(self, log_filename, logger_name, from_address, notify, log_level, console_level,
                 log_format_file, date_format_file, log_format_console, date_format_console, **kwargs):
        """Initialize logging handlers, formats, etc.

        Should not be called directly; use setup().
        """
Trevor Cappallo's avatar
Trevor Cappallo committed
74
        self.__server_name = socket.getfqdn()
Trevor Cappallo's avatar
Trevor Cappallo committed
75
        self.__debug_buffer = StringIO.StringIO()
Trevor Cappallo's avatar
Trevor Cappallo committed
76 77
        self.__error_buffer = StringIO.StringIO()
        self.__critical_buffer = StringIO.StringIO()
Trevor Cappallo's avatar
Trevor Cappallo committed
78
        if log_format_file is None:
Trevor Cappallo's avatar
Trevor Cappallo committed
79
            log_format_file = self.DEFAULT_LOG_FORMAT_FILE
Trevor Cappallo's avatar
Trevor Cappallo committed
80
        if log_format_console is None:
Trevor Cappallo's avatar
Trevor Cappallo committed
81
            log_format_console = self.DEFAULT_LOG_FORMAT_CONSOLE
Trevor Cappallo's avatar
Trevor Cappallo committed
82
        if date_format_file is None:
Trevor Cappallo's avatar
Trevor Cappallo committed
83
            date_format_file = self.DEFAULT_DATE_FORMAT_FILE
Trevor Cappallo's avatar
Trevor Cappallo committed
84
        if date_format_console is None:
Trevor Cappallo's avatar
Trevor Cappallo committed
85
            date_format_console = self.DEFAULT_DATE_FORMAT_CONSOLE
Trevor Cappallo's avatar
Trevor Cappallo committed
86
        if from_address is None:
Trevor Cappallo's avatar
Trevor Cappallo committed
87
            from_address = self.DEFAULT_FROM_ADDRESS
Trevor Cappallo's avatar
Trevor Cappallo committed
88
        self.__from_address = from_address
Trevor Cappallo's avatar
Trevor Cappallo committed
89

Trevor Cappallo's avatar
Trevor Cappallo committed
90 91
        logging.getLogger(logger_name).handlers = []
        logging.getLogger('_sub').handlers = []
Trevor Cappallo's avatar
Trevor Cappallo committed
92 93
        logging.basicConfig(filename=log_filename, format=log_format_file, datefmt=date_format_file, level=logging.DEBUG)
        formatter = logging.Formatter(fmt=log_format_console, datefmt=date_format_console)
94
        formatter_file = logging.Formatter(fmt=log_format_file, datefmt=date_format_file)
95 96 97 98

        # sub_handler is used for output from log_shell.
        # It is passed parentname and parentline in 'extra' dict,
        #   corresponding to file and line of code calling log_shell.
99
        formatter_sub = logging.Formatter(
Trevor Cappallo's avatar
Trevor Cappallo committed
100 101
            #fmt='%(asctime)s [%(parentname)s:%(parentline)d] ::  %(message)s',
            fmt='%(asctime)s         |-    %(message)s',
102 103
            datefmt='%H:%M:%S'
        )
Trevor Cappallo's avatar
Trevor Cappallo committed
104
        sub_handler = logging.handlers.WatchedFileHandler(log_filename)
105 106
        sub_handler.setLevel(logging.INFO)
        sub_handler.setFormatter(formatter_sub)
Trevor Cappallo's avatar
Trevor Cappallo committed
107
        logging.getLogger('_sub').addHandler(sub_handler)
108 109

        # Turn off propagation so root handler is not triggered.
Trevor Cappallo's avatar
Trevor Cappallo committed
110
        logging.getLogger('_sub').propagate = False
Trevor Cappallo's avatar
Trevor Cappallo committed
111

112 113
        debug_trigger = logging.StreamHandler(self.__debug_buffer)
        debug_trigger.setLevel(logging.DEBUG)
114
        debug_trigger.setFormatter(formatter_file)
Trevor Cappallo's avatar
Trevor Cappallo committed
115 116 117 118 119 120 121
        error_trigger = logging.StreamHandler(self.__error_buffer)
        error_trigger.setLevel(logging.ERROR)
        error_trigger.setFormatter(formatter)
        critical_trigger = logging.StreamHandler(self.__critical_buffer)
        critical_trigger.setLevel(logging.CRITICAL)
        critical_trigger.setFormatter(formatter)

Trevor Cappallo's avatar
Trevor Cappallo committed
122 123
        logging.getLogger(logger_name).addHandler(error_trigger)
        logging.getLogger(logger_name).addHandler(critical_trigger)
124
        logging.getLogger(logger_name).addHandler(debug_trigger)
Trevor Cappallo's avatar
Trevor Cappallo committed
125

Trevor Cappallo's avatar
Trevor Cappallo committed
126
        # provide a more concise format for terminal output
127
        if sys.stdout.isatty():
Trevor Cappallo's avatar
Trevor Cappallo committed
128
            console = logging.StreamHandler(sys.stdout)
Trevor Cappallo's avatar
Trevor Cappallo committed
129
            console.setLevel(console_level)
130
            console.setFormatter(logging.Formatter(
Trevor Cappallo's avatar
Trevor Cappallo committed
131 132
                fmt=log_format_console,
                datefmt=date_format_console,
133
            ))
Trevor Cappallo's avatar
Trevor Cappallo committed
134
            logging.getLogger(logger_name).addHandler(console)
Trevor Cappallo's avatar
Trevor Cappallo committed
135

136 137 138
            sub_handler_console = logging.StreamHandler(sys.stdout)
            sub_handler_console.setLevel(logging.INFO)
            sub_handler_console.setFormatter(formatter_sub)
Trevor Cappallo's avatar
Trevor Cappallo committed
139
            logging.getLogger('_sub').addHandler(sub_handler_console)
140

Trevor Cappallo's avatar
Trevor Cappallo committed
141 142
    def has_errors(self):
        """Return whether any ERROR-level log statements in buffer."""
Trevor Cappallo's avatar
Trevor Cappallo committed
143 144
        return len(self.__error_buffer.getvalue()) > 0

Trevor Cappallo's avatar
Trevor Cappallo committed
145 146
    def has_critical(self):
        """Return whether any CRITICAL-level log statements in buffer."""
Trevor Cappallo's avatar
Trevor Cappallo committed
147 148
        return len(self.__critical_buffer.getvalue()) > 0

149
    def email_log(self, addresses, from_address=None, level=logging.ERROR):
150
        """Send email to addresses with current buffered errors."""
Trevor Cappallo's avatar
Trevor Cappallo committed
151 152
        if from_address is None:
            from_address = self.__from_address
Trevor Cappallo's avatar
Trevor Cappallo committed
153
        logging.info("Emailing log to: %s", ', '.join(addresses))
Trevor Cappallo's avatar
Trevor Cappallo committed
154
        subject_prefix = "ERROR"
155
        if level == logging.CRITICAL:
Trevor Cappallo's avatar
Trevor Cappallo committed
156
            buf = self.__critical_buffer.getvalue()
Trevor Cappallo's avatar
Trevor Cappallo committed
157
            subject_prefix = "CRITICAL"
158
        elif level == logging.DEBUG:
Trevor Cappallo's avatar
Trevor Cappallo committed
159
            buf = self.__debug_buffer.getvalue()
Trevor Cappallo's avatar
Trevor Cappallo committed
160
            subject_prefix = "debug"
161
        else:
Trevor Cappallo's avatar
Trevor Cappallo committed
162
            buf = self.__error_buffer.getvalue()
163
        message = "<br />\n".join([self.__class__.__colorize(line) for line in buf.split('\n')])
Trevor Cappallo's avatar
Trevor Cappallo committed
164
        OperationalMail.send_status(subject='[{}] Log for {}:{}'.format(subject_prefix, self.__server_name,
Trevor Cappallo's avatar
Trevor Cappallo committed
165
                                                                           os.path.basename(sys.argv[0])),
Trevor Cappallo's avatar
Trevor Cappallo committed
166 167
                                    message=message, to_list=addresses, from_address=from_address,
                                    text_attachment=self.__debug_buffer.getvalue())
Trevor Cappallo's avatar
Trevor Cappallo committed
168 169

    @staticmethod
170 171
    def __colorize(line):
        """Add HTML markup for severity of log message."""
Trevor Cappallo's avatar
Trevor Cappallo committed
172
        if 'CRITICAL' in line:
173
            return '<span style="color:red">{}</span>'.format(line)
Trevor Cappallo's avatar
Trevor Cappallo committed
174
        if 'ERROR' in line:
175
            return '<span style="color:red">{}</span>'.format(line)
Trevor Cappallo's avatar
Trevor Cappallo committed
176
        if 'WARNING' in line:
177
            return '<span style="color:blue">{}</span>'.format(line)
Trevor Cappallo's avatar
Trevor Cappallo committed
178 179 180 181 182 183 184 185 186 187
        return line


##########################################################################################
#
# Helper functions
#
##########################################################################################


Trevor Cappallo's avatar
Trevor Cappallo committed
188 189 190 191 192 193 194
def setup(config_file=None, logger_name=None, log_filename=None, log_root_dir=None,
          from_address=None, notify=None, log_level=None, console_level=None,
          log_format_file=None, date_format_file=None, log_format_console=None, date_format_console=None):
    """Configure logger and begin logging.

    config_file: filename to load for logging config as JSON using these keywords, overwritten by args
    logger_name: name to pass to logger
Trevor Cappallo's avatar
Trevor Cappallo committed
195
    log_root_dir, log_filename: log will be created as log_root_dir/LOG_FILENAME.log
Trevor Cappallo's avatar
Trevor Cappallo committed
196 197 198 199 200 201 202 203
                                log_root_dir defaults to '.'
                                log_filename defaults to script name
    from_address: email 'From' address for notifications
    notify: dict containing 'LOG_LEVEL':['list', 'of', 'addresses']
    log_level: cutoff level for overall/file logging
    console_level: cutoff level for stdout
    log_format_file, date_format_file: formats to use for file logger
    log_format_console, date_format_console: formats to use for stdout logger
Trevor Cappallo's avatar
Trevor Cappallo committed
204
    """
205 206
    # Load config{} with passed args, defaulting to None.
    config = {
207
        'log_filename': log_filename, 'log_root_dir': log_root_dir, 'logger_name': logger_name,
208 209 210 211 212 213
        'from_address': from_address, 'notify': notify,
        'log_level': log_level, 'console_level': console_level,
        'log_format_file': log_format_file, 'date_format_file': date_format_file,
        'log_format_console': log_format_console, 'date_format_console': date_format_console,
    }
    # If config file provided, replace any None values with loaded value.
Trevor Cappallo's avatar
Trevor Cappallo committed
214
    if config_file:
215 216 217
        if not os.path.exists(config_file):
            logging.warn("Could not find logging config file: %s", config_file)
        else:
Trevor Cappallo's avatar
Trevor Cappallo committed
218
            logging.info("Loading logging config from: %s", config_file)
219 220 221
            with open(config_file, 'r') as f:
                loaded_config = json.load(f)
            for key, val in loaded_config.items():
222
                if key in config and config[key] is None:
Trevor Cappallo's avatar
Trevor Cappallo committed
223
                    logging.debug("- setting option from file: %s --> %s", key, val)
224
                    config[key] = val
225
    # Set reasonable defaults for remaining Nones.
226 227 228 229 230 231 232 233 234 235 236
    if config['log_root_dir'] is None:
        config['log_root_dir'] = os.getcwd()
#    log_directory = os.path.join(log_root_dir, 'log', datetime.datetime.utcnow().strftime('%Y-%m-%d'))
    log_directory = os.path.abspath(config['log_root_dir'])
    if not os.path.exists(log_directory):
        try:
            # default log dir permissions: SGID bit + rwxr-x---
            os.makedirs(log_directory, 02750)
        except OSError:
            raise RuntimeError('Unable to create log directory: {}'.format(log_directory))

237
    if config['log_filename'] is None:
238 239
        default_filename = os.path.basename(sys.argv[0]).split('.')[0] + '.log'
        config['log_filename'] = os.path.join(log_directory, default_filename)
240 241 242 243 244 245 246 247
    if config['logger_name'] is None:
        config['logger_name'] = ''
    if config['notify'] is None:
        config['notify'] = {}
    if config['log_level'] is None:
        config['log_level'] = logging.DEBUG
    if config['console_level'] is None:
        config['console_level'] = logging.INFO
Trevor Cappallo's avatar
Trevor Cappallo committed
248

Trevor Cappallo's avatar
Trevor Cappallo committed
249 250 251 252 253 254 255
#    logger = OperationalLogger(
#        log_filename=os.path.join(log_directory, log_filename), logger_name=logger_name,
#        from_address=from_address, notify=notify, log_level=log_level, console_level=console_level,
#        log_format_file=log_format_file, date_format_file=date_format_file,
#        log_format_console=log_format_console, date_format_console=date_format_console
#    )
    logger = OperationalLogger(**config)
256
    logging.info('Logging output from: {}'.format(' '.join(sys.argv)))
257
    logging.info('Log writing to: %s', config['log_filename'])
258
    logging.info('Process id {}, parent process id {}'.format(os.getpid(), os.getppid()))
Trevor Cappallo's avatar
Trevor Cappallo committed
259
    logging.info('-' * 60)
Trevor Cappallo's avatar
Trevor Cappallo committed
260 261
    #if notify:
    atexit.register(__exit_handler, logger, config['notify'])
Trevor Cappallo's avatar
Trevor Cappallo committed
262

263

Trevor Cappallo's avatar
Trevor Cappallo committed
264
def long_log(logging_level=logging.INFO, message=''):
265 266 267 268
    """For program output, multi-line messages, etc.

    When message has linebreaks, will break it into individual log calls for consistent formatting.
    """
Trevor Cappallo's avatar
Trevor Cappallo committed
269
    message_list = message.split("\n")
270
    for msg in message_list:
Trevor Cappallo's avatar
Trevor Cappallo committed
271
        logging.log(logging_level, ' ::  ' + msg)
Trevor Cappallo's avatar
Trevor Cappallo committed
272 273


Trevor Cappallo's avatar
Trevor Cappallo committed
274
def long_critical(message):
275
    """Log a multi-line CRITICAL message."""
Trevor Cappallo's avatar
Trevor Cappallo committed
276
    long_log(logging.CRITICAL, message)
277 278


Trevor Cappallo's avatar
Trevor Cappallo committed
279
def long_error(message):
280
    """Log a multi-line ERROR message."""
Trevor Cappallo's avatar
Trevor Cappallo committed
281
    long_log(logging.ERROR, message)
282

Trevor Cappallo's avatar
Trevor Cappallo committed
283

Trevor Cappallo's avatar
Trevor Cappallo committed
284
def long_warning(message):
285
    """Log a multi-line WARNING message."""
Trevor Cappallo's avatar
Trevor Cappallo committed
286
    long_log(logging.WARNING, message)
Trevor Cappallo's avatar
Trevor Cappallo committed
287 288


Trevor Cappallo's avatar
Trevor Cappallo committed
289
def long_info(message):
290
    """Log a multi-line INFO message."""
Trevor Cappallo's avatar
Trevor Cappallo committed
291
    long_log(logging.INFO, message)
Trevor Cappallo's avatar
Trevor Cappallo committed
292

293

Trevor Cappallo's avatar
Trevor Cappallo committed
294
def long_debug(message):
295
    """Log a multi-line DEBUG message."""
Trevor Cappallo's avatar
Trevor Cappallo committed
296
    long_log(logging.DEBUG, message)
297 298


299 300 301 302 303 304 305 306
def log_shell(arg_list, raise_err=False, return_output=False, **kwargs):
    """Pass arg_list to a subprocess call and log all output.

    raise_err: (like subprocess.check_call) if True,
               raises a RuntimeError if exit code is non-zero
    return_output: (like subprocess.check_output) returns any output
                   from shell call instead of the exit code
    """
Trevor Cappallo's avatar
Trevor Cappallo committed
307
    logging.info('Spawning child process from pid={}'.format(os.getpid()))
Trevor Cappallo's avatar
Trevor Cappallo committed
308
    logging.info('Executing: {}'.format(' '.join(arg_list)))
309
    try:
310 311 312 313 314 315
        my_name = os.path.basename(inspect.getfile(inspect.currentframe()))
        for f in inspect.stack():
            if my_name != os.path.basename(f[1]):
                parent_name, line_num = os.path.basename(f[1]), f[2]
                break

316
        proc_output = ""
317 318
        proc = subprocess.Popen(arg_list, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, **kwargs)
        for line in iter(proc.stdout.readline, b''):
Trevor Cappallo's avatar
Trevor Cappallo committed
319 320
            if not line:
                break
321
            proc_output += line
Trevor Cappallo's avatar
Trevor Cappallo committed
322
            logging.getLogger('_sub').info(line.rstrip(), extra={'parentname':parent_name, 'parentline':line_num})
Trevor Cappallo's avatar
Trevor Cappallo committed
323 324
        return_code = proc.wait()
        if return_code:
325 326 327 328 329 330
            if raise_err:
                logging.error('{} failed with exit code {}'.format(' '.join(arg_list), return_code))
                raise RuntimeError('{} failed with exit code {}'.format(' '.join(arg_list), return_code))
            else:
                logging.warning('{} failed with exit code {}'.format(' '.join(arg_list), return_code))
                return proc_output if return_output else return_code
Trevor Cappallo's avatar
Trevor Cappallo committed
331
    except OSError as err:
Trevor Cappallo's avatar
Trevor Cappallo committed
332 333
        logging.error('Error while executing %s: %s', ' '.join(arg_list), str(err))
        return err
334
    else:
Trevor Cappallo's avatar
Trevor Cappallo committed
335
        logging.info('Successfully finished: %s', ' '.join(arg_list))
336
        return proc_output if return_output else return_code
337

Trevor Cappallo's avatar
Trevor Cappallo committed
338 339

def stack_trace(log_level=logging.ERROR):
340
    """Log a stack trace at the given level."""
Trevor Cappallo's avatar
Trevor Cappallo committed
341 342
    import traceback
    tb = traceback.format_exc()
Trevor Cappallo's avatar
Trevor Cappallo committed
343
    long_log(log_level, tb)