common.lib.logger

  1"""
  2Log handler
  3"""
  4import traceback
  5import platform
  6import logging
  7import time
  8import json
  9import re
 10
 11from pathlib import Path
 12
 13from logging.handlers import RotatingFileHandler, HTTPHandler
 14
 15from common.config_manager import CoreConfigManager
 16from common.lib.helpers import get_software_commit
 17
 18class WebHookLogHandler(HTTPHandler):
 19    """
 20    Basic HTTPHandler for webhooks via standard log handling
 21
 22    In essence, an HTTPHandler that formats its payload as JSON.
 23    """
 24    server_name = ""
 25
 26    def __init__(self, url):
 27        """
 28        Initialise WebHook handler
 29
 30        :param str url:  URL to send log messages to
 31        """
 32        host = url.split("/")[2]
 33        secure = url.lower().startswith("https")
 34
 35        super().__init__(host, url, method="POST", secure=secure)
 36
 37    def emit(self, record):
 38        """
 39        Emit a record
 40
 41        Send the record to the Web server as a percent-encoded dictionary
 42        This is the `emit()` method of the original HTTPHandler; the only
 43        change is that content is sent as JSON (which the webhooks expect)
 44        instead of urlencoded data.
 45
 46        :param logging.LogRecord record:  Log record to send
 47        """
 48        try:
 49            import http.client
 50            host = self.host
 51            if self.secure:
 52                h = http.client.HTTPSConnection(host, context=self.context)
 53            else:
 54                h = http.client.HTTPConnection(host)
 55            url = self.url
 56            ############### CHANGED FROM ORIGINAL ###############
 57            data = json.dumps(self.mapLogRecord(record))
 58            #####################################################
 59            if self.method == "GET":
 60                if (url.find('?') >= 0):
 61                    sep = '&'
 62                else:
 63                    sep = '?'
 64                url = url + "%c%s" % (sep, data)
 65            h.putrequest(self.method, url)
 66            # support multiple hosts on one IP address...
 67            # need to strip optional :port from host, if present
 68            i = host.find(":")
 69            if i >= 0:
 70                host = host[:i]
 71            # See issue #30904: putrequest call above already adds this header
 72            # on Python 3.x.
 73            # h.putheader("Host", host)
 74            if self.method == "POST":
 75                ############### CHANGED FROM ORIGINAL ###############
 76                h.putheader("Content-type", "application/json")
 77                #####################################################
 78                h.putheader("Content-length", str(len(data)))
 79            if self.credentials:
 80                import base64
 81                s = ('%s:%s' % self.credentials).encode('utf-8')
 82                s = 'Basic ' + base64.b64encode(s).strip().decode('ascii')
 83                h.putheader('Authorization', s)
 84            h.endheaders()
 85            if self.method == "POST":
 86                h.send(data.encode('utf-8'))
 87            h.getresponse()  # can't do anything with the result
 88        except Exception:
 89            self.handleError(record)
 90
 91
 92class SlackLogHandler(WebHookLogHandler):
 93    """
 94    Slack webhook log handler
 95    """
 96    _base_github_url = ""
 97    _base_4cat_url = ""
 98    _base_4cat_path = ""
 99    _extension_path = ""
