logger.py 11.3 KB
Newer Older
louiz’'s avatar
louiz’ committed
1
# Copyright 2010-2011 Florent Le Coz <louiz@louiz.org>
2 3 4 5
#
# This file is part of Poezio.
#
# Poezio is free software: you can redistribute it and/or modify
6
# it under the terms of the zlib license. See the COPYING file.
7 8 9 10 11
"""
The logger module that handles logging of the poezio
conversations and roster changes
"""

12
import mmap
13
import re
Link Mauve's avatar
coucou  
Link Mauve committed
14
from typing import List, Dict, Optional, IO, Any
15
from datetime import datetime
16

mathieui's avatar
mathieui committed
17 18 19 20
from poezio import common
from poezio.config import config
from poezio.xhtml import clean_text
from poezio.theming import dump_tuple, get_theme
21

22 23 24 25
import logging

log = logging.getLogger(__name__)

mathieui's avatar
mathieui committed
26
from poezio.config import LOG_DIR as log_dir
27

28
MESSAGE_LOG_RE = re.compile(r'^MR (\d{4})(\d{2})(\d{2})T'
29
                            r'(\d{2}):(\d{2}):(\d{2})Z '
30 31
                            r'(\d+) <([^ ]+)>  (.*)$')
INFO_LOG_RE = re.compile(r'^MI (\d{4})(\d{2})(\d{2})T'
32
                         r'(\d{2}):(\d{2}):(\d{2})Z '
33
                         r'(\d+) (.*)$')
34

mathieui's avatar
mathieui committed
35

mathieui's avatar
mathieui committed
36
class LogItem:
mathieui's avatar
mathieui committed
37 38 39
    def __init__(self, year, month, day, hour, minute, second, nb_lines,
                 message):
        self.time = datetime(
mathieui's avatar
mathieui committed
40 41
            int(year), int(month), int(day), int(hour), int(minute),
            int(second))
mathieui's avatar
mathieui committed
42 43 44
        self.nb_lines = int(nb_lines)
        self.text = message

mathieui's avatar
mathieui committed
45

mathieui's avatar
mathieui committed
46 47 48 49
class LogInfo(LogItem):
    def __init__(self, *args):
        LogItem.__init__(self, *args)

mathieui's avatar
mathieui committed
50

mathieui's avatar
mathieui committed
51
class LogMessage(LogItem):
mathieui's avatar
mathieui committed
52 53
    def __init__(self, year, month, day, hour, minute, seconds, nb_lines, nick,
                 message):
mathieui's avatar
mathieui committed
54 55 56 57
        LogItem.__init__(self, year, month, day, hour, minute, seconds,
                         nb_lines, message)
        self.nick = nick

mathieui's avatar
mathieui committed
58

59
def _parse_log_line(msg: str) -> Optional[LogItem]:
60 61 62 63 64 65 66
    match = re.match(MESSAGE_LOG_RE, msg)
    if match:
        return LogMessage(*match.groups())
    match = re.match(INFO_LOG_RE, msg)
    if match:
        return LogInfo(*match.groups())
    log.debug('Error while parsing "%s"', msg)
67
    return None
68

mathieui's avatar
mathieui committed
69

70
class Logger:
71 72 73 74
    """
    Appends things to files. Error/information/warning logs
    and also log the conversations to logfiles
    """
mathieui's avatar
mathieui committed
75

76
    def __init__(self):
Link Mauve's avatar
coucou  
Link Mauve committed
77
        self._roster_logfile = None  # Optional[IO[Any]]
78
        # a dict of 'groupchatname': file-object (opened)
Link Mauve's avatar
coucou  
Link Mauve committed
79
        self._fds = {}  # type: Dict[str, IO[Any]]
80

81
    def __del__(self):
82
        for opened_file in self._fds.values():
83
            if opened_file:
mathieui's avatar
mathieui committed
84 85
                try:
                    opened_file.close()
mathieui's avatar
mathieui committed
86
                except:  # Can't close? too bad
mathieui's avatar
mathieui committed
87
                    pass
88

Link Mauve's avatar
Link Mauve committed
89
    def close(self, jid) -> None:
90
        jid = str(jid).replace('/', '\\')
91 92 93 94
        if jid in self._fds:
            self._fds[jid].close()
            log.debug('Log file for %s closed.', jid)
            del self._fds[jid]
95
        return None
96

Link Mauve's avatar
Link Mauve committed
97
    def reload_all(self) -> None:
98
        """Close and reload all the file handles (on SIGHUP)"""
99
        for opened_file in self._fds.values():
100 101 102
            if opened_file:
                opened_file.close()
        log.debug('All log file handles closed')
103
        for room in self._fds:
104
            self._check_and_create_log_dir(room)
105
            log.debug('Log handle for %s re-created', room)
106
        return None
107

Link Mauve's avatar
Link Mauve committed
108 109
    def _check_and_create_log_dir(self, room: str,
                                  open_fd: bool = True) -> Optional[IO[Any]]:
