locking error while propagating tags via a checkout

[Paul Pelzl]

Running "bzr pull" from a heavyweight checkout can deadlock while waiting on a lock created by the same process. The deadlock appears to occur while attempting to merge tags from the pull source.

Platform: Win32 Bazaar 2.4.2 running on Windows 7. The standalone installer was used. (It is possible that this issue is specific to Windows 7; I had never seen this bug in the past on Windows XP.)

Steps to reproduce: see attached batch script.

Log entry for the pull, with "-Dlock" enabled:
--------------------------------------------------------------------------
Wed 2012-06-27 13:17:43 -0500
0.034 bazaar version: 2.4.2
0.035 bzr arguments: [u'pull', u'-Dlock', u'C:\\Users\\PAULPE~1.RD\\AppData\\Local\\Temp\\bzr-lock-bug\\repo1\\foo']
0.053 looking for plugins in C:/Users/paul.pelzl.RD/AppData/Roaming/bazaar/2.0/plugins
0.066 looking for plugins in C:/Program Files (x86)/Bazaar/plugins
0.089 encoding stdout as sys.stdout encoding 'cp437'
0.120 opening working tree 'C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt'
0.122 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): lock_write...
0.138 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): peek -> held
0.138 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): after locking, info=LockHeldInfo({'nonce': u'n2yv6j7db2hche4cqxi3', 'start_time': u'1340821063', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
0.138 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): ... lock succeeded after 16ms
0.138 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): lock_write...
0.154 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): peek -> held
0.154 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): after locking, info=LockHeldInfo({'nonce': u'wtxf6ujiz9ev1idx6hmq', 'start_time': u'1340821063', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
0.154 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): ... lock succeeded after 16ms
0.184 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): lock_write...
0.199 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
0.199 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): after locking, info=LockHeldInfo({'nonce': u'smfcqsqvkixq175lwdni', 'start_time': u'1340821064', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
0.199 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): ... lock succeeded after 15ms
0.206 Using fetch logic to copy between CHKInventoryRepository('file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo1/.bzr/repository/')(RepositoryFormat2a()) and CHKInventoryRepository('file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/')(RepositoryFormat2a())
0.207 fetching: <SearchResult search:(set(['<email address hidden>']), set(['null:']), 1)>
0.233 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): lock_write...
0.248 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): peek -> held
0.248 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): after locking, info=LockHeldInfo({'nonce': u'tr56ueyyu1llipiddd8u', 'start_time': u'1340821064', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
0.248 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): ... lock succeeded after 14ms
0.251 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): unlocking
0.251 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): peek -> held
0.264 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): ... unlock succeeded after 13ms
0.278 Using fetch logic to copy between CHKInventoryRepository('file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo1/.bzr/repository/')(RepositoryFormat2a()) and CHKInventoryRepository('file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/')(RepositoryFormat2a())
0.278 fetching: <SearchResult search:(set(['<email address hidden>']), set(['null:']), 1)>
0.300 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): lock_write...
0.316 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): peek -> held
0.316 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): after locking, info=LockHeldInfo({'nonce': u'wxipzf9tqxj7k91pyfap', 'start_time': u'1340821064', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
0.316 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): ... lock succeeded after 16ms
0.319 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): unlocking
0.319 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): peek -> held
0.332 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/.bzr/repository/lock): ... unlock succeeded after 13ms
0.345 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): lock_write...
0.348 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): ... contention, File exists: u'C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock/mo0o2qy6kl.tmp': [Error 183] Cannot create a file when that file already exists
0.348 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
0.348 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): other holder is LockHeldInfo({'nonce': u'smfcqsqvkixq175lwdni', 'start_time': u'1340821064', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
0.349 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): remove lock/mo0o2qy6kl.tmp
0.349 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
[ 9608] 2012-06-27 13:17:44.164 INFO: Unable to obtain lock file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/ held by Paul Pelzl <email address hidden> on gsi-baz (process #9608), acquired 0 seconds ago.
Will continue to try until 13:18:14, unless you press Ctrl-C.
See "bzr help break-lock" for more.
0.350 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): waiting 1.0s
1.350 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): lock_write...
1.355 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): ... contention, File exists: u'C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock/nix0f788uf.tmp': [Error 183] Cannot create a file when that file already exists
1.355 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
1.355 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): other holder is LockHeldInfo({'nonce': u'smfcqsqvkixq175lwdni', 'start_time': u'1340821064', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
1.357 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): remove lock/nix0f788uf.tmp
1.357 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
1.357 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): waiting 1.0s
2.357 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): lock_write...
2.362 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): ... contention, File exists: u'C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock/r42qzvj5ot.tmp': [Error 183] Cannot create a file when that file already exists
2.365 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
2.365 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): other holder is LockHeldInfo({'nonce': u'smfcqsqvkixq175lwdni', 'start_time': u'1340821064', 'hostname': u'gsi-baz', 'pid': u'9608', 'user': u'Paul Pelzl <email address hidden>'})
2.366 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): remove lock/r42qzvj5ot.tmp
2.367 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
2.367 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): waiting 1.0s
3.352 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): unlocking
3.352 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): peek -> held
3.374 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/foo/.bzr/branch/lock): ... unlock succeeded after 22ms
3.375 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): unlocking
3.377 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): peek -> held
3.390 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/checkout/lock): ... unlock succeeded after 15ms
3.391 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): unlocking
3.392 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): peek -> held
3.406 LockDir(file:///C:/Users/PAULPE~1.RD/AppData/Local/Temp/bzr-lock-bug/repo2/wt/.bzr/branch/lock): ... unlock succeeded after 14ms
3.406 Transferred: 0kB (0.0kB/s r:0kB w:0kB)
3.406 Traceback (most recent call last):
  File "bzrlib\commands.pyo", line 946, in exception_to_return_code
  File "bzrlib\commands.pyo", line 1150, in run_bzr
  File "bzrlib\commands.pyo", line 699, in run_argv_aliases
  File "bzrlib\commands.pyo", line 721, in run
  File "bzrlib\cleanup.pyo", line 135, in run_simple
  File "bzrlib\cleanup.pyo", line 165, in _do_with_cleanups
  File "bzrlib\builtins.pyo", line 1076, in run
  File "bzrlib\decorators.pyo", line 217, in write_locked
  File "bzrlib\workingtree.pyo", line 1017, in pull
  File "bzrlib\branch.pyo", line 1109, in pull
  File "bzrlib\decorators.pyo", line 217, in write_locked
  File "bzrlib\branch.pyo", line 3376, in pull
  File "bzrlib\branch.pyo", line 3511, in _pull
  File "bzrlib\tag.pyo", line 209, in merge_to
  File "bzrlib\cleanup.pyo", line 131, in run
  File "bzrlib\cleanup.pyo", line 165, in _do_with_cleanups
  File "bzrlib\tag.pyo", line 241, in _merge_to_operation
  File "bzrlib\branch.pyo", line 2452, in lock_write
  File "bzrlib\lockable_files.pyo", line 162, in lock_write
  File "bzrlib\lockdir.pyo", line 673, in lock_write
  File "bzrlib\lockdir.pyo", line 635, in wait_lock
KeyboardInterrupt

[Paul Pelzl (pelzlpj)]

Some root cause analysis:

    * GenericInterBranch.pull() takes a write lock on the bound branch, and
      maintains the lock across a call to BasicTags.merge_to().

    * BasicTags.merge_to takes its own lock on the bound branch. Under
      different circumstances this lock would succeed, because
      BzrBranch.get_master_branch() provides a cached result and the
      in-memory branch will support counted locks. But in this code path
      GenericInterBranch._pull() calls
      GenericInterBranch._update_revisions(), and this blows away the
      cached master on a call to BzrBranch.set_last_revision_info().
      So the master gets reloaded from disk, and bzr is unaware that
      the branch is already write-locked.

[Martin Packman (gz)]

Not windows specific, locking issue also present on nix with the given script adapted to shell.