bzr crashed with ErrorFromSmartServer: ('error', 'bytes must be a string')

[Nguyen Huu Binh Minh]

Binary package hint: bzr

bzr: failed to report crash using apport:et stream source
     OSError(17, 'File exists')
bzr: ERROR: bzrlib.errors.ErrorFromSmartServer: Error received from smart server: ('error', 'bytes must be a string')

ProblemType: Crash
DistroRelease: Ubuntu 10.10
Package: bzr 2.2.1-0ubuntu1
ProcVersionSignature: Ubuntu 2.6.35-25.44-generic 2.6.35.10
Uname: Linux 2.6.35-25-generic i686
Architecture: i386
BzrDebugFlags: set()
BzrVersion: 2.2.1
CommandLine: ['/usr/bin/bzr', 'push', 'bzr+http://node09:8081/code/xalo-news/fastesp/trunk']
CrashDb: bzr
Date: Fri Feb 18 16:46:51 2011
ExecutablePath: /usr/bin/bzr
FileSystemEncoding: UTF-8
InstallationMedia: Ubuntu 10.04 LTS "Lucid Lynx" - Release i386 (20100429)
InterpreterPath: /usr/bin/python2.6
Locale: en_US.utf8
Platform: Linux-2.6.35-25-generic-i686-with-Ubuntu-10.10-maverick
ProcCmdline: /usr/bin/python /usr/bin/bzr push bzr+http://node09:8081/code/xalo-news/fastesp/trunk
ProcEnviron:
 SHELL=/bin/bash
 PATH=(custom, user)
 LANG=en_US.utf8
PythonVersion: 2.6.6
SourcePackage: bzr
Title: bzr crashed with ErrorFromSmartServer in _translate_error()
UserEncoding: UTF-8
UserGroups: adm admin cdrom dialout lpadmin plugdev sambashare

Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 912, in exception_to_return_code
    return the_callable(*args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 1112, in run_bzr
    ret = run(*run_argv)
  File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 690, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 705, in run
    return self._operation.run_simple(*args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/cleanup.py", line 135, in run_simple
    self.cleanups, self.func, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/cleanup.py", line 165, in _do_with_cleanups
    result = func(*args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/builtins.py", line 1161, in run
    use_existing_dir=use_existing_dir)
  File "/usr/lib/python2.6/dist-packages/bzrlib/push.py", line 139, in _show_push_branch
    remember, create_prefix)
  File "/usr/lib/python2.6/dist-packages/bzrlib/bzrdir.py", line 1360, in push_branch
    overwrite, stop_revision=revision_id)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 1077, in push
    *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 3439, in push
    _override_hook_source_branch=_override_hook_source_branch)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 3244, in _run_with_write_locked_target
    result = callable(*args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 3478, in _push_with_bound_branches
    stop_revision)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 2642, in _basic_push
    overwrite=overwrite, graph=graph)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 1017, in update_revisions
    overwrite, graph)
  File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 194, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 3370, in update_revisions
    self.target.fetch(self.source, stop_revision)
  File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 194, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 673, in fetch
    pb=pb)
  File "/usr/lib/python2.6/dist-packages/bzrlib/remote.py", line 1380, in fetch
    find_ghosts=find_ghosts, fetch_spec=fetch_spec)
  File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 194, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/bzrlib/repository.py", line 3448, in fetch
    find_ghosts=find_ghosts)
  File "/usr/lib/python2.6/dist-packages/bzrlib/fetch.py", line 73, in __init__
    self.__fetch()
  File "/usr/lib/python2.6/dist-packages/bzrlib/fetch.py", line 99, in __fetch
    self._fetch_everything_for_search(search)
  File "/usr/lib/python2.6/dist-packages/bzrlib/fetch.py", line 127, in _fetch_everything_for_search
    stream, from_format, [])
  File "/usr/lib/python2.6/dist-packages/bzrlib/remote.py", line 1841, in insert_stream
    (verb, path, resume_tokens) + lock_args, byte_stream)
  File "/usr/lib/python2.6/dist-packages/bzrlib/smart/client.py", line 181, in call_with_body_stream
    expect_response_body=False)
  File "/usr/lib/python2.6/dist-packages/bzrlib/smart/client.py", line 81, in _call_and_read_response
    expect_body=expect_response_body),
  File "/usr/lib/python2.6/dist-packages/bzrlib/smart/message.py", line 306, in read_response_tuple
    _translate_error(self.args)
  File "/usr/lib/python2.6/dist-packages/bzrlib/smart/message.py", line 361, in _translate_error
    raise errors.ErrorFromSmartServer(error_tuple)
