logger.py 14.9 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
14
from typing import List, Dict, Optional, IO, Any, Union, Generator
15
from datetime import datetime
16
from pathlib import Path
17

mathieui's avatar
mathieui committed
18
19
20
from poezio import common
from poezio.config import config
from poezio.xhtml import clean_text
21
from poezio.ui.types import Message, BaseMessage, LoggableTrait
22
from slixmpp import JID
mathieui's avatar
mathieui committed
23
from poezio.types import TypedDict
24

25
26
27
28
import logging

log = logging.getLogger(__name__)

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

mathieui's avatar
mathieui committed
36

mathieui's avatar
mathieui committed
37
class LogItem:
38
39
40
41
42
43
44
    time: datetime
    nb_lines: int
    text: str

    def __init__(self, year: str, month: str, day: str, hour: str, minute: str,
                 second: str, nb_lines: str,
                 message: str):
mathieui's avatar
mathieui committed
45
        self.time = datetime(
mathieui's avatar
mathieui committed
46
47
            int(year), int(month), int(day), int(hour), int(minute),
            int(second))
mathieui's avatar
mathieui committed
48
49
50
        self.nb_lines = int(nb_lines)
        self.text = message

mathieui's avatar
mathieui committed
51

mathieui's avatar
mathieui committed
52
53
54
55
class LogInfo(LogItem):
    def __init__(self, *args):
        LogItem.__init__(self, *args)

mathieui's avatar
mathieui committed
56

mathieui's avatar
mathieui committed
57
class LogMessage(LogItem):
58
59
60
61
62
    nick: str

    def __init__(self, year: str, month: str, day: str, hour: str, minute: str,
                 seconds: str, nb_lines: str, nick: str,
                 message: str):
mathieui's avatar
mathieui committed
63
64
65
66
        LogItem.__init__(self, year, month, day, hour, minute, seconds,
                         nb_lines, message)
        self.nick = nick

mathieui's avatar
mathieui committed
67

68
69
70
LogDict = TypedDict(
    'LogDict',
    {
mathieui's avatar
mathieui committed
71
        'type': str, 'txt': str, 'time': datetime,
72
73
74
75
76
77
        'history': bool, 'nickname': str
    },
    total=False,
)


78
def parse_log_line(msg: str, jid: str = '') -> Optional[LogItem]:
79
80
81
82
83
84
    """Parse a log line.

    :param msg: The message ligne
    :param jid: jid (for error logging)
    :returns: The LogItem or None on error
    """
85
86
87
88
89
90
    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())
91
    log.debug('Error while parsing %s’s logs: “%s”', jid, msg)
92
    return None
93

mathieui's avatar
mathieui committed
94

95
class Logger:
96
97
98
99
    """
    Appends things to files. Error/information/warning logs
    and also log the conversations to logfiles
    """
100
101
102
    _roster_logfile: Optional[IO[str]]
    log_dir: Path
    _fds: Dict[str, IO[str]]
103
    _busy_fds: Dict[str, bool]
mathieui's avatar
mathieui committed
104

105
    def __init__(self):
106
107
        self.log_dir = Path()
        self._roster_logfile = None
108
        # a dict of 'groupchatname': file-object (opened)
109
        self._fds = {}
110
111
        self._busy_fds = {}
        self._buffered_fds = {}
112

113
    def __del__(self):
114
        """Close all fds on exit"""
115
        for opened_file in self._fds.values():
116
            if opened_file:
mathieui's avatar
mathieui committed
117
118
                try:
                    opened_file.close()
119
                except Exception:  # Can't close? too bad
mathieui's avatar
mathieui committed
120
                    pass
121
122
123
124
        try:
            self._roster_logfile.close()
        except Exception:
            pass
125

126
    def get_file_path(self, jid: Union[str, JID]) -> Path:
127
128
129
130
        """Return the log path for a specific jid"""
        jidstr = str(jid).replace('/', '\\')
        return self.log_dir / jidstr

131
    def fd_busy(self, jid: Union[str, JID]) -> None:
