##// END OF EJS Templates
lock: fix race in lock-breaking code...
lock: fix race in lock-breaking code With low frequency, I see hg pulls fail with output like: abort: no such file or directory: .hg/store/lock I think what happens is, in lock.py, in: def _testlock(self, locker): if not self._lockshouldbebroken(locker): return locker # if locker dead, break lock. must do this with another lock # held, or can race and break valid lock. try: with lock(self.vfs, self.f + b'.break', timeout=0): self.vfs.unlink(self.f) except error.LockError: return locker if a lock is breakable on disk, and two hg processes concurrently get to the "if locker dead" comment, a possible interleaving is: process1 finishes executing the function and then process2 finishes executing the function. If that happens, process2 will either get ENOENT in self.vfs.unlink (resulting in the spurious failure above), or break a valid lock and potentially cause repository corruption. The fix is simple enough: make sure the lock is breakable _inside_ the critical section, because only then can we know that no other process can invalidate our knowledge on the lock on disk. I don't think there are tests for this. I've tested this manually with: diff --git a/mercurial/lock.py b/mercurial/lock.py --- a/mercurial/lock.py +++ b/mercurial/lock.py @@ -351,6 +351,8 @@ class lock(object): if not self._lockshouldbebroken(locker): return locker + import random + time.sleep(1. + random.random()) # if locker dead, break lock. must do this with another lock # held, or can race and break valid lock. try: @@ -358,6 +360,7 @@ class lock(object): self.vfs.unlink(self.f) except error.LockError: return locker + time.sleep(1) def testlock(self): """return id of locker if lock is valid, else None. and I see this change of behavior before/after this commit: $ $hg init repo $ cd repo $ ln -s $HOSTNAME/effffffc:987654321 .hg/wlock $ touch a $ $hg commit -Am_ & $hg commit -Am _; wait -abort: No such file or directory: '/tmp/repo/.hg/wlock' adding a +warning: ignoring unknown working parent 679a8959a8ca! +nothing changed Differential Revision: https://phab.mercurial-scm.org/D7199

File last commit:

r43347:687b865b default
r44108:039fbd14 default
Show More
loggingutil.py
141 lines | 3.9 KiB | text/x-python | PythonLexer
# loggingutil.py - utility for logging events
#
# Copyright 2010 Nicolas Dumazet
# Copyright 2013 Facebook, Inc.
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.
from __future__ import absolute_import
import errno
from . import pycompat
from .utils import (
dateutil,
procutil,
stringutil,
)
def openlogfile(ui, vfs, name, maxfiles=0, maxsize=0):
"""Open log file in append mode, with optional rotation
If maxsize > 0, the log file will be rotated up to maxfiles.
"""
def rotate(oldpath, newpath):
try:
vfs.unlink(newpath)
except OSError as err:
if err.errno != errno.ENOENT:
ui.debug(
b"warning: cannot remove '%s': %s\n"
% (newpath, err.strerror)
)
try:
if newpath:
vfs.rename(oldpath, newpath)
except OSError as err:
if err.errno != errno.ENOENT:
ui.debug(
b"warning: cannot rename '%s' to '%s': %s\n"
% (newpath, oldpath, err.strerror)
)
if maxsize > 0:
try:
st = vfs.stat(name)
except OSError:
pass
else:
if st.st_size >= maxsize:
path = vfs.join(name)
for i in pycompat.xrange(maxfiles - 1, 1, -1):
rotate(
oldpath=b'%s.%d' % (path, i - 1),
newpath=b'%s.%d' % (path, i),
)
rotate(oldpath=path, newpath=maxfiles > 0 and path + b'.1')
return vfs(name, b'a', makeparentdirs=False)
def _formatlogline(msg):
date = dateutil.datestr(format=b'%Y/%m/%d %H:%M:%S')
pid = procutil.getpid()
return b'%s (%d)> %s' % (date, pid, msg)
def _matchevent(event, tracked):
return b'*' in tracked or event in tracked
class filelogger(object):
"""Basic logger backed by physical file with optional rotation"""
def __init__(self, vfs, name, tracked, maxfiles=0, maxsize=0):
self._vfs = vfs
self._name = name
self._trackedevents = set(tracked)
self._maxfiles = maxfiles
self._maxsize = maxsize
def tracked(self, event):
return _matchevent(event, self._trackedevents)
def log(self, ui, event, msg, opts):
line = _formatlogline(msg)
try:
with openlogfile(
ui,
self._vfs,
self._name,
maxfiles=self._maxfiles,
maxsize=self._maxsize,
) as fp:
fp.write(line)
except IOError as err:
ui.debug(
b'cannot write to %s: %s\n'
% (self._name, stringutil.forcebytestr(err))
)
class fileobjectlogger(object):
"""Basic logger backed by file-like object"""
def __init__(self, fp, tracked):
self._fp = fp
self._trackedevents = set(tracked)
def tracked(self, event):
return _matchevent(event, self._trackedevents)
def log(self, ui, event, msg, opts):
line = _formatlogline(msg)
try:
self._fp.write(line)
self._fp.flush()
except IOError as err:
ui.debug(
b'cannot write to %s: %s\n'
% (
stringutil.forcebytestr(self._fp.name),
stringutil.forcebytestr(err),
)
)
class proxylogger(object):
"""Forward log events to another logger to be set later"""
def __init__(self):
self.logger = None
def tracked(self, event):
return self.logger is not None and self.logger.tracked(event)
def log(self, ui, event, msg, opts):
assert self.logger is not None
self.logger.log(ui, event, msg, opts)