Skip to content
Snippets Groups Projects
Commit 52018f8e authored by Pierre-Yves David's avatar Pierre-Yves David :octopus:
Browse files

persistent-nodemap: introduce a test to highlight possible race

Weakness in the current file caching of the changelog means that a writer can
end up using an outdated docket. This might result in "committed"
persistent-nodemap data from a previous writer to be overwritten by a later
writer. This break the strong "append only" assumption of the persistent nodemap
and can result in confused reader.

The race windows are quite narrow. See the test documentation for details.

The issues is fixed in the next changeset.

Differential Revision: https://phab.mercurial-scm.org/D11481
parent 016081cc
No related branches found
No related tags found
No related merge requests found
......@@ -26,6 +26,14 @@
raise error.RevlogError(b'unknown node: %s' % x)
def test_race_hook_1():
"""hook point for test
This let tests to have things happens between the docket reading and the
data reading"""
pass
def persisted_data(revlog):
"""read the nodemap for a revlog from disk"""
if revlog._nodemap_file is None:
......@@ -50,6 +58,8 @@
filename = _rawdata_filepath(revlog, docket)
use_mmap = revlog.opener.options.get(b"persistent-nodemap.mmap")
test_race_hook_1()
try:
with revlog.opener(filename) as fd:
if use_mmap:
......
......@@ -613,6 +613,202 @@
$ hg id -r . --traceback
90d5d3ba2fc4 tip
(be a good citizen and regenerate the nodemap)
$ hg debugupdatecaches
$ hg debugnodemap --metadata
uid: * (glob)
tip-rev: 5005
tip-node: 90d5d3ba2fc47db50f712570487cb261a68c8ffe
data-length: 121088
data-unused: 0
data-unused: 0.000%
Check race condition when multiple process write new data to the repository
---------------------------------------------------------------------------
In this test, we check that two writers touching the repositories will not
overwrite each other data. This test is prompted by the existent of issue6554.
Where a writer ended up using and outdated docket to update the repository. See
the dedicated extension for details on the race windows and read/write schedule
necessary to end up in this situation: testlib/persistent-nodemap-race-ext.py
The issue was initially observed on a server with a high push trafic, but it
can be reproduced using a share and two commiting process which seems simpler.
The test is Rust only as the other implementation does not use the same
read/write patterns.
$ cd ..
#if rust
$ cp -R test-repo race-repo
$ hg share race-repo ./other-wc --config format.use-share-safe=yes
updating working directory
5001 files updated, 0 files merged, 0 files removed, 0 files unresolved
$ hg debugformat -R ./race-repo | egrep 'share-safe|persistent-nodemap'
share-safe: yes
persistent-nodemap: yes
$ hg debugformat -R ./other-wc/ | egrep 'share-safe|persistent-nodemap'
share-safe: yes
persistent-nodemap: yes
$ hg -R ./other-wc update 'min(head())'
3 files updated, 0 files merged, 2 files removed, 0 files unresolved
$ hg -R ./race-repo debugnodemap --metadata
uid: 43c37dde
tip-rev: 5005
tip-node: 90d5d3ba2fc47db50f712570487cb261a68c8ffe
data-length: 121088
data-unused: 0
data-unused: 0.000%
$ hg -R ./race-repo log -G -r 'head()'
@ changeset: 5005:90d5d3ba2fc4
| tag: tip
~ user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: a2
o changeset: 5001:16395c3cf7e2
| user: test
~ date: Thu Jan 01 00:00:00 1970 +0000
summary: foo
$ hg -R ./other-wc log -G -r 'head()'
o changeset: 5005:90d5d3ba2fc4
| tag: tip
~ user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: a2
@ changeset: 5001:16395c3cf7e2
| user: test
~ date: Thu Jan 01 00:00:00 1970 +0000
summary: foo
$ echo left-side-race > race-repo/left-side-race
$ hg -R ./race-repo/ add race-repo/left-side-race
$ echo right-side-race > ./other-wc/right-side-race
$ hg -R ./other-wc/ add ./other-wc/right-side-race
$ mkdir sync-files
$ mkdir outputs
$ (
> hg -R ./race-repo/ commit -m left-side-commit \
> --config "extensions.race=${RUNTESTDIR}/testlib/persistent-nodemap-race-ext.py" \
> --config 'devel.nodemap-race.role=left';
> touch sync-files/left-done
> ) > outputs/left.txt 2>&1 &
$ (
> hg -R ./other-wc/ commit -m right-side-commit \
> --config "extensions.race=${RUNTESTDIR}/testlib/persistent-nodemap-race-ext.py" \
> --config 'devel.nodemap-race.role=right';
> touch sync-files/right-done
> ) > outputs/right.txt 2>&1 &
$ (
> hg -R ./race-repo/ check-nodemap-race \
> --config "extensions.race=${RUNTESTDIR}/testlib/persistent-nodemap-race-ext.py" \
> --config 'devel.nodemap-race.role=reader';
> touch sync-files/reader-done
> ) > outputs/reader.txt 2>&1 &
$ sh "$RUNTESTDIR"/testlib/wait-on-file 10 sync-files/left-done
$ cat outputs/left.txt
docket-details:
uid: 43c37dde
actual-tip: 5005
tip-rev: 5005
data-length: 121088
nodemap-race: left side locked and ready to commit
docket-details:
uid: 43c37dde
actual-tip: 5005
tip-rev: 5005
data-length: 121088
finalized changelog write
persisting changelog nodemap
new data start at 121088
persisted changelog nodemap
docket-details:
uid: 43c37dde
actual-tip: 5006
tip-rev: 5006
data-length: 121280
$ sh "$RUNTESTDIR"/testlib/wait-on-file 10 sync-files/right-done
$ cat outputs/right.txt
nodemap-race: right side start of the locking sequence
nodemap-race: right side reading changelog
nodemap-race: right side reading of changelog is done
docket-details:
uid: 43c37dde
actual-tip: 5006
tip-rev: 5005
data-length: 121088
nodemap-race: right side ready to wait for the lock
nodemap-race: right side locked and ready to commit
docket-details:
uid: 43c37dde
actual-tip: 5006
tip-rev: 5005
data-length: 121088
right ready to write, waiting for reader
right proceeding with writing its changelog index and nodemap
finalized changelog write
persisting changelog nodemap
new data start at 121088
persisted changelog nodemap
docket-details:
uid: 43c37dde
actual-tip: 5007
tip-rev: 5007
data-length: 121472
$ sh "$RUNTESTDIR"/testlib/wait-on-file 10 sync-files/reader-done
$ cat outputs/reader.txt
reader: reading changelog
reader ready to read the changelog, waiting for right
reader: nodemap docket read
record-data-length: 121280
actual-data-length: 121280
file-actual-length: 121472
reader: changelog read
docket-details:
uid: 43c37dde
actual-tip: 5006
tip-rev: 5006
data-length: 121280
tip-rev: 5006
tip-node: 492901161367
node-rev: 5006
error while checking revision: 18 (known-bad-output !)
Inconsistency: Revision 5007 found in nodemap is not in revlog indexi (known-bad-output !)
$ hg -R ./race-repo log -G -r 'head()'
o changeset: 5007:ac4a2abde241
| tag: tip
~ parent: 5001:16395c3cf7e2
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: right-side-commit
@ changeset: 5006:492901161367
| user: test
~ date: Thu Jan 01 00:00:00 1970 +0000
summary: left-side-commit
$ hg -R ./other-wc log -G -r 'head()'
@ changeset: 5007:ac4a2abde241
| tag: tip
~ parent: 5001:16395c3cf7e2
user: test
date: Thu Jan 01 00:00:00 1970 +0000
summary: right-side-commit
o changeset: 5006:492901161367
| user: test
~ date: Thu Jan 01 00:00:00 1970 +0000
summary: left-side-commit
#endif
Test upgrade / downgrade
========================
......@@ -616,6 +812,8 @@
Test upgrade / downgrade
========================
$ cd ./test-repo/
downgrading
$ cat << EOF >> .hg/hgrc
......
"""Create the race condition for issue6554
The persistent nodemap issues had an issue where a second writer could
overwrite the data that a previous write just wrote. The would break the append
only garantee of the persistent nodemap and could confuse reader. This
extensions create all the necessary synchronisation point to the race condition
to happen.
It involves 3 process <LEFT> (a writer) <RIGHT> (a writer) and <READER>
[1] <LEFT> take the lock and start a transaction
[2] <LEFT> updated `00changelog.i` with the new data
[3] <RIGHT> reads:
- the new changelog index `00changelog.i`
- the old `00changelog.n`
[4] <LEFT> update the persistent nodemap:
- writing new data from the last valid offset
- updating the docket (00changelog.n)
[5] <LEFT> release the lock
[6] <RIGHT> grab the lock and run `repo.invalidate`
[7] <READER> reads:
- the changelog index after <LEFT> write
- the nodemap docket after <LEFT> write
[8] <RIGHT> reload the changelog since `00changelog.n` changed
/!\ This is the faulty part in issue 6554, the outdated docket is kept
[9] <RIGHT> write:
- the changelog index (00changelog.i)
- the nodemap data (00changelog*.nd)
/!\ if the outdated docket is used, the write starts from the same ofset
/!\ as in [4], overwriting data that <LEFT> wrote in step [4].
- the nodemap docket (00changelog.n)
[10] <READER> reads the nodemap data from `00changelog*.nd`
/!\ if step [9] was wrong, the data matching the docket that <READER>
/!\ loaded have been overwritten and the expected root-nodes is no longer
/!\ valid.
"""
from __future__ import print_function
import os
from mercurial.revlogutils.constants import KIND_CHANGELOG
from mercurial import (
changelog,
encoding,
extensions,
localrepo,
node,
pycompat,
registrar,
testing,
util,
)
from mercurial.revlogutils import (
nodemap as nodemaputil,
)
configtable = {}
configitem = registrar.configitem(configtable)
configitem(b'devel', b'nodemap-race.role', default=None)
cmdtable = {}
command = registrar.command(cmdtable)
LEFT = b'left'
RIGHT = b'right'
READER = b'reader'
SYNC_DIR = os.path.join(encoding.environ[b'TESTTMP'], b'sync-files')
# mark the end of step [1]
FILE_LEFT_LOCKED = os.path.join(SYNC_DIR, b'left-locked')
# mark that step [3] is ready to run.
FILE_RIGHT_READY_TO_LOCK = os.path.join(SYNC_DIR, b'right-ready-to-lock')
# mark the end of step [2]
FILE_LEFT_CL_DATA_WRITE = os.path.join(SYNC_DIR, b'left-data')
# mark the end of step [4]
FILE_LEFT_CL_NODEMAP_WRITE = os.path.join(SYNC_DIR, b'left-nodemap')
# mark the end of step [3]
FILE_RIGHT_CL_NODEMAP_READ = os.path.join(SYNC_DIR, b'right-nodemap')
# mark that step [9] is read to run
FILE_RIGHT_CL_NODEMAP_PRE_WRITE = os.path.join(
SYNC_DIR, b'right-pre-nodemap-write'
)
# mark that step [9] has run.
FILE_RIGHT_CL_NODEMAP_POST_WRITE = os.path.join(
SYNC_DIR, b'right-post-nodemap-write'
)
# mark that step [7] is ready to run
FILE_READER_READY = os.path.join(SYNC_DIR, b'reader-ready')
# mark that step [7] has run
FILE_READER_READ_DOCKET = os.path.join(SYNC_DIR, b'reader-read-docket')
def _print(*args, **kwargs):
print(*args, **kwargs)
def _role(repo):
"""find the role associated with the process"""
return repo.ui.config(b'devel', b'nodemap-race.role')
def wrap_changelog_finalize(orig, cl, tr):
"""wrap the update of `00changelog.i` during transaction finalization
This is useful for synchronisation before or after the file is updated on disk.
"""
role = getattr(tr, '_race_role', None)
if role == RIGHT:
print('right ready to write, waiting for reader')
testing.wait_file(FILE_READER_READY)
testing.write_file(FILE_RIGHT_CL_NODEMAP_PRE_WRITE)
testing.wait_file(FILE_READER_READ_DOCKET)
print('right proceeding with writing its changelog index and nodemap')
ret = orig(cl, tr)
print("finalized changelog write")
if role == LEFT:
testing.write_file(FILE_LEFT_CL_DATA_WRITE)
return ret
def wrap_persist_nodemap(orig, tr, revlog, *args, **kwargs):
"""wrap the update of `00changelog.n` and `*.nd` during tr finalization
This is useful for synchronisation before or after the files are updated on
disk.
"""
is_cl = revlog.target[0] == KIND_CHANGELOG
role = getattr(tr, '_race_role', None)
if is_cl:
if role == LEFT:
testing.wait_file(FILE_RIGHT_CL_NODEMAP_READ)
if is_cl:
print("persisting changelog nodemap")
print(" new data start at", revlog._nodemap_docket.data_length)
ret = orig(tr, revlog, *args, **kwargs)
if is_cl:
print("persisted changelog nodemap")
print_nodemap_details(revlog)
if role == LEFT:
testing.write_file(FILE_LEFT_CL_NODEMAP_WRITE)
elif role == RIGHT:
testing.write_file(FILE_RIGHT_CL_NODEMAP_POST_WRITE)
return ret
def print_nodemap_details(cl):
"""print relevant information about the nodemap docket currently in memory"""
dkt = cl._nodemap_docket
print('docket-details:')
if dkt is None:
print(' <no-docket>')
return
print(' uid: ', pycompat.sysstr(dkt.uid))
print(' actual-tip: ', cl.tiprev())
print(' tip-rev: ', dkt.tip_rev)
print(' data-length:', dkt.data_length)
def wrap_persisted_data(orig, revlog):
"""print some information about the nodemap information we just read
Used by the <READER> process only.
"""
ret = orig(revlog)
if ret is not None:
docket, data = ret
file_path = nodemaputil._rawdata_filepath(revlog, docket)
file_path = revlog.opener.join(file_path)
file_size = os.path.getsize(file_path)
print('record-data-length:', docket.data_length)
print('actual-data-length:', len(data))
print('file-actual-length:', file_size)
return ret
def sync_read(orig):
"""used by <READER> to force the race window
This make sure we read the docker from <LEFT> while reading the datafile
after <RIGHT> write.
"""
orig()
testing.write_file(FILE_READER_READ_DOCKET)
print('reader: nodemap docket read')
testing.wait_file(FILE_RIGHT_CL_NODEMAP_POST_WRITE)
def uisetup(ui):
class RacedRepo(localrepo.localrepository):
def lock(self, wait=True):
# make sure <RIGHT> as the "Wrong" information in memory before
# grabbing the lock
newlock = self._currentlock(self._lockref) is None
if newlock and _role(self) == LEFT:
cl = self.unfiltered().changelog
print_nodemap_details(cl)
elif newlock and _role(self) == RIGHT:
testing.write_file(FILE_RIGHT_READY_TO_LOCK)
print('nodemap-race: right side start of the locking sequence')
testing.wait_file(FILE_LEFT_LOCKED)
testing.wait_file(FILE_LEFT_CL_DATA_WRITE)
self.invalidate(clearfilecache=True)
print('nodemap-race: right side reading changelog')
cl = self.unfiltered().changelog
tiprev = cl.tiprev()
tip = cl.node(tiprev)
tiprev2 = cl.rev(tip)
if tiprev != tiprev2:
raise RuntimeError(
'bad tip -round-trip %d %d' % (tiprev, tiprev2)
)
testing.write_file(FILE_RIGHT_CL_NODEMAP_READ)
print('nodemap-race: right side reading of changelog is done')
print_nodemap_details(cl)
testing.wait_file(FILE_LEFT_CL_NODEMAP_WRITE)
print('nodemap-race: right side ready to wait for the lock')
ret = super(RacedRepo, self).lock(wait=wait)
if newlock and _role(self) == LEFT:
print('nodemap-race: left side locked and ready to commit')
testing.write_file(FILE_LEFT_LOCKED)
testing.wait_file(FILE_RIGHT_READY_TO_LOCK)
cl = self.unfiltered().changelog
print_nodemap_details(cl)
elif newlock and _role(self) == RIGHT:
print('nodemap-race: right side locked and ready to commit')
cl = self.unfiltered().changelog
print_nodemap_details(cl)
return ret
def transaction(self, *args, **kwargs):
# duck punch the role on the transaction to help other pieces of code
tr = super(RacedRepo, self).transaction(*args, **kwargs)
tr._race_role = _role(self)
return tr
localrepo.localrepository = RacedRepo
extensions.wrapfunction(
nodemaputil, 'persist_nodemap', wrap_persist_nodemap
)
extensions.wrapfunction(
changelog.changelog, '_finalize', wrap_changelog_finalize
)
def reposetup(ui, repo):
if _role(repo) == READER:
extensions.wrapfunction(
nodemaputil, 'persisted_data', wrap_persisted_data
)
extensions.wrapfunction(nodemaputil, 'test_race_hook_1', sync_read)
class ReaderRepo(repo.__class__):
@util.propertycache
def changelog(self):
print('reader ready to read the changelog, waiting for right')
testing.write_file(FILE_READER_READY)
testing.wait_file(FILE_RIGHT_CL_NODEMAP_PRE_WRITE)
return super(ReaderRepo, self).changelog
repo.__class__ = ReaderRepo
@command(b'check-nodemap-race')
def cmd_check_nodemap_race(ui, repo):
"""Run proper <READER> access in the race Windows and check nodemap content"""
repo = repo.unfiltered()
print('reader: reading changelog')
cl = repo.changelog
print('reader: changelog read')
print_nodemap_details(cl)
tip_rev = cl.tiprev()
tip_node = cl.node(tip_rev)
print('tip-rev: ', tip_rev)
print('tip-node:', node.short(tip_node).decode('ascii'))
print('node-rev:', cl.rev(tip_node))
for r in cl.revs():
n = cl.node(r)
try:
r2 = cl.rev(n)
except ValueError as exc:
print('error while checking revision:', r)
print(' ', exc)
return 1
else:
if r2 != r:
print('revision %d is missing from the nodemap' % r)
return 1
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment