comparison tests/testlib/persistent-nodemap-race-ext.py @ 48038:52018f8ef020 stable

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
author Pierre-Yves David <pierre-yves.david@octobus.net>
date Tue, 21 Sep 2021 21:18:50 +0200
parents
children 6000f5b25c9b
comparison
equal deleted inserted replaced
48037:016081cca1fb 48038:52018f8ef020
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