ReadOnlyError from pull/update of checkout using smart server in 2.3.x

[Nicholas Allen]

I upgraded my server and client to the very latest bzr 2.3.0. Now when I
try to pull or update my branch on my client using the smart server I
get the following error:

Using saved parent location: bzr://server/project/branch
bzr: ERROR: Received bad protocol version marker: 'Unable to obtain
lock held by devel\nat devel [process #1422], acquired 5 seconds
ago.\nSee "bzr help break-lock" for more.\n'

It seems that Bazaar is locking itself out! Each time I run it the lock
is a different one and there are no locks on the server or client and I
am the only one using the server and client. It's always held a few
seconds ago so it's clearly the smart server process that is spawned by
Bazaar that blocks itself. I did not have this problem before upgrading.

[Nicholas Allen (nick-allen)]

Here is a stack trace I found in ~/.bzr.log:

Sat 2011-02-19 11:08:02 +0100
0.044 bazaar version: 2.3.0
0.044 bzr arguments: [u'pull']
0.077 looking for plugins in /home/nick/.bazaar/plugins
0.100 looking for plugins in /usr/lib/pymodules/python2.6/bzrlib/plugins
0.106 looking for plugins in /usr/lib/python2.6/dist-packages/bzrlib/plugins
0.109 encoding stdout as sys.stdout encoding 'UTF-8'
6.495 Using fetch logic to copy between RemoteRepository(bzr://devel/devel/bitwig/.bzr/)(RemoteRepositoryFormat(_network_name='Bazaar repository format 2a (needs bzr 1.16 or later)\n')) and CHKInventoryRepository('file:///home/nick/projects/bitwig/.bzr/repository/')(RepositoryFormat2a())
6.496 fetch up to rev {<email address hidden>}
9.540 Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.6/bzrlib/commands.py", line 923, in exception_to_return_code
    return the_callable(*args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/commands.py", line 1123, in run_bzr
    ret = run(*run_argv)
  File "/usr/lib/pymodules/python2.6/bzrlib/commands.py", line 691, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/usr/lib/pymodules/python2.6/bzrlib/commands.py", line 710, in run
    return self._operation.run_simple(*args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/cleanup.py", line 135, in run_simple
    self.cleanups, self.func, *args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/cleanup.py", line 165, in _do_with_cleanups
    result = func(*args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/builtins.py", line 1011, in run
    branch_from, overwrite, revision_id, local=local)
  File "/usr/lib/pymodules/python2.6/bzrlib/branch.py", line 1086, in pull
    possible_transports=possible_transports, *args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/decorators.py", line 194, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/branch.py", line 3478, in pull
    merge_tags_to_master=not source_is_master)
  File "/usr/lib/pymodules/python2.6/bzrlib/branch.py", line 3593, in _pull
    overwrite, ignore_master=not merge_tags_to_master)
  File "/usr/lib/pymodules/python2.6/bzrlib/tag.py", line 209, in merge_to
    return operation.run(to_tags, overwrite, ignore_master)
  File "/usr/lib/pymodules/python2.6/bzrlib/cleanup.py", line 131, in run
    self.cleanups, self.func, self, *args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/cleanup.py", line 165, in _do_with_cleanups
    result = func(*args, **kwargs)
  File "/usr/lib/pymodules/python2.6/bzrlib/tag.py", line 241, in _merge_to_operation
    add_cleanup(master.lock_write().unlock)
  File "/usr/lib/pymodules/python2.6/bzrlib/remote.py", line 2468, in lock_write
    remote_tokens = self._remote_lock_write(token)
  File "/usr/lib/pymodules/python2.6/bzrlib/remote.py", line 2452, in _remote_lock_write
    repo_token or '', **err_context)
  File "/usr/lib/pymodules/python2.6/bzrlib/remote.py", line 57, in _call
    return self._client.call(method, *args)
  File "/usr/lib/pymodules/python2.6/bzrlib/smart/client.py", line 132, in call
    result, protocol = self...

[Michael Hudson-Doyle (mwhudson)]

I don't know if this is your problem, but i had a similar issue when the branch that another branch was stacked on was moved. Have a look at the .bzr/branch/branch.confs of the various involved branches and see if anything jumps out at you?

[Andrew Bennetts (spiv)]

Hmm. This error is interesting.

“bzr: ERROR: Received bad protocol version marker: 'Unable to obtain
lock held by devel\nat devel [process #1422], acquired 5 seconds
ago.\nSee "bzr help break-lock" for more.\n'”

There's a couple of things going on here:
 * that error text (“Unable to obtain…”) is typically a warning emitted on stderr (or stdout?) via trace.note, but the server is supposed to be running in a mode that doesn't print those warnings (BzrServerFactory._change_globals installs a SilentUIFactory).
 * having emitted that text, it's apparently ended up relayed to the client. Given that you're using the 'bzr' protocol, I'm guess there's an inetd involved in serving bzr? I can't imagine any likely reason why bzr would accidentally write that text to a socket instead of stderr or stdout! But if bzr is running behind inetd then stdout (and possibly stderr?) is relayed to the client.

What version of bzr is installed on the server? Although I'm pretty sure SilentUIFactory has been installed by cmd_serve since at least 2.0... ah, maybe trace.note isn't affected by the ui_factory? I wonder if lockdir ought to be using ui_factory.note instead?

Still, it would be good to confirm that inetd is involved, and exactly which version of bzr is on the server.

[Nicholas Allen (nick-allen)]

Hi,

I have 2.3.0 installed on the server and I am running the server using inetd.

[Nicholas Allen (nick-allen)]

My local branch is a
lightweight checkout of a branch in my local shared repository. If I
bind it so that it's bound to the server then I can't pull or update. If
I unbind it first it seems to work.

If I do bzr info in my lightweight checkout when bound it looks like this:

Lightweight checkout (format: 2a)
Location:
       light checkout root: .
  repository checkout root: /home/nick/projects/bitwig/document-conversion
        checkout of branch: bzr://devel/devel/bitwig/document-conversion
         shared repository: /home/nick/projects/bitwig

Related branches:
  public branch: bzr://devel/devel/bitwig/document-conversion
    push branch: bzr://devel/devel/bitwig/document-conversion
  parent branch: bzr://devel/devel/bitwig/document-conversion/
  submit branch: bzr://devel/stable/bitwig/trunk

When unbound like this:

Lightweight checkout (format: 2a)
Location:
  light checkout root: .
   checkout of branch: /home/nick/projects/bitwig/document-conversion
    shared repository: /home/nick/projects/bitwig

Related branches:
  public branch: bzr://devel/devel/bitwig/document-conversion
    push branch: bzr://devel/devel/bitwig/document-conversion
  parent branch: bzr://devel/devel/bitwig/document-conversion/
  submit branch: bzr://devel/stable/bitwig/trunk

The directory of my lightweight checkout is /home/nick/projects/bitwig/devel

Hope this helps....

[Nicholas Allen (nick-allen)]

This bug is really annoying. I can't update anymore so I have to "bzr unbind" "bzr pull" and "bzr bind". If I forget the last bind then my colleagues don't get email notifications and can't merge from me so this annoys them too. Is there any progress being made on this?

[Andrew Bennetts (spiv)]

This is almost certainly the same as bug 733350, which has been fixed in lp:bzr/2.3 and will be part of the 2.3.2 release.

[Nicholas Allen (nick-allen)]

I just branch lp:bzr/2.3 to test it and it crashes now with a different stack trace:

bzr: ERROR: bzrlib.errors.ReadOnlyError: A write attempt was made in a read only transaction on RemoteBranch(bzr://devel/devel/bitwig/nick/)

Traceback (most recent call last):
  File "/home/nick/source/bzr-2.3/bzrlib/commands.py", line 926, in exception_to_return_code
    return the_callable(*args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/commands.py", line 1126, in run_bzr
    ret = run(*run_argv)
  File "/home/nick/source/bzr-2.3/bzrlib/commands.py", line 691, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/home/nick/source/bzr-2.3/bzrlib/commands.py", line 713, in run
    return self._operation.run_simple(*args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/cleanup.py", line 135, in run_simple
    self.cleanups, self.func, *args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/cleanup.py", line 165, in _do_with_cleanups
    result = func(*args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/builtins.py", line 1413, in run
    old_tip = branch.update(possible_transports)
  File "/home/nick/source/bzr-2.3/bzrlib/decorators.py", line 194, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/branch.py", line 2803, in update
    self.pull(master, overwrite=True)
  File "/home/nick/source/bzr-2.3/bzrlib/branch.py", line 1089, in pull
    possible_transports=possible_transports, *args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/decorators.py", line 194, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/home/nick/source/bzr-2.3/bzrlib/branch.py", line 3473, in pull
    master_branch.lock_write()
  File "/home/nick/source/bzr-2.3/bzrlib/remote.py", line 2485, in lock_write
    raise errors.ReadOnlyError(self)
ReadOnlyError: A write attempt was made in a read only transaction on RemoteBranch(bzr://devel/devel/bitwig/nick/)

[Nicholas Allen (nick-allen)]

Just to let you know I only upgraded the client side as it's not easy to upgrade the server. I will try with both using 2.3 and let you know what happens as soon as I can...

[Andrew Bennetts (spiv)]

Ok, so in addition to bug 733350, it appears you're affected by a separate (but related) bug causing the ReadOnlyError.

I don't think the server version matters much, I'm pretty sure this is a client-side bug.

It appears something earlier in the code has done b.get_master_branch() and read-locked it without unlocking it yet. This is an unfortunate interaction with caching the result of get_master_branch :/

This is yet another bug that would be fixed by allowing lock_read()s to be upgraded to lock_write()s.

[Andrew Bennetts (spiv)]

Btw, I un-duped this report to track your ReadOnlyError issue.