#!/usr/bin/env python
# Copyright 2012 Lars Wirzenius
#
# This program is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program. If not, see .
'''Check lock file usage from log files.
This program reads a number of Obnam log files, produced with tracing
for obnamlib, and analyses them for bugs when using lock files. Each
log file is assumed to be produced by a separate Obnam instance.
* Have any instances held the same lock during overlapping periods?
'''
import cliapp
import logging
import os
import re
import time
import ttystatus
timestamp_pat = \
r'^\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d (?P\d+\.\d+) .*'
lock_pat = re.compile(
timestamp_pat +
r'vfs_local.py:[0-9]*:lock: got lockname=(?P.*)')
unlock_pat = re.compile(
timestamp_pat +
r'vfs_local.py:[0-9]*:unlock: lockname=(?P.*)')
writefile_pat = re.compile(
timestamp_pat +
r'vfs_local.py:[0-9]*:write_file: write_file (?P.*)$')
overwritefile_pat = re.compile(
timestamp_pat +
r'vfs_local.py:[0-9]*:overwrite_file: overwrite_file (?P.*)$')
node_open_pat = re.compile(
timestamp_pat +
r'nodestore_disk.py:\d+:get_node: reading node \d+ from file '
r'(?P.*)$')
node_remove_pat = re.compile(
timestamp_pat +
r'vfs_local.py:\d+:remove: remove (?P.*/nodes/.*)$')
rename_pat = re.compile(
timestamp_pat +
r'vfs_local.py:\d+:rename: rename (?P\S+) (?P\S+)$')
class LogEvent(object):
def __init__(self, logfile, lineno, timestamp):
self.logfile = logfile
self.lineno = lineno
self.timestamp = timestamp
def sortkey(self):
return self.timestamp
class LockEvent(LogEvent):
def __init__(self, logfile, lineno, timestamp, lockname):
LogEvent.__init__(self, logfile, lineno, timestamp)
self.lockname = lockname
def __str__(self):
return 'Lock(%s)' % self.lockname
class UnlockEvent(LockEvent):
def __str__(self):
return 'Unlock(%s)' % self.lockname
class WriteFileEvent(LogEvent):
def __init__(self, logfile, lineno, timestamp, filename):
LogEvent.__init__(self, logfile, lineno, timestamp)
self.filename = filename
def __str__(self):
return 'WriteFile(%s)' % self.filename
class OverwriteFileEvent(WriteFileEvent):
def __str__(self):
return 'OverwriteFile(%s)' % self.filename
class NodeCreateEvent(LogEvent):
def __init__(self, logfile, lineno, timestamp, node_id):
LogEvent.__init__(self, logfile, lineno, timestamp)
self.node_id = node_id
def __str__(self):
return 'NodeCreate(%s)' % self.node_id
class NodeDestroyEvent(NodeCreateEvent):
def __str__(self):
return 'NodeDestroy(%s)' % self.node_id
class NodeReadEvent(NodeCreateEvent):
def __str__(self):
return 'NodeOpen(%s)' % self.node_id
class RenameEvent(LogEvent):
def __init__(self, logfile, lineno, timestamp, old, new):
LogEvent.__init__(self, logfile, lineno, timestamp)
self.old = old
self.new = new
def __str__(self):
return 'Rename(%s -> %s)' % (self.old, self.new)
class CheckLocks(cliapp.Application):
def setup(self):
self.events = []
self.errors = 0
self.latest_opened_node = None
self.patterns = [
(lock_pat, self.lock_event),
(unlock_pat, self.unlock_event),
(writefile_pat, self.writefile_event),
(overwritefile_pat, self.overwritefile_event),
(node_open_pat, self.read_node_event),
(node_remove_pat, self.node_remove_event),
(rename_pat, self.rename_event),
]
self.ts = ttystatus.TerminalStatus()
self.ts.format(
'Reading %ElapsedTime() %Integer(lines): %Pathname(filename)')
self.ts['lines'] = 0
def cleanup(self):
self.ts.clear()
self.analyse_phase_1()
self.ts.finish()
if self.errors:
raise cliapp.AppException('There were %d errors' % self.errors)
def error(self, msg):
logging.error(msg)
self.ts.error(msg)
self.errors += 1
def analyse_phase_1(self):
self.events.sort(key=lambda e: e.sortkey())
self.events = self.create_node_events(self.events)
self.ts.format('Phase 1: %Index(event,events)')
self.ts['events'] = self.events
self.ts.flush()
current_locks = set()
current_nodes = set()
for e in self.events:
self.ts['event'] = e
logging.debug(
'analysing: %s:%s: %s: %s' %
(e.logfile, e.lineno, repr(e.sortkey()), str(e)))
if type(e) is LockEvent:
if e.lockname in current_locks:
self.error(
'Re-locking %s: %s:%s:%s' %
(e.lockname, e.logfile, e.lineno,
e.timestamp))
else:
current_locks.add(e.lockname)
elif type(e) is UnlockEvent:
if e.lockname not in current_locks:
self.error(
'Unlocking %s which was not locked: %s:%s:%s' %
(e.lockname, e.logfile, e.lineno,
e.timestamp))
else:
current_locks.remove(e.lockname)
elif type(e) in (WriteFileEvent, OverwriteFileEvent):
lockname = self.determine_lockfile(e.filename)
if lockname and lockname not in current_locks:
self.error(
'%s:%s: '
'Write to file %s despite lock %s not existing' %
(e.logfile, e.lineno, e.filename, lockname))
elif type(e) is NodeCreateEvent:
if e.node_id in current_nodes:
self.error(
'%s:%s: Node %s already exists' %
(e.logfile, e.lineno, e.node_id))
else:
current_nodes.add(e.node_id)
elif type(e) is NodeDestroyEvent:
if e.node_id not in current_nodes:
self.error(
'%s:%s: Node %s does not exist' %
(e.logfile, e.lineno, e.node_id))
else:
current_nodes.remove(e.node_id)
elif type(e) is NodeReadEvent:
if e.node_id not in current_nodes:
self.error(
'%s:%s: Node %s does not exist' %
(e.logfile, e.lineno, e.node_id))
elif type(e) is RenameEvent:
if e.old in current_nodes:
current_nodes.remove(e.old)
current_nodes.add(e.new)
else:
raise NotImplementedError()
def create_node_events(self, events):
new = []
for e in events:
new.append(e)
if type(e) in (WriteFileEvent, OverwriteFileEvent):
if '/nodes/' in e.filename:
new_e = NodeCreateEvent(
e.logfile, e.lineno, e.timestamp, e.filename)
new_e.timestamp = e.timestamp
new.append(new_e)
return new
def determine_lockfile(self, filename):
if filename.endswith('/lock'):
return None
toplevel = filename.split('/')[0]
if toplevel == 'chunks':
return None
if toplevel in ('metadata', 'clientlist'):
return './lock'
return toplevel + '/lock'
def process_input(self, name):
self.ts['filename'] = name
return cliapp.Application.process_input(self, name)
def process_input_line(self, filename, line):
self.ts['lines'] = self.global_lineno
for pat, func in self.patterns:
m = pat.search(line)
if m:
event = func(filename, line, m)
if event is not None:
self.events.append(event)
def lock_event(self, filename, line, match):
return LockEvent(
filename, self.lineno, float(match.group('timestamp')),
match.group('lock'))
def unlock_event(self, filename, line, match):
return UnlockEvent(
filename, self.lineno, float(match.group('timestamp')),
match.group('lock'))
def writefile_event(self, filename, line, match):
return WriteFileEvent(
filename, self.lineno, float(match.group('timestamp')),
match.group('filename'))
def overwritefile_event(self, filename, line, match):
return OverwriteFileEvent(
filename, self.lineno, float(match.group('timestamp')),
match.group('filename'))
def read_node_event(self, filename, line, match):
node_id = match.group('nodeid')
if not os.path.basename(node_id).startswith('tmp'):
return NodeReadEvent(
filename, self.lineno, float(match.group('timestamp')),
node_id)
def node_remove_event(self, filename, line, match):
return NodeDestroyEvent(
filename, self.lineno, float(match.group('timestamp')),
match.group('nodeid'))
def rename_event(self, filename, line, match):
return RenameEvent(
filename, self.lineno, float(match.group('timestamp')),
match.group('old'), match.group('new'))
CheckLocks().run()