132
133
134
135
136
        """Signal to the logger that this logfile is busy elsewhere.
        And that the messages should be queued to be logged later.

        :param jid: file name
        """
137
138
        jidstr = str(jid).replace('/', '\\')
        self._busy_fds[jidstr] = True
139
140
        if jidstr not in self._buffered_fds:
            self._buffered_fds[jidstr] = []
141

142
    def fd_available(self, jid: Union[str, JID]) -> None:
143
144
145
146
147
        """Signal to the logger that this logfile is no longer busy.
        And write messages to the end.

        :param jid: file name
        """
148
149
150
151
152
153
154
155
        jidstr = str(jid).replace('/', '\\')
        if jidstr in self._busy_fds:
            del self._busy_fds[jidstr]
        if jidstr in self._buffered_fds:
            msgs = ''.join(self._buffered_fds.pop(jidstr))
            if jidstr in self._fds:
                self._fds[jidstr].close()
                del self._fds[jidstr]
156
157
            self.log_raw(jid, msgs)

158
159
    def close(self, jid: str) -> None:
        """Close the log file for a JID."""
160
        jid = str(jid).replace('/', '\\')
161
162
163
164
165
        if jid in self._fds:
            self._fds[jid].close()
            log.debug('Log file for %s closed.', jid)
            del self._fds[jid]

Link Mauve's avatar
Link Mauve committed
166
    def reload_all(self) -> None:
167
        """Close and reload all the file handles (on SIGHUP)"""
168
169
        not_closed = set()
        for key, opened_file in self._fds.items():
170
            if opened_file:
171
172
173
174
175
176
177
178
179
                try:
                    opened_file.close()
                except Exception:
                    not_closed.add(key)
        if self._roster_logfile:
            try:
                self._roster_logfile.close()
            except Exception:
                not_closed.add('roster')
180
        log.debug('All log file handles closed')
181
182
        if not_closed:
            log.error('Unable to close log files for: %s', not_closed)
183
        for room in self._fds:
184
            self._check_and_create_log_dir(room)
185
            log.debug('Log handle for %s re-created', room)
186

187
188
    def _check_and_create_log_dir(self, jid: str,
                                  open_fd: bool = True) -> Optional[IO[str]]:
189
        """
190
191
        Check that the directory where we want to log the messages
        exists. if not, create it
192
193
194
195

        :param jid: JID of the file to open after creating the dir
        :param open_fd: if the file should be opened after creating the dir
        :returns: the opened fd or None
196
        """
197
        if not config.get_by_tabname('use_log', jid):
198
            return None
199
        try:
200
201
            self.log_dir.mkdir(parents=True, exist_ok=True)
        except OSError:
202
            log.error('Unable to create the log dir', exc_info=True)
203
        except Exception:
204
            log.error('Unable to create the log dir', exc_info=True)
205
            return None
206
        if not open_fd:
207
            return None
208
        filename = self.log_dir / jid
209
        try:
210
            fd = filename.open('a', encoding='utf-8')
211
            self._fds[jid] = fd
212
            return fd
213
        except IOError:
mathieui's avatar
mathieui committed
214
            log.error(
mathieui's avatar
mathieui committed
215
                'Unable to open the log file (%s)', filename, exc_info=True)
216
        return None
217

Link Mauve's avatar
Link Mauve committed
218
219
    def log_message(self,
                    jid: str,
220
                    msg: Union[BaseMessage, Message]) -> bool:
221
        """
222
223
224
225
226
        Log the message in the appropriate file

        :param jid: JID of the entity for which to log the message
        :param msg: Message to log
        :returns: True if no error was encountered
227
        """
228
        if not config.get_by_tabname('use_log', jid):
229
            return True
230
231
232
233
234
        if not isinstance(msg, LoggableTrait):
            return True
        date = msg.time
        txt = msg.txt
        nick = ''
235
        typ = 'MI'
236
237
        if isinstance(msg, Message):
            nick = msg.nickname or ''
238
239
            typ = 'MR'
        logged_msg = build_log_message(nick, txt, date=date, prefix=typ)
