pep/poezio
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Refactor logger.py to make it more testable

Browse source 
Also fixes:
- release the message log mmap when we are done with it
- Write the right character in log lines
This commit is contained in:
mathieui 2017-11-21 21:24:10 +01:00
parent 094c62750f
commit 057f7ac9f5
No known key found for this signature in database
GPG key ID: C59F84CEEFD616E3
3 changed files with 120 additions and 80 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
Makefile
View file

@ -24,7 +24,7 @@ doc:
make -C doc/ html
test:
py.test -v test/
py.test test/
release:
rm -fr $(TMPDIR)/poezio-$(version)

174
poezio/logger.py
View file

@ -171,60 +171,14 @@ class Logger(object):
# do that efficiently, instead of seek()s and read()s which are costly.
with fd:
try:
m = mmap.mmap(fd.fileno(), 0, prot=mmap.PROT_READ)
lines = get_lines_from_fd(fd, nb=nb)
except Exception: # file probably empty
log.error(
'Unable to mmap the log file for (%s)',
os.path.join(log_dir, jid),
exc_info=True)
return
pos = m.rfind(b"\nM") # start of messages begin with MI or MR,
# after a \n
# number of message found so far
count = 0
while pos != -1 and count < nb - 1:
count += 1
pos = m.rfind(b"\nM", 0, pos)
if pos == -1: # If we don't have enough lines in the file
pos = 1 # 1, because we do -1 just on the next line
# to get 0 (start of the file)
lines = m[pos - 1:].decode(errors='replace').splitlines()
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
log_item = parse_log_line(lines[idx])
idx += 1
if not isinstance(log_item, LogItem):
log.debug('wrong log format? %s', log_item)
continue
message = {
'lines': [],
'history': True,
'time': common.get_local_time(log_item.time)
}
size = log_item.nb_lines
if isinstance(log_item, LogInfo):
message['lines'].append(color + log_item.text)
elif isinstance(log_item, LogMessage):
message['nickname'] = log_item.nick
message['lines'].append(color + log_item.text)
while size != 0 and idx < len(lines):
message['lines'].append(lines[idx][1:])
size -= 1
idx += 1
message['txt'] = '\n'.join(message['lines'])
del message['lines']
messages.append(message)
return messages
return parse_log_lines(lines)
def log_message(self, jid, nick, msg, date=None, typ=1):
"""
@ -234,12 +188,11 @@ class Logger(object):
1 = Message
2 = Status/whatever
"""
if not typ:
return True
jid = str(jid).replace('/', '\\')
if not config.get_by_tabname('use_log', jid):
return True
logged_msg = build_log_message(nick, msg, date=date, typ=typ)
if not logged_msg:
return True
if jid in self._fds.keys():
fd = self._fds[jid]
else:
@ -247,30 +200,8 @@ class Logger(object):
if not fd:
return True
try:
msg = clean_text(msg)
if date is None:
str_time = common.get_utc_time().strftime('%Y%m%dT%H:%M:%SZ')
else:
str_time = common.get_utc_time(date).strftime(
'%Y%m%dT%H:%M:%SZ')
if typ == 1:
prefix = 'MR'
else:
prefix = 'MI'
lines = msg.split('\n')
first_line = lines.pop(0)
nb_lines = str(len(lines)).zfill(3)
if nick:
nick = '<' + nick + '>'
fd.write('%s %s %s %s %s\n' % (prefix, str_time, nb_lines,
nick, first_line))
else:
fd.write('%s %s %s %s\n' % (prefix, str_time, nb_lines,
first_line))
for line in lines:
fd.write(' %s\n' % line)
except:
fd.write(logged_msg)
except OSError:
log.error(
'Unable to write in the log file (%s)',
os.path.join(log_dir, jid),
@ -324,6 +255,97 @@ class Logger(object):
return True
def build_log_message(nick, msg, date=None, typ=1):
"""
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)
if date is None:
str_time = common.get_utc_time().strftime('%Y%m%dT%H:%M:%SZ')
else:
str_time = common.get_utc_time(date).strftime('%Y%m%dT%H:%M:%SZ')
if typ == 1:
prefix = 'MR'
else:
prefix = 'MI'
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)
def get_lines_from_fd(fd, nb=10):
"""
Get the last log lines from a fileno
"""
with mmap.mmap(fd.fileno(), 0, prot=mmap.PROT_READ) as m:
pos = m.rfind(b"\nM") # start of messages begin with MI or MR,
# after a \n
# number of message found so far
count = 0
while pos != -1 and count < nb - 1:
count += 1
pos = m.rfind(b"\nM", 0, pos)
if pos == -1: # If we don't have enough lines in the file
pos = 1 # 1, because we do -1 just on the next line
# to get 0 (start of the file)
lines = m[pos - 1:].decode(errors='replace').splitlines()
return lines
def parse_log_lines(lines):
"""
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
log_item = parse_log_line(lines[idx])
idx += 1
if not isinstance(log_item, LogItem):
log.debug('wrong log format? %s', log_item)
continue
message = {
'lines': [],
'history': True,
'time': common.get_local_time(log_item.time)
}
size = log_item.nb_lines
if isinstance(log_item, LogInfo):
message['lines'].append(color + log_item.text)
elif isinstance(log_item, LogMessage):
message['nickname'] = log_item.nick
message['lines'].append(color + log_item.text)
while size != 0 and idx < len(lines):
message['lines'].append(lines[idx][1:])
size -= 1
idx += 1
message['txt'] = '\n'.join(message['lines'])
del message['lines']
messages.append(message)
return messages
def create_logger():
"Create the global logger object"
global logger

24
test/test_logger.py
View file

@ -1,15 +1,33 @@
"""
Test the functions in the `logger` module
"""
from poezio.logger import LogMessage, parse_log_line
import datetime
from poezio.logger import LogMessage, parse_log_line, parse_log_lines, build_log_message
from poezio.common import get_utc_time, get_local_time
def test_parse_message():
line = 'MR 20170909T09:09:09Z 000 <nick>  body'
assert vars(parse_log_line(line)) == vars(LogMessage('2017', '09', '09', '09', '09', '09', '0', 'nick', 'body'))
line = '<>'
assert parse_log_line(line) == None
assert parse_log_line(line) is None
line = 'MR 20170908T07:05:04Z 003 <nick>  '
assert vars(parse_log_line(line)) == vars(LogMessage('2017', '09', '08', '07', '05', '04', '003', 'nick', ''))
def test_log_and_parse_messages():
msg1 = {'nick': 'toto', 'msg': 'coucou', 'date': datetime.datetime.now().replace(microsecond=0)}
msg1_utc = get_utc_time(msg1['date'])
built_msg1 = build_log_message(**msg1)
assert built_msg1 == 'MR %s 000 <toto>  coucou\n' % (msg1_utc.strftime('%Y%m%dT%H:%M:%SZ'))
msg2 = {'nick': 'toto', 'msg': 'coucou\ncoucou', 'date': datetime.datetime.now().replace(microsecond=0)}
built_msg2 = build_log_message(**msg2)
msg2_utc = get_utc_time(msg2['date'])
assert built_msg2 == 'MR %s 001 <toto>  coucou\n coucou\n' % (msg2_utc.strftime('%Y%m%dT%H:%M:%SZ'))
assert parse_log_lines((built_msg1 + built_msg2).split('\n')) == [
{'time': msg1['date'], 'history': True, 'txt': '\x195,-1}coucou', 'nickname': 'toto'},
{'time': msg2['date'], 'history': True, 'txt': '\x195,-1}coucou\ncoucou', 'nickname': 'toto'},
]