110
        """
111 112
        Check that the directory where we want to log the messages
        exists. if not, create it
113
        """
114
        if not config.get_by_tabname('use_log', room):
115
            return None
116
        try:
117
            log_dir.mkdir(parents=True, exist_ok=True)
mathieui's avatar
mathieui committed
118
        except OSError as e:
119
            log.error('Unable to create the log dir', exc_info=True)
120 121
        except:
            log.error('Unable to create the log dir', exc_info=True)
122
            return None
123
        if not open_fd:
124
            return None
125
        filename = log_dir / room
126
        try:
127
            fd = filename.open('a', encoding='utf-8')
128
            self._fds[room] = fd
129
            return fd
130
        except IOError:
mathieui's avatar
mathieui committed
131
            log.error(
mathieui's avatar
mathieui committed
132
                'Unable to open the log file (%s)', filename, exc_info=True)
133
        return None
134

Link Mauve's avatar
Link Mauve committed
135 136
    def get_logs(self, jid: str,
                 nb: int = 10) -> Optional[List[Dict[str, Any]]]:
137
        """
138 139 140 141
        Get the nb last messages from the log history for the given jid.
        Note that a message may be more than one line in these files, so
        this function is a little bit more complicated than “read the last
        nb lines”.
142
        """
143
        if config.get_by_tabname('load_log', jid) <= 0:
144
            return None
145

146
        if not config.get_by_tabname('use_log', jid):
147
            return None
148

149
        if nb <= 0:
150
            return None
151

152
        self._check_and_create_log_dir(jid, open_fd=False)
153

154
        filename = log_dir / jid
155
        try:
156
            fd = filename.open('rb')
157
        except FileNotFoundError:
mathieui's avatar
mathieui committed
158
            log.info('Non-existing log file (%s)', filename, exc_info=True)
159
            return None
160
        except OSError:
mathieui's avatar
mathieui committed
161
            log.error(
mathieui's avatar
mathieui committed
162
                'Unable to open the log file (%s)', filename, exc_info=True)
163
            return None
164
        if not fd:
165
            return None
166

167 168 169 170
        # read the needed data from the file, we just search nb messages by
        # searching "\nM" nb times from the end of the file.  We use mmap to
        # do that efficiently, instead of seek()s and read()s which are costly.
        with fd:
171
            try:
172
                lines = _get_lines_from_fd(fd, nb=nb)
mathieui's avatar
mathieui committed
173 174 175
            except Exception:  # file probably empty
                log.error(
                    'Unable to mmap the log file for (%s)',
176
                    filename,
mathieui's avatar
mathieui committed
177
                    exc_info=True)
178
                return None
179
        return _parse_log_lines(lines)
180

Link Mauve's avatar
Link Mauve committed
181 182 183 184 185 186
    def log_message(self,
                    jid: str,
                    nick: str,
                    msg: str,
                    date: Optional[datetime] = None,
                    typ: int = 1) -> bool:
187
        """
188
        log the message in the appropriate jid's file
189 190 191
        type:
              0 = Don’t log
              1 = Message
192
              2 = Status/whatever
193
        """
194
        if not config.get_by_tabname('use_log', jid):
195
            return True
196
        logged_msg = _build_log_message(nick, msg, date=date, typ=typ)
197 198
        if not logged_msg:
            return True
199 200
        if jid in self._fds.keys():
            fd = self._fds[jid]
201
        else:
202 203 204 205
            option_fd = self._check_and_create_log_dir(jid)
            if option_fd is None:
                return True
            fd = option_fd
206
        filename = log_dir / jid
207
        try:
208 209
            fd.write(logged_msg)
        except OSError:
mathieui's avatar
mathieui committed
210 211
            log.error(
                'Unable to write in the log file (%s)',
212
                filename,
mathieui's avatar
mathieui committed
213
                exc_info=True)
mathieui's avatar
mathieui committed
214
            return False
215
        else:
mathieui's avatar
mathieui committed
216
            try:
mathieui's avatar
mathieui committed
217
                fd.flush()  # TODO do something better here?
218
            except OSError:
mathieui's avatar
mathieui committed
219 220
                log.error(
                    'Unable to flush the log file (%s)',
221
                    filename,
mathieui's avatar
mathieui committed
222
                    exc_info=True)
mathieui's avatar
mathieui committed
223 224
                return False
        return True
225

Link Mauve's avatar
Link Mauve committed
226
    def log_roster_change(self, jid: str, message: str) -> bool:
227 228 229
        """
        Log a roster change
        """
230
        if not config.get_by_tabname('use_log', jid):
231
            return True
232
        self._check_and_create_log_dir('', open_fd=False)
233
        filename = log_dir / 'roster.log'
234
        if not self._roster_logfile:
mathieui's avatar
mathieui committed
235
            try:
mathieui's avatar
mathieui committed
236
                self._roster_logfile = filename.open('a', encoding='utf-8')
