Merge lp:~parthm/bzr/250451-better-url-for-break-lock into lp:bzr

[Parth Malwankar]

Lock URL shown in case of failure to acquire lock (for smart server access) is now valid. Default timeout for lock contention is now 30s.

=== Fixes Bug #250451 ===

This patch gives a more accurate url in case where bzr fails to obtain lock from smart server.
In the current implementation, the server passes details such as lock_url (inaccurate), user, time_ago, pid to client. These are displayed in bzrlib.lockdir.wait_lock. Unfortunately at this point we don't have a clear lock_url and a url like "lp-69989648:///~parthm/%2Bjunk/lock-test/.bzr/branch/lock" is displayed to the user.

This patch, avoids displaying the inaccurate lock_url in the wait_lock. If the wait_fails, bzr raises a LockContention error in bzrlib.remote.RemoteBranch._remote_lock_write. Here, we add the correct lock_url to LockContention msg which is displayed to the user.

Does this approach look reasonable? Any other areas of code that I should check? I would appreciate any pointers on what would be a good place to put tests for this.

One thing remaining would be to handle ^C in bzrlib.lockdir.wait_lock to raise LockContention error so that the correct lock_url is displayed to the user.

Running the test locally, following is the interaction:
========================================================
[foo]% bzr push bzr+ssh://parthm@localhost/home/parthm/tmp/lock-path/trunk
Unable to obtain lock held by Parth Malwankar <email address hidden> at parthm-laptop [process #9606], acquired 7 hours, 52 minutes ago.
Will continue to try until 22:40:59, unless you press Ctrl-C.
See "bzr help break-lock" for more.
bzr: ERROR: Could not acquire lock "(remote lock)": bzr+ssh://parthm@localhost/home/parthm/tmp/lock-path/trunk
[foo]%

Interacting with launchpad (which is running the un-patched server):
====================================================================
[trunk]% bzr push lp:~parthm/+junk/lock-test
Unable to obtain lock lp-69989648:///~parthm/%2Bjunk/lock-test/.bzr/branch/lock
held by <email address hidden> on host crowberry [process #26780]
locked 12 hours, 3 minutes ago
Will continue to try until 18:03:34, unless you press Ctrl-C.
See "bzr help break-lock" for more.
bzr: ERROR: Could not acquire lock "(remote lock)": bzr+ssh://bazaar.launchpad.net/~parthm/%2Bjunk/lock-test
[trunk]%

Current interaction (without patch)
===================================
[trunk]% bzr push lp:~parthm/+junk/lock-test
Unable to obtain lock lp-69989648:///~parthm/%2Bjunk/lock-test/.bzr/branch/lock
held by <email address hidden> on host crowberry [process #26780]
locked 12 hours, 2 minutes ago
Will continue to try until 18:03:15, unless you press Ctrl-C.
See "bzr help break-lock" for more.
bzr: ERROR: Could not acquire lock "(remote lock)":

[Martin Packman (gz)]

+ e.msg = self.repository.base.rstrip('.bzr/')

That doesn't do what you want it too. Use `.split(".bzr")[0]` instead.

Would also prefer a less hacky change to the LockContention instance, there's a todo note on the class related to this.

review: Needs Fixing

[Parth Malwankar (parthm)]

Some discussion on ^C and timeout:
https://bugs.launchpad.net/bzr/+bug/592148

[Parth Malwankar (parthm)]

> + e.msg = self.repository.base.rstrip('.bzr/')
>
> That doesn't do what you want it too. Use `.split(".bzr")[0]` instead.

Wow. That was stupid :P Fixed.

> Would also prefer a less hacky change to the LockContention instance, there's
> a todo note on the class related to this.

Agreed. I have added a comment indicating that the lock_url is not know to
the server so the initial LockContention exception doesn't have this
info. A new LockContention is now raised and we avoid directly modifying
instance variables of the old exception.

This update also fixes tests and also add a (timeout > 0) check before
showing "Will continue to try .." message.

Thanks for the review.

This is what the current interaction looks like:

[foo]% bzr push bzr+ssh://parthm@localhost/home/parthm/tmp/lock-path/trunk
parthm@localhost's password:
Unable to obtain lock held by Parth Malwankar <email address hidden>
at parthm-laptop [process #9606], acquired 46 hours, 42 minutes ago.
See "bzr help break-lock" for more.
bzr: ERROR: Could not acquire lock "(remote lock)": bzr+ssh://parthm@localhost/home/parthm/tmp/lock-path/trunk/
[foo]%

[foo]% bzr push bzr://localhost
bzr: ERROR: Could not acquire lock "(remote lock)": bzr://localhost/
[foo]%

[Parth Malwankar (parthm)]

Some further improvements to this patch:
 - As local lock urls are valid, these are displayed immediately. This way, even if the user chooses to ^C before the timeout, she would still know the url even though ^C keeps LockContention error from being raised.
 - Default timeout for lock contention retry reduced from 300s to 10s (discussion: comments 3 and 4 for bug #592148)
 - Cleanup display of local lock url. i.e.
Display:
    bzr: ERROR: Could not acquire lock "(local)": file:///home/parthm/tmp/lock-path/trunk/
instead of:
    LockContention: Could not acquire lock "LockDir(file:///home/parthm/tmp/lock-path/trunk/.bzr/branch/lock)":

Local error is now:
===================
[foo]% bzr push ../trunk
Unable to obtain lock file:///home/parthm/tmp/lock-path/trunk/
held by Parth Malwankar <email address hidden>
at parthm-laptop [process #9606], acquired 91 hours, 3 minutes ago.
Will continue to try until 09:51:21, unless you press Ctrl-C.
See "bzr help break-lock" for more.
bzr: ERROR: Could not acquire lock "(local)": file:///home/parthm/tmp/lock-path/trunk/

Remote error is:
===================
[foo]% bzr push bzr+ssh://parthm@localhost/home/parthm/tmp/lock-path/trunk
Unable to obtain lock held by Parth Malwankar <email address hidden>
at parthm-laptop [process #9606], acquired 91 hours, 22 minutes ago.
See "bzr help break-lock" for more.
bzr: ERROR: Could not acquire lock "(remote lock)": bzr+ssh://parthm@localhost/home/parthm/tmp/lock-path/trunk/
[foo]%

[Parth Malwankar (parthm)]

Timeout updated to 30s based on discussion on bug #592148.

[Vincent Ladeuil (vila)]

Excellent !

One nit though so my vote is really Tweak (needs fixing but Approve if addressed and doesn't need another review):

66 + if lock_url.startswith('file://'):
67 + lock_url = lock_url.split('.bzr/')[0] + '\n'

96 + raise LockContention('(local)', lock_url.rstrip())

is a bit ugly, there should be a way to not add this '\n' instead so you don't have to remove it later. This '\n' is not part of the url anyway.

Not a big deal but I find it harder to read.

review: Needs Fixing

[Vincent Ladeuil (vila)]

Hmm, just re-read the bug comments, make sure you have agreement from John and Robert about the timeout value 30 or 5.

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Vincent Ladeuil wrote:
> Hmm, just re-read the bug comments, make sure you have agreement from John and Robert about the timeout value 30 or 5.

So I wrote a fairly trivial plugin to time how much time is spent in
'save_pack_names'. It is available here:

 lp:~jameinel/+junk/bzr_lock_test

(install as 'lock_test'). This is what I got:

local
  $ bzr lock-test foo --count=100
  commit: 100 0.033s avg, 0.203s max
  save: 100 0.017s avg, 0.090s max

LAN sftp
  $ bzr lock-test sftp://local-server/...
  commit: 100 0.537s avg, 4.100s max
  save: 100 0.149s avg, 0.812s max

LAN smart VFS
  $ bzr lock-test bzr+ssh://local-server/...
  commit: 100 0.410s avg, 3.203s max
  save: 100 0.213s avg, 1.740s max

WAN sftp (my house in Chicago to chinstrap in London)
  $ bzr lock-test sftp://chinstrap..../xxx-test --count=100
  commit: 100 15.635s avg, 89.538s max
  save: 100 5.965s avg, 29.668s max

WAN + smart VFS
  $ bzr lock-test bzr+ssh://chinstrap.../xxx-test --count=100
  commit: 100 7.683s avg, 104.901s max
  save: 100 4.407s avg, 66.544s max

This code is testing VFS operations, rather than 'insert_stream()'
(mostly because I can't isolate the _save_pack_names time, and it should
be equivalent to 'local' time).

Note that 'commit' == 'commit_write_group' which can involve an
autopack, but 'save' is just the _save_pack_names() time. Which includes
a write-lock, reading the remote pack-names, writing a new one, and
unlocking.

Note that it can take up to *30s* just to do that via sftp, and even 66s
w/ VFS.

The averages are in the ~5s range. So I think 10s is possibly ok, 1min
would be being generous (but still possible that 2 people could push to
different branches in a shared repository and have it fail when it could
have succeeded.)

I'm willing to say that the peaks are noise, but I still think a minimum
of 10s, and 30s is probably a decent safety margin. (And yes, if we
always used RPC, then probably <5s could be ok.)

I would be interested to see what people in AU see.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkwX5rUACgkQJdeBCYSNAAOwLwCgnmGR5FS2O5mLLnrZ4vNGNoiI
pPgAoMgPoonzfnZOtR/G1hN7vIH0wXqV
=ShnQ
-----END PGP SIGNATURE-----

[Parth Malwankar (parthm)]

> Excellent !
>
> One nit though so my vote is really Tweak (needs fixing but Approve if
> addressed and doesn't need another review):
>
> 66 + if lock_url.startswith('file://'):
> 67 + lock_url = lock_url.split('.bzr/')[0] + '\n'
>
> 96 + raise LockContention('(local)', lock_url.rstrip())
>
> is a bit ugly, there should be a way to not add this '\n' instead so you don't
> have to remove it later. This '\n' is not part of the url anyway.
>

Yes. That was a little ugly. I was not too happy with it myself.
I had set it up that way to allow a line-break in case the url is printed. I have removed that now and rely on the terminal to wrap the text.

> Not a big deal but I find it harder to read.

[Parth Malwankar (parthm)]

> Hmm, just re-read the bug comments, make sure you have agreement from John and
> Robert about the timeout value 30 or 5.

John has posted his detailed comment and I synced up with Robert on IRC. Robert was ok with both 10 and 30, so I am keeping this the timeout as 30. As mentioned by John, that seems to have a decent margin.

[Parth Malwankar (parthm)]

sent to pqm by email

=== modified file 'NEWS'
--- NEWS	2010-06-15 07:44:29 +0000
+++ NEWS	2010-06-15 09:55:53 +0000
@@ -63,6 +63,11 @@
 * Relative imports in plugins are now handled correctly when using
   BZR_PLUGINS_AT. (Vincent Ladeuil, #588959)
 
+* URL displayed for use with ``break-lock`` when smart server sees lock
+  contention are now valid. Default timeout for lock contention retry is
+  now 30 seconds instead of 300 seconds.
+  (Parth Malwankar, #250451)
+
 Improvements
 ************
 

=== modified file 'bzrlib/errors.py'
--- bzrlib/errors.py	2010-05-28 06:04:57 +0000
+++ bzrlib/errors.py	2010-06-15 09:55:53 +0000
@@ -1041,8 +1041,6 @@
 class LockContention(LockError):
 
     _fmt = 'Could not acquire lock "%(lock)s": %(msg)s'
-    # TODO: show full url for lock, combining the transport and relative
-    # bits?
 
     internal_error = False
 

=== modified file 'bzrlib/lockdir.py'
--- bzrlib/lockdir.py	2010-05-25 17:27:52 +0000
+++ bzrlib/lockdir.py	2010-06-15 09:55:53 +0000
@@ -151,7 +151,7 @@
 # files/dirs created.
 
 
-_DEFAULT_TIMEOUT_SECONDS = 300
+_DEFAULT_TIMEOUT_SECONDS = 30
 _DEFAULT_POLL_SECONDS = 1.0
 
 
@@ -539,24 +539,27 @@
                 if deadline_str is None:
                     deadline_str = time.strftime('%H:%M:%S',
                                                  time.localtime(deadline))
+                # As local lock urls are correct we display them.
+                # We avoid displaying remote lock urls.
                 lock_url = self.transport.abspath(self.path)
-                # See <https://bugs.launchpad.net/bzr/+bug/250451>
-                # the URL here is sometimes not one that is useful to the
-                # user, perhaps being wrapped in a lp-%d or chroot decorator,
-                # especially if this error is issued from the server.
-                self._report_function('%s %s\n'
-                    '%s\n' # held by
-                    '%s\n' # locked ... ago
-                    'Will continue to try until %s, unless '
-                    'you press Ctrl-C.\n'
-                    'See "bzr help break-lock" for more.',
-                    start,
-                    formatted_info[0],
-                    formatted_info[1],
-                    formatted_info[2],
-                    deadline_str,
-                    )
-
+                if lock_url.startswith('file://'):
+                    lock_url = lock_url.split('.bzr/')[0]
+                else:
+                    lock_url = ''
+                user, hostname, pid, time_ago = formatted_info
+                msg = ('%s lock %s '        # lock_url
+                    'held by '              # start
+                    '%s\n'                  # user
+                    'at %s '                # hostname
+                    '[process #%s], '       # pid
+                    'acquired %s.')         # time ago
+                msg_args = [start, lock_url, user, hostname, pid, time_ago]
+                if timeout > 0:
+                    msg += ('\nWill continue to try until %s, unless '
+                        'you press Ctrl-C.')
+                    msg_args.append(deadline_str)
+                msg += '\nSee "bzr help break-lock" for more.'
+                self._report_function(msg, *msg_args)
             if (max_attempts is not None) and (attempt_count >= max_attempts):
                 self._trace("exceeded %d attempts")
                 raise LockContention(self)
@@ -564,8 +567,11 @@
                 self._trace("waiting %ss", poll)
                 time.sleep(poll)
             else:
+                # As timeout is always 0 for remote locks
+                # this block is applicable only for local
+                # lock contention
                 self._trace("timeout after waiting %ss", timeout)
-                raise LockContention(self)
+                raise LockContention('(local)', lock_url)
 
     def leave_in_place(self):
         self._locked_via_token = True
@@ -616,17 +622,19 @@
 
     def _format_lock_info(self, info):
         """Turn the contents of peek() into something for the user"""
-        lock_url = self.transport.abspath(self.path)
         start_time = info.get('start_time')
         if start_time is None:
             time_ago = '(unknown)'
         else:
             time_ago = format_delta(time.time() - int(info['start_time']))
+        user = info.get('user', '<unknown>')
+        hostname = info.get('hostname', '<unknown>')
+        pid = info.get('pid', '<unknown>')
         return [
-            'lock %s' % (lock_url,),
-            'held by %s on host %s [process #%s]' %
-                tuple([info.get(x, '<unknown>') for x in ['user', 'hostname', 'pid']]),
-            'locked %s' % (time_ago,),
+            user,
+            hostname,
+            pid,
+            time_ago,
             ]
 
     def validate_token(self, token):

=== modified file 'bzrlib/remote.py'
--- bzrlib/remote.py	2010-05-20 18:23:17 +0000
+++ bzrlib/remote.py	2010-06-15 09:55:53 +0000
@@ -2420,9 +2420,16 @@
             repo_token = self.repository.lock_write().repository_token
             self.repository.unlock()
         err_context = {'token': token}
-        response = self._call(
-            'Branch.lock_write', self._remote_path(), branch_token,
-            repo_token or '', **err_context)
+        try:
+            response = self._call(
+                'Branch.lock_write', self._remote_path(), branch_token,
+                repo_token or '', **err_context)
+        except errors.LockContention, e:
+            # The LockContention from the server doesn't have any
+            # information about the lock_url. We re-raise LockContention
+            # with valid lock_url.
+            raise errors.LockContention('(remote lock)',
+                self.repository.base.split('.bzr/')[0])
         if response[0] != 'ok':
             raise errors.UnexpectedSmartServerResponse(response)
         ok, branch_token, repo_token = response

=== modified file 'bzrlib/tests/test_lockdir.py'
--- bzrlib/tests/test_lockdir.py	2010-05-20 18:23:17 +0000
+++ bzrlib/tests/test_lockdir.py	2010-06-15 09:55:53 +0000
@@ -191,22 +191,21 @@
                     "took %f seconds to detect lock contention" % (after - before))
         finally:
             lf1.unlock()
-        lock_base = lf2.transport.abspath(lf2.path)
         self.assertEqual(1, len(self._logged_reports))
-        lock_url = lf2.transport.abspath(lf2.path)
-        self.assertEqual('%s %s\n'
-                         '%s\n%s\n'
-                         'Will continue to try until %s, unless '
-                         'you press Ctrl-C.\n'
-                         'See "bzr help break-lock" for more.',
-                         self._logged_reports[0][0])
-        args = self._logged_reports[0][1]
-        self.assertEqual('Unable to obtain', args[0])
-        self.assertEqual('lock %s' % (lock_base,), args[1])
-        self.assertStartsWith(args[2], 'held by ')
-        self.assertStartsWith(args[3], 'locked ')
-        self.assertEndsWith(args[3], ' ago')
-        self.assertContainsRe(args[4], r'\d\d:\d\d:\d\d')
+        self.assertEqual(self._logged_reports[0][0],
+            '%s lock %s held by %s\n'
+            'at %s [process #%s], acquired %s.\n'
+            'Will continue to try until %s, unless '
+            'you press Ctrl-C.\n'
+            'See "bzr help break-lock" for more.')
+        start, lock_url, user, hostname, pid, time_ago, deadline_str = \
+            self._logged_reports[0][1]
+        self.assertEqual(start, u'Unable to obtain')
+        self.assertEqual(user, u'[e-mail]')
+        # skip hostname
+        self.assertContainsRe(pid, r'\d+')
+        self.assertContainsRe(time_ago, r'.* ago')
+        self.assertContainsRe(deadline_str, r'\d{2}:\d{2}:\d{2}')
 
     def test_31_lock_wait_easy(self):
         """Succeed when waiting on a lock with no contention.
@@ -597,11 +596,10 @@
             info_list = ld1._format_lock_info(ld1.peek())
         finally:
             ld1.unlock()
-        self.assertEqual('lock %s' % (ld1.transport.abspath(ld1.path),),
-                         info_list[0])
-        self.assertContainsRe(info_list[1],
-                              r'^held by .* on host .* \[process #\d*\]$')
-        self.assertContainsRe(info_list[2], r'locked \d+ seconds? ago$')
+        self.assertEqual(info_list[0], u'[e-mail]')
+        # info_list[1] is hostname. we skip this.
+        self.assertContainsRe(info_list[2], '^\d+$') # pid
+        self.assertContainsRe(info_list[3], r'^\d+ seconds? ago$') # time_ago
 
     def test_lock_without_email(self):
         global_config = config.GlobalConfig()
@@ -680,9 +678,7 @@
         info = lf.peek()
         formatted_info = lf._format_lock_info(info)
         self.assertEquals(
-            ['lock %s' % t.abspath('test_lock'),
-             'held by <unknown> on host <unknown> [process #<unknown>]',
-             'locked (unknown)'],
+            ['<unknown>', '<unknown>', '<unknown>', '(unknown)'],
             formatted_info)