ErrorFromSmartServer: Error received from smart server: ('error', 'bytes must be a string')

[John A Meinel (jameinel)]

marking as upstream issue.

[Andrew Bennetts (spiv)]

This is strange. I can't think of any likely causes, and I don't think any hooks are triggered by that RPC so it's unlikely to be a faulty plugin either. I think we need to see the bzr log from the server.

Oh! The error string matches an error raised by _chk_map_pyx._bytes_to_text_key. In bzr 2.3 that error message has been improved to give slightly more information, so it'd be worth upgrading the server to 2.3.

[John Szakmeister (jszakmeister)]

I'm seeing a similar issue. I've made some changes to get more debugging out, but the problem isn't present (tends to go away upon restarting the web server). When it does, I'll post more information here.

[Andrew Bennetts (spiv)]

FWIW, the error John reported on the mailing list is:

ErrorFromSmartServer: Error received from smart server: ('error', "bytes must be a string, got <type 'bzrlib._static_tuple_c.StaticTuple'>")

So something is passing a StaticTuple to _bytes_to_text_key, which sounds like some code already has a key but thinks it has the bytes representation it. The callers of that are in bzrlib/repofmt/groupcompress_repo.py; the only one of those I'd expect to be triggered on stream insertion is in GCRepositoryPackCollection._check_new_inventories, which is invoked at the end of inserting a stream, which matches the original report here and John's report on the mailing list.

The mystery then is why that code path is failing for them, because I'm pretty sure basically every write to a 2a repository would exercise that call, so presumably something earlier during receiving the stream is getting muddled. There's nothing obviously wrong with that code that I can see, and it's especially weird that it's only happening for some people sometimes, rather than constantly.

[John A Meinel (jameinel)]

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

On 05/06/2011 01:52 AM, Andrew Bennetts wrote:
> FWIW, the error John reported on the mailing list is:
>
> ErrorFromSmartServer: Error received from smart server: ('error', "bytes
> must be a string, got <type 'bzrlib._static_tuple_c.StaticTuple'>")
>
> So something is passing a StaticTuple to _bytes_to_text_key, which
> sounds like some code already has a key but thinks it has the bytes
> representation it. The callers of that are in
> bzrlib/repofmt/groupcompress_repo.py; the only one of those I'd expect
> to be triggered on stream insertion is in
> GCRepositoryPackCollection._check_new_inventories, which is invoked at
> the end of inserting a stream, which matches the original report here
> and John's report on the mailing list.
>
> The mystery then is why that code path is failing for them, because I'm
> pretty sure basically every write to a 2a repository would exercise that
> call, so presumably something earlier during receiving the stream is
> getting muddled. There's nothing obviously wrong with that code that I
> can see, and it's especially weird that it's only happening for some
> people sometimes, rather than constantly.
>

Is a foreign branch implementation involved at all? (Syncing from an svn
repository, etc?)

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

iEYEARECAAYFAk3D8fQACgkQJdeBCYSNAANnmQCgstfCfD597+pllFF+L0JxQ7o1
rLoAn1Qd7/ZhECk8BXk6/Fk0629pO9X8
=Lxhw
-----END PGP SIGNATURE-----

[John Szakmeister (jszakmeister)]

Finally hit this again.

John: no, we initially cloned from a Subversion branch but everything is in Bazaar now. I responded before... but apparently it didn't post to Launchpad. Sorry about that.

I caught this in the .bzr.log on the server:

2.150 stripping trailing bytes from groupcompress block 1639 => 316
2.153 creating new compressed block on-the-fly in 0.001s 81066 bytes => 1703 bytes
2.353 _iter_with_errors caught error
2.398 Traceback (most recent call last):
  File "/var/lib/python-support/python2.5/bzrlib/smart/protocol.py", line 1277, in _iter_with_errors
    yield None, iterator.next()
  File "/var/lib/python-support/python2.5/bzrlib/smart/repository.py", line 480, in body_stream
    for bytes in byte_stream:
  File "/var/lib/python-support/python2.5/bzrlib/smart/repository.py", line 504, in _stream_to_byte_stream
    for record in substream:
  File "/var/lib/python-support/python2.5/bzrlib/repofmt/groupcompress_repo.py", line 1247, in wrap_and_count
    for record in stream:
  File "/var/lib/python-support/python2.5/bzrlib/repofmt/groupcompress_repo.py", line 1228, in _filter_id_to_entry
    chk_map._bytes_to_text_key):
  File "/var/lib/python-support/python2.5/bzrlib/repofmt/groupcompress_repo.py", line 1347, in _filter_text_keys
    text_keys_update([bytes_to_text_key(b) for n,b in items])
  File "_chk_map_pyx.pyx", line 416, in _chk_map_pyx._bytes_to_text_key