mathieui's avatar
mathieui committed
237
            except IOError:
mathieui's avatar
mathieui committed
238 239
                log.error(
                    'Unable to create the log file (%s)',
240
                    filename,
mathieui's avatar
mathieui committed
241
                    exc_info=True)
mathieui's avatar
mathieui committed
242 243
                return False
        try:
244
            str_time = common.get_utc_time().strftime('%Y%m%dT%H:%M:%SZ')
245
            message = clean_text(message)
246 247 248
            lines = message.split('\n')
            first_line = lines.pop(0)
            nb_lines = str(len(lines)).zfill(3)
mathieui's avatar
mathieui committed
249 250
            self._roster_logfile.write(
                'MI %s %s %s %s\n' % (str_time, nb_lines, jid, first_line))
251
            for line in lines:
252 253
                self._roster_logfile.write(' %s\n' % line)
            self._roster_logfile.flush()
mathieui's avatar
mathieui committed
254
        except:
mathieui's avatar
mathieui committed
255 256
            log.error(
                'Unable to write in the log file (%s)',
257
                filename,
mathieui's avatar
mathieui committed
258
                exc_info=True)
mathieui's avatar
mathieui committed
259 260
            return False
        return True
mathieui's avatar
mathieui committed
261

mathieui's avatar
mathieui committed
262

263 264 265 266
def _build_log_message(nick: str,
                       msg: str,
                       date: Optional[datetime] = None,
                       typ: int = 1) -> str:
267 268 269 270 271 272 273 274 275 276 277
    """
    Create a log message from a nick, a message, optionally a date and type
    message types:
        0 = Don’t log
        1 = Message
        2 = Status/whatever
    """
    if not typ:
        return ''

    msg = clean_text(msg)
Link Mauve's avatar
Link Mauve committed
278 279 280
    time = common.get_utc_time() if date is None else common.get_utc_time(date)
    str_time = time.strftime('%Y%m%dT%H:%M:%SZ')
    prefix = 'MR' if typ == 1 else 'MI'
281 282 283 284 285 286 287 288 289 290 291 292
    lines = msg.split('\n')
    first_line = lines.pop(0)
    nb_lines = str(len(lines)).zfill(3)
    if nick:
        nick = '<' + nick + '>'
        logged_msg = '%s %s %s %s  %s\n' % (prefix, str_time, nb_lines, nick,
                                            first_line)
    else:
        logged_msg = '%s %s %s %s\n' % (prefix, str_time, nb_lines, first_line)
    return logged_msg + ''.join(' %s\n' % line for line in lines)


293
def _get_lines_from_fd(fd: IO[Any], nb: int = 10) -> List[str]:
294 295 296 297
    """
    Get the last log lines from a fileno
    """
    with mmap.mmap(fd.fileno(), 0, prot=mmap.PROT_READ) as m:
298 299
        # start of messages begin with MI or MR, after a \n
        pos = m.rfind(b"\nM") + 1
300 301
        # number of message found so far
        count = 0
302
        while pos != 0 and count < nb - 1:
303
            count += 1
304 305
            pos = m.rfind(b"\nM", 0, pos) + 1
        lines = m[pos:].decode(errors='replace').splitlines()
306 307 308
    return lines


309
def _parse_log_lines(lines: List[str]) -> List[Dict[str, Any]]:
310 311 312 313 314 315 316 317 318 319 320 321 322
    """
    Parse raw log lines into poezio log objects
    """
    messages = []
    color = '\x19%s}' % dump_tuple(get_theme().COLOR_LOG_MSG)

    # now convert that data into actual Message objects
    idx = 0
    while idx < len(lines):
        if lines[idx].startswith(' '):  # should not happen ; skip
            idx += 1
            log.debug('fail?')
            continue
323
        log_item = _parse_log_line(lines[idx])
324 325 326 327
        idx += 1
        if not isinstance(log_item, LogItem):
            log.debug('wrong log format? %s', log_item)
            continue
328
        message_lines = []
329 330 331 332 333 334
        message = {
            'history': True,
            'time': common.get_local_time(log_item.time)
        }
        size = log_item.nb_lines
        if isinstance(log_item, LogInfo):
335
            message_lines.append(color + log_item.text)
336 337
        elif isinstance(log_item, LogMessage):
            message['nickname'] = log_item.nick
338
            message_lines.append(color + log_item.text)
339
        while size != 0 and idx < len(lines):
340
            message_lines.append(lines[idx][1:])
341 342
            size -= 1
            idx += 1
343
        message['txt'] = '\n'.join(message_lines)
344 345 346 347
        messages.append(message)
    return messages


Link Mauve's avatar
Link Mauve committed
348
def create_logger() -> None:
349 350 351 352
    "Create the global logger object"
    global logger
    logger = Logger()

mathieui's avatar
mathieui committed
353

mathieui's avatar
mathieui committed
354
logger = None  # type: Optional[Logger]