240
241
        if not logged_msg:
            return True
242
243
        return self.log_raw(jid, logged_msg)

244
    def log_raw(self, jid: Union[str, JID], logged_msg: str, force: bool = False) -> bool:
245
246
247
248
249
250
251
        """Log a raw string.

        :param jid: filename
        :param logged_msg: string to log
        :param force: Bypass the buffered fd check
        :returns: True if no error was encountered
        """
mathieui's avatar
mathieui committed
252
        jid = str(jid).replace('/', '\\')
253
254
        if jid in self._fds.keys():
            fd = self._fds[jid]
255
        else:
256
257
258
259
            option_fd = self._check_and_create_log_dir(jid)
            if option_fd is None:
                return True
            fd = option_fd
260
        filename = self.log_dir / jid
261
        try:
262
263
264
            if not force and self._busy_fds.get(jid):
                self._buffered_fds[jid].append(logged_msg)
                return True
265
266
            fd.write(logged_msg)
        except OSError:
mathieui's avatar
mathieui committed
267
268
            log.error(
                'Unable to write in the log file (%s)',
269
                filename,
mathieui's avatar
mathieui committed
270
                exc_info=True)
mathieui's avatar
mathieui committed
271
            return False
272
        else:
mathieui's avatar
mathieui committed
273
            try:
mathieui's avatar
mathieui committed
274
                fd.flush()  # TODO do something better here?
275
            except OSError:
mathieui's avatar
mathieui committed
276
277
                log.error(
                    'Unable to flush the log file (%s)',
278
                    filename,
mathieui's avatar
mathieui committed
279
                    exc_info=True)
mathieui's avatar
mathieui committed
280
281
                return False
        return True
282

Link Mauve's avatar
Link Mauve committed
283
    def log_roster_change(self, jid: str, message: str) -> bool:
284
285
        """
        Log a roster change
286
287
288
289

        :param jid: jid to log the change for
        :param message: message to log
        :returns: True if no error happened
290
        """
291
        if not config.get_by_tabname('use_log', jid):
292
            return True
293
        self._check_and_create_log_dir('', open_fd=False)
294
        filename = self.log_dir / 'roster.log'
295
        if not self._roster_logfile:
mathieui's avatar
mathieui committed
296
            try:
mathieui's avatar
mathieui committed
297
                self._roster_logfile = filename.open('a', encoding='utf-8')
mathieui's avatar
mathieui committed
298
            except IOError:
mathieui's avatar
mathieui committed
299
300
                log.error(
                    'Unable to create the log file (%s)',
301
                    filename,
mathieui's avatar
mathieui committed
302
                    exc_info=True)
mathieui's avatar
mathieui committed
303
304
                return False
        try:
305
            str_time = common.get_utc_time().strftime('%Y%m%dT%H:%M:%SZ')
306
            message = clean_text(message)
307
308
309
            lines = message.split('\n')
            first_line = lines.pop(0)
            nb_lines = str(len(lines)).zfill(3)
mathieui's avatar
mathieui committed
310
311
            self._roster_logfile.write(
                'MI %s %s %s %s\n' % (str_time, nb_lines, jid, first_line))
312
            for line in lines:
313
314
                self._roster_logfile.write(' %s\n' % line)
            self._roster_logfile.flush()
315
        except Exception:
mathieui's avatar
mathieui committed
316
317
            log.error(
                'Unable to write in the log file (%s)',
318
                filename,
mathieui's avatar
mathieui committed
319
                exc_info=True)
mathieui's avatar
mathieui committed
320
321
            return False
        return True
mathieui's avatar
mathieui committed
322

mathieui's avatar
mathieui committed
323

mathieui's avatar
mathieui committed
324
325
326
def build_log_message(nick: str,
                      msg: str,
                      date: Optional[datetime] = None,
327
                      prefix: str = 'MI') -> str:
328
329
330
    """
    Create a log message from a nick, a message, optionally a date and type

331
332
333
334
335
336
    :param nick: nickname to log
    :param msg: text of the message
    :param date: date of the message
    :param prefix: MI (info) or MR (message)
    :returns: The log line(s)
    """