TypeError: bytes must be a string, got <type 'bzrlib._static_tuple_c.StaticTuple'>

I have this in the bazaar.conf file, but it doesn't seem to have added anything extra:
    [DEFAULT]
    debug_flags = hpss, hpssdetail

[justink (justin-kelly)]

just adding some notes re this

- when i get this problem every second bzr push to the bzr+http server fails
- i do a push - get the error, then push again and it works

then after x period all pushes fail - this is only resolved by an apache restart

bzr 2.3.3 on the server
bzr 2.3.1 on the client

cheers

justin

[John A Meinel (jameinel)]

I think I have an idea how this is happening. I don't have a great way to prove it.

1) I think it requires having a lot of files/directories, such that the inventory pages have multiple levels.
2) It requires that something about the 'interesting' filter is causing some of the sub-tree pages to not get loaded. (Which if you have an incremental pull in a large tree, it is expected that some of the sub-sets won't get touched.)
3) It doesn't have anything to do with _chk_map_pyx.pyx specifically. It has to do with getting data that wasn't expected.

I'll try to document the program flow, because it is a bit confusing with nested generators.

_get_filtered_chk_streams(...):
  _filter_id_to_entry()
    interesting_nodes = chk_map.iter_interesting_nodes(chk_bytes,
      self._chk_id_roots, uninteresting_root_keys)
    for record in _filter_text_keys(interesting_nodes, self._text_keys,
        chk_map._bytes_to_text_key):
        if record is not None:
            yield record

and in _filter_text_keys:
def _filter_text_keys(interesting_nodes_iterable, text_keys, bytes_to_text_key):
    """Iterate the result of iter_interesting_nodes, yielding the records
    and adding to text_keys.
    """
    text_keys_update = text_keys.update
    for record, items in interesting_nodes_iterable:
        text_keys_update([bytes_to_text_key(b) for n,b in items])
        yield record

The key parts is that for every node yielded by "iter_interesting_nodes", we
expect it to be a tuple of (record, items). And then for the items themselves,
we expect them to be tuples of name, bytes.

The yielder code looks like:

    def process(self):
        for record in self._read_all_roots():
            yield record, []
        for record, items in self._process_queues():
            yield record, items

The idea is that for InternalNode objects, they should *not* have any items,
and for LeafNode objects, they should have items of the appropriate form.

What it appears to be is that we are getting some items which are in the form
"n,b" but that "b" is not a simple string, but a tuple.

The code that grabs items is in "_read_nodes_from_store(refs)": which looks
like:

def _read_nodes_from_store(self, keys):
    ...
    for record in stream:
        ...
        bytes = record.get_bytes_as('fulltext')
        node = _deserialise(bytes, record.key,
                            search_key_func=self._search_key_func)
        if type(node) is InternalNode:
            # Note we don't have to do node.refs() because we know that
            # there are no children that have been pushed into this node
            ...
            prefix_refs = node._items.items()
            items = []
        else:
            prefix_refs = []
            ...
            items = node._items.items()
        yield record, node, prefix_refs, items

Looking at that, we force items to be an empty list if it is an InternalNode.
So this has to be happening on a LeafNode.

Looking at the code parser for LeafNodes, the 'key' portion is rather complex,
but we have:
    value = PyString_FromStringAndSize(value_start, next_line - value_start)
    ...
    entry_bits = StaticTuple_Intern(entry_bits)
    PyDict_Set...

[James Gregory-Monk (jamgregory)]

We're seeing this particular error with one of our repositories (originally submitted via bug #656178; re-submitted in bug #815845 by myself). The usual fix was to remove the _chk_map_pyx extension, but I'd rather find a permanent fix.

So, based on your research @John, where can we go with this to try and get it fixed? Point 1) is definitely applicable in our case (~800 items).

As noted in #656178, a rebuild of _chk_map_pyx from trunk seems to fix the issue, so is it perhaps a problem with that version being out of date?

[Launchpad Janitor (janitor)]

[Expired for Bazaar because there has been no activity for 60 days.]

[Martin Pool (mbp)]

    status confirmed