100
101    def __init__(self, *args, **kwargs):
102        """
103        Constructor
104
105        We add an argument for the Github link to link to in the stack trace
106        for easier debugging.
107
108        :param args:
109        :param kwargs:
110        """
111        if "config" in kwargs:
112            config = kwargs["config"]
113            del kwargs["config"]
114        else:
115            raise TypeError("SlackLogHandler() expects a config reader as argument")
116
117        # construct a github URL to link in slack alerts to easily review
118        # erroneous code
119        if config.get("4cat.github_url"):
120            github_url = config.get("4cat.github_url")
121            if github_url.endswith("/"):
122                github_url = github_url[:-1]
123            github_url += "/blob/"
124
125            # use commit hash if available, else link to master
126            commit = get_software_commit()
127            github_url += f"{commit[0] or 'master'}/"
128            self._base_github_url = github_url
129
130        # we cannot use the config reader later because the logger is shared
131        # across threads and the config reader/memcache is not thread-safe, so
132        # pre-read the relevant values here
133        self._base_4cat_url = f"http{'s' if config.get('flask.https') else ''}://{config.get('flask.server_name')}/results/"
134        self._base_4cat_path = config.get("PATH_ROOT")
135        self._extension_path = config.get("PATH_EXTENSIONS")
136
137        super().__init__(*args, **kwargs)
138
139    def mapLogRecord(self, record):
140        """
141        Format log message so it is compatible with Slack webhooks
142
143        :param logging.LogRecord record: Log record
144        """
145        if record.levelno in (logging.ERROR, logging.CRITICAL):
146            emoji = ":rotating_light:"
147            color = "#FF0000"  # red
148        elif record.levelno == logging.WARNING:
149            emoji = ":bell:"
150            color = "#DD7711"  # orange
151        else:
152            emoji = ":information_source:"
153            color = "#3CC619"  # green
154
155        # this also catches other 32-char hex strings...
156        # but a few false positives are OK as a trade-off for the convenience
157        error_message = re.sub(r"\b([0-9a-fA-F]{32})\b", f"<{self._base_4cat_url}\\1/|\\1>", record.message)
158
159        # simple stack trace
160        if record.stack:
161            # this is the stack where the log was called
162            frames = record.stack
163        else:
164            # the last 9 frames are not specific to the exception (general logging code etc)
165            # the frame before that is where the exception was raised
166            frames = traceback.extract_stack()[:-9]
167
168        # go through the traceback and distinguish 4CAT's own code from library
169        # or stdlib code, and annotate accordingly
170        nice_frames = []
171        highlight_frame = None
172        highlight_link = None
173        for frame in frames:
174            framepath = Path(frame.filename)
175            frame_location = frame.filename.split("/")[-1] + ":" + str(frame.lineno)
176
177            # make a link to the github if it is a file in the 4cat root and
178            # not in the venv (i.e. it is 4CAT's own code)
179            if (
180                    framepath.is_relative_to(self._base_4cat_path)
181                    and not framepath.is_relative_to(self._extension_path)
182                    and "site-packages" not in framepath.parts
183                    and self._base_github_url
184            ):
185                sub_path = str(framepath.relative_to(self._base_4cat_path))
186                url = f"{self._base_github_url}{sub_path}#L{frame.lineno}"
187                frame_location = f"<{url}|`{frame_location}`>"
188                highlight_frame = frame
189                highlight_link = frame_location
190            else:
191                frame_location = f"_`{frame_location}`_"
192
193            if not highlight_frame:
194                highlight_frame = frame
195                highlight_link = frame_location
196
197            nice_frames.append(frame_location)
198
199        # prepare slack webhook payload
200        attachments = [{
201            "type": "section",
202            "text": {
203                "type": "mrkdwn",
204                "text": f"*Stack trace:*\n{' → '.join(nice_frames)}"
205            }
206        }]
207
208        # try to read some metadata from the offending file
209        try:
210            with Path(highlight_frame.filename).open() as infile:
211                attachments.append({
212                    "type": "section",
213                    "text": {
214                        "type": "mrkdwn",
215                        "text": "*Code* (" + highlight_link + "):\n```" + infile.readlines()[highlight_frame.lineno - 1].strip() + "```",
216                    }
217                })
218        except (IndexError, AttributeError):
219            # the file is not readable, or the line number is out of bounds
220            pass
221
222        return {
223            "attachments": [
224                {
225                    "color": color,
226                    "blocks": [
227                        {
228                            "type": "section",
229                            "text": {
230                                "type": "mrkdwn",
231                                "text": f"{emoji} *4CAT {record.levelname.lower()} logged on `{platform.uname().node}`:*",
232                            },
233                        },
234                        {
235                            "type": "section",
236                            "text": {"type": "mrkdwn", "text": error_message},
237                        },
238                        *attachments,
239                    ],
240                }
241            ]
242        }
243
244
245class Logger:
246    """
247    Logger
248
249    Sets up a rotating logger that writes to a log file
250    """
251    logger = None
252    log_path = None
253    print_logs = True
254    db = None
255    previous_report = 0
256    levels = {
257        "DEBUG2": 5,  # logging.DEBUG = 10
258        "DEBUG": logging.DEBUG,
259        "INFO": logging.INFO,
260        "WARNING": logging.WARNING,
261        "ERROR": logging.ERROR,
262        "CRITICAL": logging.CRITICAL,
263        "FATAL": logging.FATAL
264    }
265    alert_level = "FATAL"
266
267    def __init__(self, log_path="4cat.log", logger_name='4cat', output=False, log_level="INFO"):
268        """
269        Set up log handler
270
271        :param str|Path filename:  File path that will be written to
272        :param str logger_name:  Identifier for logging context
273        :param bool output:  Whether to print logs to output
274        :param str log_level:  Messages at this level or below will be logged
275        """
276        if self.logger:
277            return
278        log_level = self.levels.get(log_level, logging.INFO)
279
280        self.print_logs = output
281
282        if type(log_path) is str:
283            core_config = CoreConfigManager()
284            log_path = core_config.get("PATH_LOGS").joinpath(log_path)
285
286        if not log_path.parent.exists():
287            log_path.parent.mkdir(parents=True)
288
289        self.log_path = log_path
290        self.previous_report = time.time()
291
292        self.logger = logging.getLogger(logger_name)
293        self.logger.setLevel(log_level)
294
295        # this handler manages the text log files
296        formatter = logging.Formatter("%(asctime)-15s | %(levelname)s at %(location)s: %(message)s",
297                                                   "%d-%m-%Y %H:%M:%S")
298        if not self.logger.handlers:
299            handler = RotatingFileHandler(self.log_path, maxBytes=(50 * 1024 * 1024), backupCount=1)
300            handler.setLevel(log_level)
301            handler.setFormatter(formatter)
302            self.logger.addHandler(handler)
303
304        # to stdout
305        if output:
306            handler = logging.StreamHandler()
307            handler.setLevel(log_level)
308            handler.setFormatter(formatter)
309            self.logger.addHandler(handler)
310
311    def load_webhook(self, config):
312        """
313        Load webhook configuration
314
315        The webhook is configured in the database; but the logger may not
316        always have access to the database. So instead of setting it up at
317        init, this function must be called explicitly to enable it for this
318        logger instance.
319
320        :param config:  Configuration reader
321        :return:
322        """
323        if config.get("logging.slack.webhook"):
324            slack_handler = SlackLogHandler(config.get("logging.slack.webhook"), config=config)
325            slack_handler.setLevel(self.levels.get(config.get("logging.slack.level"), self.alert_level))
326            self.logger.addHandler(slack_handler)
327
328    def log(self, message, level=logging.INFO, frame=None):
329        """
330        Log message
331
332        :param message:  Message to log
333        :param level:  Severity level, should be a logger.* constant
334        :param frame:  Traceback frame. If no frame is given, it is
335        extrapolated
336        """
337        if type(frame) is traceback.StackSummary:
338            # Full stack was provided
339            stack = frame
340            frame = stack[-1]
341        else:
342            # Collect the stack (used by Slack)
343            stack = traceback.extract_stack()[:-2]
344
345        if frame is None:
346            # Use the last frame in the stack
347            frame = stack[-1]
348        else:
349            # Frame was provided; use it
350            pass
351
352        # Logging uses the location, Slack uses the full stack
353        location = frame.filename.split("/")[-1] + ":" + str(frame.lineno)
354        self.logger.log(level, message, extra={"location": location, "frame": frame, "stack": stack})
355
356    def debug2(self, message, frame=None):
357        """
358        Log DEBUG2 level message
359
360        DEBUG2 is a custom log level, with less priority than the standard DEBUG
361
362        :param message: Message to log
363        :param frame:  Traceback frame relating to the error
364        """
365        self.log(message, 5, frame)
366
367    def debug(self, message, frame=None):
368        """
369        Log DEBUG level message
370
371        :param message: Message to log
372        :param frame:  Traceback frame relating to the error
373        """
374        self.log(message, logging.DEBUG, frame)
375
376    def info(self, message, frame=None):
377        """
378        Log INFO level message
379
380        :param message: Message to log
381        :param frame:  Traceback frame relating to the error
382        """
383        self.log(message, logging.INFO)
384
385    def warning(self, message, frame=None):
386        """
387        Log WARNING level message
388
389        :param message: Message to log
390        :param frame:  Traceback frame relating to the error
391        """
392        self.log(message, logging.WARN, frame)
393
394    def error(self, message, frame=None):
395        """
396        Log ERROR level message
397
398        :param message: Message to log
399        :param frame:  Traceback frame relating to the error
400        """
401        self.log(message, logging.ERROR, frame)
402
403    def critical(self, message, frame=None):
404        """
405        Log CRITICAL level message
406
407        :param message: Message to log
408        :param frame:  Traceback frame relating to the error
409        """
410        self.log(message, logging.CRITICAL, frame)
411
412    def fatal(self, message, frame=None):
413        """
414        Log FATAL level message
415
416        :param message: Message to log
417        :param frame:  Traceback frame relating to the error
418        """
419        self.log(message, logging.FATAL, frame)