##// END OF EJS Templates
persistent-nodemap: introduce a test to highlight possible race...
marmoute -
r48852:52018f8e stable
parent child Browse files
Show More
@@ -0,0 +1,294 b''
1 """Create the race condition for issue6554
2
3 The persistent nodemap issues had an issue where a second writer could
4 overwrite the data that a previous write just wrote. The would break the append
5 only garantee of the persistent nodemap and could confuse reader. This
6 extensions create all the necessary synchronisation point to the race condition
7 to happen.
8
9 It involves 3 process <LEFT> (a writer) <RIGHT> (a writer) and <READER>
10
11 [1] <LEFT> take the lock and start a transaction
12 [2] <LEFT> updated `00changelog.i` with the new data
13 [3] <RIGHT> reads:
14 - the new changelog index `00changelog.i`
15 - the old `00changelog.n`
16 [4] <LEFT> update the persistent nodemap:
17 - writing new data from the last valid offset
18 - updating the docket (00changelog.n)
19 [5] <LEFT> release the lock
20 [6] <RIGHT> grab the lock and run `repo.invalidate`
21 [7] <READER> reads:
22 - the changelog index after <LEFT> write
23 - the nodemap docket after <LEFT> write
24 [8] <RIGHT> reload the changelog since `00changelog.n` changed
25 /!\ This is the faulty part in issue 6554, the outdated docket is kept
26 [9] <RIGHT> write:
27 - the changelog index (00changelog.i)
28 - the nodemap data (00changelog*.nd)
29 /!\ if the outdated docket is used, the write starts from the same ofset
30 /!\ as in [4], overwriting data that <LEFT> wrote in step [4].
31 - the nodemap docket (00changelog.n)
32 [10] <READER> reads the nodemap data from `00changelog*.nd`
33 /!\ if step [9] was wrong, the data matching the docket that <READER>
34 /!\ loaded have been overwritten and the expected root-nodes is no longer
35 /!\ valid.
36 """
37
38 from __future__ import print_function
39
40 import os
41
42 from mercurial.revlogutils.constants import KIND_CHANGELOG
43
44 from mercurial import (
45 changelog,
46 encoding,
47 extensions,
48 localrepo,
49 node,
50 pycompat,
51 registrar,
52 testing,
53 util,
54 )
55
56 from mercurial.revlogutils import (
57 nodemap as nodemaputil,
58 )
59
60 configtable = {}
61 configitem = registrar.configitem(configtable)
62
63 configitem(b'devel', b'nodemap-race.role', default=None)
64
65 cmdtable = {}
66 command = registrar.command(cmdtable)
67
68 LEFT = b'left'
69 RIGHT = b'right'
70 READER = b'reader'
71
72 SYNC_DIR = os.path.join(encoding.environ[b'TESTTMP'], b'sync-files')
73
74 # mark the end of step [1]
75 FILE_LEFT_LOCKED = os.path.join(SYNC_DIR, b'left-locked')
76 # mark that step [3] is ready to run.
77 FILE_RIGHT_READY_TO_LOCK = os.path.join(SYNC_DIR, b'right-ready-to-lock')
78
79 # mark the end of step [2]
80 FILE_LEFT_CL_DATA_WRITE = os.path.join(SYNC_DIR, b'left-data')
81 # mark the end of step [4]
82 FILE_LEFT_CL_NODEMAP_WRITE = os.path.join(SYNC_DIR, b'left-nodemap')
83 # mark the end of step [3]
84 FILE_RIGHT_CL_NODEMAP_READ = os.path.join(SYNC_DIR, b'right-nodemap')
85 # mark that step [9] is read to run
86 FILE_RIGHT_CL_NODEMAP_PRE_WRITE = os.path.join(
87 SYNC_DIR, b'right-pre-nodemap-write'
88 )
89 # mark that step [9] has run.
90 FILE_RIGHT_CL_NODEMAP_POST_WRITE = os.path.join(
91 SYNC_DIR, b'right-post-nodemap-write'
92 )
93 # mark that step [7] is ready to run
94 FILE_READER_READY = os.path.join(SYNC_DIR, b'reader-ready')
95 # mark that step [7] has run
96 FILE_READER_READ_DOCKET = os.path.join(SYNC_DIR, b'reader-read-docket')
97
98
99 def _print(*args, **kwargs):
100 print(*args, **kwargs)
101
102
103 def _role(repo):
104 """find the role associated with the process"""
105 return repo.ui.config(b'devel', b'nodemap-race.role')
106
107
108 def wrap_changelog_finalize(orig, cl, tr):
109 """wrap the update of `00changelog.i` during transaction finalization
110
111 This is useful for synchronisation before or after the file is updated on disk.
112 """
113 role = getattr(tr, '_race_role', None)
114 if role == RIGHT:
115 print('right ready to write, waiting for reader')
116 testing.wait_file(FILE_READER_READY)
117 testing.write_file(FILE_RIGHT_CL_NODEMAP_PRE_WRITE)
118 testing.wait_file(FILE_READER_READ_DOCKET)
119 print('right proceeding with writing its changelog index and nodemap')
120 ret = orig(cl, tr)
121 print("finalized changelog write")
122 if role == LEFT:
123 testing.write_file(FILE_LEFT_CL_DATA_WRITE)
124 return ret
125
126
127 def wrap_persist_nodemap(orig, tr, revlog, *args, **kwargs):
128 """wrap the update of `00changelog.n` and `*.nd` during tr finalization
129
130 This is useful for synchronisation before or after the files are updated on
131 disk.
132 """
133 is_cl = revlog.target[0] == KIND_CHANGELOG
134 role = getattr(tr, '_race_role', None)
135 if is_cl:
136 if role == LEFT:
137 testing.wait_file(FILE_RIGHT_CL_NODEMAP_READ)
138 if is_cl:
139 print("persisting changelog nodemap")
140 print(" new data start at", revlog._nodemap_docket.data_length)
141 ret = orig(tr, revlog, *args, **kwargs)
142 if is_cl:
143 print("persisted changelog nodemap")
144 print_nodemap_details(revlog)
145 if role == LEFT:
146 testing.write_file(FILE_LEFT_CL_NODEMAP_WRITE)
147 elif role == RIGHT:
148 testing.write_file(FILE_RIGHT_CL_NODEMAP_POST_WRITE)
149 return ret
150
151
152 def print_nodemap_details(cl):
153 """print relevant information about the nodemap docket currently in memory"""
154 dkt = cl._nodemap_docket
155 print('docket-details:')
156 if dkt is None:
157 print(' <no-docket>')
158 return
159 print(' uid: ', pycompat.sysstr(dkt.uid))
160 print(' actual-tip: ', cl.tiprev())
161 print(' tip-rev: ', dkt.tip_rev)
162 print(' data-length:', dkt.data_length)
163
164
165 def wrap_persisted_data(orig, revlog):
166 """print some information about the nodemap information we just read
167
168 Used by the <READER> process only.
169 """
170 ret = orig(revlog)
171 if ret is not None:
172 docket, data = ret
173 file_path = nodemaputil._rawdata_filepath(revlog, docket)
174 file_path = revlog.opener.join(file_path)
175 file_size = os.path.getsize(file_path)
176 print('record-data-length:', docket.data_length)
177 print('actual-data-length:', len(data))
178 print('file-actual-length:', file_size)
179 return ret
180
181
182 def sync_read(orig):
183 """used by <READER> to force the race window
184
185 This make sure we read the docker from <LEFT> while reading the datafile
186 after <RIGHT> write.
187 """
188 orig()
189 testing.write_file(FILE_READER_READ_DOCKET)
190 print('reader: nodemap docket read')
191 testing.wait_file(FILE_RIGHT_CL_NODEMAP_POST_WRITE)
192
193
194 def uisetup(ui):
195 class RacedRepo(localrepo.localrepository):
196 def lock(self, wait=True):
197 # make sure <RIGHT> as the "Wrong" information in memory before
198 # grabbing the lock
199 newlock = self._currentlock(self._lockref) is None
200 if newlock and _role(self) == LEFT:
201 cl = self.unfiltered().changelog
202 print_nodemap_details(cl)
203 elif newlock and _role(self) == RIGHT:
204 testing.write_file(FILE_RIGHT_READY_TO_LOCK)
205 print('nodemap-race: right side start of the locking sequence')
206 testing.wait_file(FILE_LEFT_LOCKED)
207 testing.wait_file(FILE_LEFT_CL_DATA_WRITE)
208 self.invalidate(clearfilecache=True)
209 print('nodemap-race: right side reading changelog')
210 cl = self.unfiltered().changelog
211 tiprev = cl.tiprev()
212 tip = cl.node(tiprev)
213 tiprev2 = cl.rev(tip)
214 if tiprev != tiprev2:
215 raise RuntimeError(
216 'bad tip -round-trip %d %d' % (tiprev, tiprev2)
217 )
218 testing.write_file(FILE_RIGHT_CL_NODEMAP_READ)
219 print('nodemap-race: right side reading of changelog is done')
220 print_nodemap_details(cl)
221 testing.wait_file(FILE_LEFT_CL_NODEMAP_WRITE)
222 print('nodemap-race: right side ready to wait for the lock')
223 ret = super(RacedRepo, self).lock(wait=wait)
224 if newlock and _role(self) == LEFT:
225 print('nodemap-race: left side locked and ready to commit')
226 testing.write_file(FILE_LEFT_LOCKED)
227 testing.wait_file(FILE_RIGHT_READY_TO_LOCK)
228 cl = self.unfiltered().changelog
229 print_nodemap_details(cl)
230 elif newlock and _role(self) == RIGHT:
231 print('nodemap-race: right side locked and ready to commit')
232 cl = self.unfiltered().changelog
233 print_nodemap_details(cl)
234 return ret
235
236 def transaction(self, *args, **kwargs):
237 # duck punch the role on the transaction to help other pieces of code
238 tr = super(RacedRepo, self).transaction(*args, **kwargs)
239 tr._race_role = _role(self)
240 return tr
241
242 localrepo.localrepository = RacedRepo
243
244 extensions.wrapfunction(
245 nodemaputil, 'persist_nodemap', wrap_persist_nodemap
246 )
247 extensions.wrapfunction(
248 changelog.changelog, '_finalize', wrap_changelog_finalize
249 )
250
251
252 def reposetup(ui, repo):
253 if _role(repo) == READER:
254 extensions.wrapfunction(
255 nodemaputil, 'persisted_data', wrap_persisted_data
256 )
257 extensions.wrapfunction(nodemaputil, 'test_race_hook_1', sync_read)
258
259 class ReaderRepo(repo.__class__):
260 @util.propertycache
261 def changelog(self):
262 print('reader ready to read the changelog, waiting for right')
263 testing.write_file(FILE_READER_READY)
264 testing.wait_file(FILE_RIGHT_CL_NODEMAP_PRE_WRITE)
265 return super(ReaderRepo, self).changelog
266
267 repo.__class__ = ReaderRepo
268
269
270 @command(b'check-nodemap-race')
271 def cmd_check_nodemap_race(ui, repo):
272 """Run proper <READER> access in the race Windows and check nodemap content"""
273 repo = repo.unfiltered()
274 print('reader: reading changelog')
275 cl = repo.changelog
276 print('reader: changelog read')
277 print_nodemap_details(cl)
278 tip_rev = cl.tiprev()
279 tip_node = cl.node(tip_rev)
280 print('tip-rev: ', tip_rev)
281 print('tip-node:', node.short(tip_node).decode('ascii'))
282 print('node-rev:', cl.rev(tip_node))
283 for r in cl.revs():
284 n = cl.node(r)
285 try:
286 r2 = cl.rev(n)
287 except ValueError as exc:
288 print('error while checking revision:', r)
289 print(' ', exc)
290 return 1
291 else:
292 if r2 != r:
293 print('revision %d is missing from the nodemap' % r)
294 return 1
@@ -26,6 +26,14 b' class NodeMap(dict):'
26 raise error.RevlogError(b'unknown node: %s' % x)
26 raise error.RevlogError(b'unknown node: %s' % x)
27
27
28
28
29 def test_race_hook_1():
30 """hook point for test
31
32 This let tests to have things happens between the docket reading and the
33 data reading"""
34 pass
35
36
29 def persisted_data(revlog):
37 def persisted_data(revlog):
30 """read the nodemap for a revlog from disk"""
38 """read the nodemap for a revlog from disk"""
31 if revlog._nodemap_file is None:
39 if revlog._nodemap_file is None:
@@ -50,6 +58,8 b' def persisted_data(revlog):'
50
58
51 filename = _rawdata_filepath(revlog, docket)
59 filename = _rawdata_filepath(revlog, docket)
52 use_mmap = revlog.opener.options.get(b"persistent-nodemap.mmap")
60 use_mmap = revlog.opener.options.get(b"persistent-nodemap.mmap")
61
62 test_race_hook_1()
53 try:
63 try:
54 with revlog.opener(filename) as fd:
64 with revlog.opener(filename) as fd:
55 if use_mmap:
65 if use_mmap:
@@ -613,9 +613,207 b' removing data with strip'
613 $ hg id -r . --traceback
613 $ hg id -r . --traceback
614 90d5d3ba2fc4 tip
614 90d5d3ba2fc4 tip
615
615
616 (be a good citizen and regenerate the nodemap)
617 $ hg debugupdatecaches
618 $ hg debugnodemap --metadata
619 uid: * (glob)
620 tip-rev: 5005
621 tip-node: 90d5d3ba2fc47db50f712570487cb261a68c8ffe
622 data-length: 121088
623 data-unused: 0
624 data-unused: 0.000%
625
626 Check race condition when multiple process write new data to the repository
627 ---------------------------------------------------------------------------
628
629 In this test, we check that two writers touching the repositories will not
630 overwrite each other data. This test is prompted by the existent of issue6554.
631 Where a writer ended up using and outdated docket to update the repository. See
632 the dedicated extension for details on the race windows and read/write schedule
633 necessary to end up in this situation: testlib/persistent-nodemap-race-ext.py
634
635 The issue was initially observed on a server with a high push trafic, but it
636 can be reproduced using a share and two commiting process which seems simpler.
637
638 The test is Rust only as the other implementation does not use the same
639 read/write patterns.
640
641 $ cd ..
642
643 #if rust
644
645 $ cp -R test-repo race-repo
646 $ hg share race-repo ./other-wc --config format.use-share-safe=yes
647 updating working directory
648 5001 files updated, 0 files merged, 0 files removed, 0 files unresolved
649 $ hg debugformat -R ./race-repo | egrep 'share-safe|persistent-nodemap'
650 share-safe: yes
651 persistent-nodemap: yes
652 $ hg debugformat -R ./other-wc/ | egrep 'share-safe|persistent-nodemap'
653 share-safe: yes
654 persistent-nodemap: yes
655 $ hg -R ./other-wc update 'min(head())'
656 3 files updated, 0 files merged, 2 files removed, 0 files unresolved
657 $ hg -R ./race-repo debugnodemap --metadata
658 uid: 43c37dde
659 tip-rev: 5005
660 tip-node: 90d5d3ba2fc47db50f712570487cb261a68c8ffe
661 data-length: 121088
662 data-unused: 0
663 data-unused: 0.000%
664 $ hg -R ./race-repo log -G -r 'head()'
665 @ changeset: 5005:90d5d3ba2fc4
666 | tag: tip
667 ~ user: test
668 date: Thu Jan 01 00:00:00 1970 +0000
669 summary: a2
670
671 o changeset: 5001:16395c3cf7e2
672 | user: test
673 ~ date: Thu Jan 01 00:00:00 1970 +0000
674 summary: foo
675
676 $ hg -R ./other-wc log -G -r 'head()'
677 o changeset: 5005:90d5d3ba2fc4
678 | tag: tip
679 ~ user: test
680 date: Thu Jan 01 00:00:00 1970 +0000
681 summary: a2
682
683 @ changeset: 5001:16395c3cf7e2
684 | user: test
685 ~ date: Thu Jan 01 00:00:00 1970 +0000
686 summary: foo
687
688 $ echo left-side-race > race-repo/left-side-race
689 $ hg -R ./race-repo/ add race-repo/left-side-race
690
691 $ echo right-side-race > ./other-wc/right-side-race
692 $ hg -R ./other-wc/ add ./other-wc/right-side-race
693
694 $ mkdir sync-files
695 $ mkdir outputs
696 $ (
697 > hg -R ./race-repo/ commit -m left-side-commit \
698 > --config "extensions.race=${RUNTESTDIR}/testlib/persistent-nodemap-race-ext.py" \
699 > --config 'devel.nodemap-race.role=left';
700 > touch sync-files/left-done
701 > ) > outputs/left.txt 2>&1 &
702 $ (
703 > hg -R ./other-wc/ commit -m right-side-commit \
704 > --config "extensions.race=${RUNTESTDIR}/testlib/persistent-nodemap-race-ext.py" \
705 > --config 'devel.nodemap-race.role=right';
706 > touch sync-files/right-done
707 > ) > outputs/right.txt 2>&1 &
708 $ (
709 > hg -R ./race-repo/ check-nodemap-race \
710 > --config "extensions.race=${RUNTESTDIR}/testlib/persistent-nodemap-race-ext.py" \
711 > --config 'devel.nodemap-race.role=reader';
712 > touch sync-files/reader-done
713 > ) > outputs/reader.txt 2>&1 &
714 $ sh "$RUNTESTDIR"/testlib/wait-on-file 10 sync-files/left-done
715 $ cat outputs/left.txt
716 docket-details:
717 uid: 43c37dde
718 actual-tip: 5005
719 tip-rev: 5005
720 data-length: 121088
721 nodemap-race: left side locked and ready to commit
722 docket-details:
723 uid: 43c37dde
724 actual-tip: 5005
725 tip-rev: 5005
726 data-length: 121088
727 finalized changelog write
728 persisting changelog nodemap
729 new data start at 121088
730 persisted changelog nodemap
731 docket-details:
732 uid: 43c37dde
733 actual-tip: 5006
734 tip-rev: 5006
735 data-length: 121280
736 $ sh "$RUNTESTDIR"/testlib/wait-on-file 10 sync-files/right-done
737 $ cat outputs/right.txt
738 nodemap-race: right side start of the locking sequence
739 nodemap-race: right side reading changelog
740 nodemap-race: right side reading of changelog is done
741 docket-details:
742 uid: 43c37dde
743 actual-tip: 5006
744 tip-rev: 5005
745 data-length: 121088
746 nodemap-race: right side ready to wait for the lock
747 nodemap-race: right side locked and ready to commit
748 docket-details:
749 uid: 43c37dde
750 actual-tip: 5006
751 tip-rev: 5005
752 data-length: 121088
753 right ready to write, waiting for reader
754 right proceeding with writing its changelog index and nodemap
755 finalized changelog write
756 persisting changelog nodemap
757 new data start at 121088
758 persisted changelog nodemap
759 docket-details:
760 uid: 43c37dde
761 actual-tip: 5007
762 tip-rev: 5007
763 data-length: 121472
764 $ sh "$RUNTESTDIR"/testlib/wait-on-file 10 sync-files/reader-done
765 $ cat outputs/reader.txt
766 reader: reading changelog
767 reader ready to read the changelog, waiting for right
768 reader: nodemap docket read
769 record-data-length: 121280
770 actual-data-length: 121280
771 file-actual-length: 121472
772 reader: changelog read
773 docket-details:
774 uid: 43c37dde
775 actual-tip: 5006
776 tip-rev: 5006
777 data-length: 121280
778 tip-rev: 5006
779 tip-node: 492901161367
780 node-rev: 5006
781 error while checking revision: 18 (known-bad-output !)
782 Inconsistency: Revision 5007 found in nodemap is not in revlog indexi (known-bad-output !)
783
784 $ hg -R ./race-repo log -G -r 'head()'
785 o changeset: 5007:ac4a2abde241
786 | tag: tip
787 ~ parent: 5001:16395c3cf7e2
788 user: test
789 date: Thu Jan 01 00:00:00 1970 +0000
790 summary: right-side-commit
791
792 @ changeset: 5006:492901161367
793 | user: test
794 ~ date: Thu Jan 01 00:00:00 1970 +0000
795 summary: left-side-commit
796
797 $ hg -R ./other-wc log -G -r 'head()'
798 @ changeset: 5007:ac4a2abde241
799 | tag: tip
800 ~ parent: 5001:16395c3cf7e2
801 user: test
802 date: Thu Jan 01 00:00:00 1970 +0000
803 summary: right-side-commit
804
805 o changeset: 5006:492901161367
806 | user: test
807 ~ date: Thu Jan 01 00:00:00 1970 +0000
808 summary: left-side-commit
809
810 #endif
811
616 Test upgrade / downgrade
812 Test upgrade / downgrade
617 ========================
813 ========================
618
814
815 $ cd ./test-repo/
816
619 downgrading
817 downgrading
620
818
621 $ cat << EOF >> .hg/hgrc
819 $ cat << EOF >> .hg/hgrc
General Comments 0
You need to be logged in to leave comments. Login now