337
    msg = clean_text(msg)
Link Mauve's avatar
Link Mauve committed
338
339
    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')
340
341
342
343
344
345
346
347
348
349
350
351
    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)


352
def last_message_in_archive(filepath: Path) -> Optional[LogDict]:
353
354
355
356
357
358
359
360
361
362
363
364
    """Get the last message from the local archive.

    :param filepath: the log file path
    """
    last_msg = None
    for msg in iterate_messages_reverse(filepath):
        if msg['type'] == 'message':
            last_msg = msg
            break
    return last_msg


365
def iterate_messages_reverse(filepath: Path) -> Generator[LogDict, None, None]:
366
367
368
369
370
371
372
373
374
    """Get the latest messages from the log file, one at a time.

    :param fd: the file descriptor
    """
    try:
        with open(filepath, 'rb') as fd:
            with mmap.mmap(fd.fileno(), 0, prot=mmap.PROT_READ) as m:
                # start of messages begin with MI or MR, after a \n
                pos = m.rfind(b"\nM") + 1
375
376
377
378
379
380
381
382
383
384
                if pos != -1:
                    lines = parse_log_lines(
                        m[pos:-1].decode(errors='replace').splitlines()
                    )
                elif m[0:1] == b'M':
                    # Handle the case of a single message present in the log
                    # file, hence no newline.
                    lines = parse_log_lines(
                        m[:].decode(errors='replace').splitlines()
                    )
385
386
387
388
389
390
391
392
393
394
                if lines:
                    yield lines[0]
                while pos > 0:
                    old_pos = pos
                    pos = m.rfind(b"\nM", 0, pos) + 1
                    lines = parse_log_lines(
                        m[pos:old_pos].decode(errors='replace').splitlines()
                    )
                    if lines:
                        yield lines[0]
395
    except (OSError, ValueError):
396
397
398
        pass


399
def _get_lines_from_fd(fd: IO[Any], nb: int = 10) -> List[str]:
400
    """
401
402
403
404
405
    Get the last log lines from a fileno with mmap

    :param fd: File descriptor on the log file
    :param nb: number of messages to fetch
    :returns: A list of message lines
406
407
    """
    with mmap.mmap(fd.fileno(), 0, prot=mmap.PROT_READ) as m:
408
409
        # start of messages begin with MI or MR, after a \n
        pos = m.rfind(b"\nM") + 1
410
411
        # number of message found so far
        count = 0
412
        while pos != 0 and count < nb - 1:
413
            count += 1
414
415
            pos = m.rfind(b"\nM", 0, pos) + 1
        lines = m[pos:].decode(errors='replace').splitlines()
416
417
418
    return lines


419
def parse_log_lines(lines: List[str], jid: str = '') -> List[LogDict]:
420
421
    """
    Parse raw log lines into poezio log objects
422
423
424
425

    :param lines: Message lines
    :param jid: jid (for error logging)
    :return: a list of dicts containing message info
426
427
428
429
430
431
432
433
434
435
    """
    messages = []

    # 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
436
        log_item = parse_log_line(lines[idx], jid)
437
438
439
440
        idx += 1
        if not isinstance(log_item, LogItem):
            log.debug('wrong log format? %s', log_item)
            continue
441
        message_lines = []
442
        message = LogDict({
443
            'history': True,
444
445
            'time': common.get_local_time(log_item.time),
            'type': 'message',
446
        })
447
448
        size = log_item.nb_lines
        if isinstance(log_item, LogInfo):
449
            message_lines.append(log_item.text)
450
            message['type'] = 'info'
451
452
        elif isinstance(log_item, LogMessage):
            message['nickname'] = log_item.nick
453
            message_lines.append(log_item.text)
454
        while size != 0 and idx < len(lines):
455
            message_lines.append(lines[idx][1:])
456
457
            size -= 1
            idx += 1
458
        message['txt'] = '\n'.join(message_lines)
459
460
461
462
        messages.append(message)
    return messages


mathieui's avatar
mathieui committed
463
logger = Logger()