Bazaar

Large readv requests can fail if there is a squid proxy

Bug #172701 reported by Andrew Bennetts
4
Affects Status Importance Assigned to Milestone
Bazaar
Fix Released
High
Vincent Ladeuil
Bazaar 1.0rc2

Bug Description

I have a bzr branch at 2977 <email address hidden> in packs-0.92 format.

I have a checkout (in a separate repository) of current bzr.dev (3041 <email address hidden>)

When using current bzr.dev to update the 2977 branch from http://bazaar-vcs.org/bzr/bzr.dev/ I got this error:

ShortReadvError: readv() read unknown bytes rather than unknown bytes at unknown for "http://bazaar-vcs.org/bzr/bzr.dev/.bzr/repository/packs/a3069b4df97462558e8666ff0cc72386.pack": Server aborted the request

Also, it took 38m32s wall time!

This is repeatable. (It's slightly exacerbated by the fact that bzr is uninterruptible by Ctrl-C or Ctrl-\ during this, apparently due to being inside pycurl; I think there's already a bug about that).

At Robert's suggestion, I bypassed my home network's squid proxy. This avoids the problem; the pull succeeds in slightly over 3 minutes.

Here is the full .bzr.log contents for this invocation:

bzr arguments: [u'pull']
looking for plugins in /home/andrew/.bazaar/plugins
looking for plugins in /tmp/bzr.packs/bzrlib/plugins
Plugin name __init__ already loaded
Plugin name __init__ already loaded
encoding stdout as sys.stdout encoding 'UTF-8'
opening working tree '/home/andrew/code/bzr'
Using fetch logic to copy between KnitPackRepository('http://bazaar-vcs.org/bzr/bzr.dev/.bzr/repository/')(<RepositoryFormatKnitPack1>) and KnitPackRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/')(<RepositoryFormatKnitPack1>)
http readv of f0ae98050acf842c11486dd3dcc0ef75.rix offsets => 1 collapsed 1
http readv of d43342146cbf98cd66e141951aaacedb.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of 9f1056346e647aa6bf7d1b4924576496.rix offsets => 1 collapsed 1
http readv of 35730a0dd2a53acfad8a4028ec9a093d.rix offsets => 1 collapsed 1
http readv of 113bedab2bf1df16bc8eb75ae016bf35.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.rix offsets => 2 collapsed 2
http readv of 9f1056346e647aa6bf7d1b4924576496.pack offsets => 3 collapsed 1
http readv of d43342146cbf98cd66e141951aaacedb.pack offsets => 3 collapsed 1
http readv of 35730a0dd2a53acfad8a4028ec9a093d.pack offsets => 11 collapsed 1
http readv of 113bedab2bf1df16bc8eb75ae016bf35.pack offsets => 5 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.pack offsets => 381 collapsed 4
http readv of f0ae98050acf842c11486dd3dcc0ef75.pack offsets => 3 collapsed 1
http readv of d43342146cbf98cd66e141951aaacedb.iix offsets => 1 collapsed 1
http readv of 35730a0dd2a53acfad8a4028ec9a093d.iix offsets => 1 collapsed 1
http readv of f0ae98050acf842c11486dd3dcc0ef75.iix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.iix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.iix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.iix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.iix offsets => 6 collapsed 6
http readv of 9f1056346e647aa6bf7d1b4924576496.iix offsets => 1 collapsed 1
http readv of 113bedab2bf1df16bc8eb75ae016bf35.iix offsets => 1 collapsed 1
http readv of d43342146cbf98cd66e141951aaacedb.pack offsets => 3 collapsed 2
http readv of 35730a0dd2a53acfad8a4028ec9a093d.pack offsets => 11 collapsed 2
http readv of f0ae98050acf842c11486dd3dcc0ef75.pack offsets => 3 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.pack offsets => 381 collapsed 4
http readv of 9f1056346e647aa6bf7d1b4924576496.pack offsets => 3 collapsed 2
http readv of 113bedab2bf1df16bc8eb75ae016bf35.pack offsets => 5 collapsed 2
http readv of 35730a0dd2a53acfad8a4028ec9a093d.tix offsets => 1 collapsed 1
http readv of d43342146cbf98cd66e141951aaacedb.tix offsets => 1 collapsed 1
http readv of 9f1056346e647aa6bf7d1b4924576496.tix offsets => 1 collapsed 1
http readv of 113bedab2bf1df16bc8eb75ae016bf35.tix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 1 collapsed 1
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 2 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 4 collapsed 4
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 8 collapsed 8
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 8 collapsed 8
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 14 collapsed 14
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 10 collapsed 10
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 16 collapsed 16
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 3 collapsed 3
http readv of a3069b4df97462558e8666ff0cc72386.tix offsets => 9 collapsed 9
http readv of f0ae98050acf842c11486dd3dcc0ef75.tix offsets => 1 collapsed 1
http readv of 35730a0dd2a53acfad8a4028ec9a093d.pack offsets => 17 collapsed 2
http readv of d43342146cbf98cd66e141951aaacedb.pack offsets => 2 collapsed 2
http readv of 9f1056346e647aa6bf7d1b4924576496.pack offsets => 3 collapsed 2
http readv of 113bedab2bf1df16bc8eb75ae016bf35.pack offsets => 6 collapsed 2
http readv of a3069b4df97462558e8666ff0cc72386.pack offsets => 649 collapsed 149
got pycurl error: 18, transfer closed with 162685 bytes remaining to read, (18, 'transfer closed with 162685 bytes remaining to read'), url: http://bazaar-vcs.org/bzr/bzr.dev/.bzr/repository/packs/a3069b4df97462558e8666ff0cc72386.pack
Traceback (most recent call last):
  File "/tmp/bzr.packs/bzrlib/commands.py", line 802, in run_bzr_catch_errors
    return run_bzr(argv)
  File "/tmp/bzr.packs/bzrlib/commands.py", line 758, in run_bzr
    ret = run(*run_argv)
  File "/tmp/bzr.packs/bzrlib/commands.py", line 492, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/tmp/bzr.packs/bzrlib/builtins.py", line 646, in run
    possible_transports=possible_transports)
  File "/tmp/bzr.packs/bzrlib/decorators.py", line 165, in write_locked
    return unbound(self, *args, **kwargs)
  File "/tmp/bzr.packs/bzrlib/workingtree.py", line 1529, in pull
    possible_transports=possible_transports)
  File "/tmp/bzr.packs/bzrlib/decorators.py", line 165, in write_locked
    return unbound(self, *args, **kwargs)
  File "/tmp/bzr.packs/bzrlib/branch.py", line 1697, in pull
    run_hooks=run_hooks)
  File "/tmp/bzr.packs/bzrlib/decorators.py", line 165, in write_locked
    return unbound(self, *args, **kwargs)
  File "/tmp/bzr.packs/bzrlib/branch.py", line 1489, in pull
    self.update_revisions(source, stop_revision)
  File "/tmp/bzr.packs/bzrlib/decorators.py", line 165, in write_locked
    return unbound(self, *args, **kwargs)
  File "/tmp/bzr.packs/bzrlib/branch.py", line 1458, in update_revisions
    self.fetch(other, stop_revision)
  File "/tmp/bzr.packs/bzrlib/decorators.py", line 165, in write_locked
    return unbound(self, *args, **kwargs)
  File "/tmp/bzr.packs/bzrlib/branch.py", line 286, in fetch
    pb=nested_pb)
  File "/tmp/bzr.packs/bzrlib/repository.py", line 873, in fetch
    return inter.fetch(revision_id=revision_id, pb=pb, find_ghosts=find_ghosts)
  File "/tmp/bzr.packs/bzrlib/decorators.py", line 165, in write_locked
    return unbound(self, *args, **kwargs)
  File "/tmp/bzr.packs/bzrlib/repository.py", line 2558, in fetch
    revision_ids).pack()
  File "/tmp/bzr.packs/bzrlib/repofmt/pack_repo.py", line 559, in pack
    return self._create_pack_from_packs()
  File "/tmp/bzr.packs/bzrlib/repofmt/pack_repo.py", line 660, in _create_pack_from_packs
    new_pack._writer, new_pack.text_index))
  File "/tmp/bzr.packs/bzrlib/repofmt/pack_repo.py", line 788, in _do_copy_nodes_graph
    izip(reader.iter_records(), pack_readv_requests):
  File "/tmp/bzr.packs/bzrlib/pack.py", line 253, in iter_records
    self._read_format()
  File "/tmp/bzr.packs/bzrlib/pack.py", line 294, in _read_format
    format = self._read_line()
  File "/tmp/bzr.packs/bzrlib/pack.py", line 221, in _read_line
    line = self._source.readline()
  File "/tmp/bzr.packs/bzrlib/pack.py", line 185, in readline
    self._next()
  File "/tmp/bzr.packs/bzrlib/pack.py", line 172, in _next
    length, data = self.readv_result.next()
  File "/tmp/bzr.packs/bzrlib/transport/http/__init__.py", line 270, in _readv
    f = self._get_ranges_hinted(relpath, coalesced)
  File "/tmp/bzr.packs/bzrlib/transport/http/__init__.py", line 232, in _get_ranges_hinted
    code, f = self._get(relpath, ranges)
  File "/tmp/bzr.packs/bzrlib/transport/http/_pycurl.py", line 162, in _get
    return self._get_ranged(relpath, offsets, tail_amount=tail_amount)
  File "/tmp/bzr.packs/bzrlib/transport/http/_pycurl.py", line 222, in _get_ranged
    self._curl_perform(curl, header, ['Range: bytes=%s' % range_header])
  File "/tmp/bzr.packs/bzrlib/transport/http/_pycurl.py", line 304, in _curl_perform
    extra='Server aborted the request')
ShortReadvError: readv() read unknown bytes rather than unknown bytes at unknown for "http://bazaar-vcs.org/bzr/bzr.dev/.bzr/repository/packs/a3069b4df97462558e8666ff0cc72386.pack": Server aborted the request

return code 4

Revision history for this message
Vincent Ladeuil (vila) wrote : Re: [Bug 172701] Large readv requests can fail if there is a squid proxy
Download full text (3.6 KiB)

>>>>> "Andrew" == Andrew Bennetts <email address hidden> writes:

    Andrew> Public bug reported:
    Andrew> I have a bzr branch at 2977
    Andrew> <email address hidden> in packs-0.92 format.

    Andrew> I have a checkout (in a separate repository) of current bzr.dev (3041
    Andrew> <email address hidden>)

    Andrew> When using current bzr.dev to update the 2977 branch from http://bazaar-
    Andrew> vcs.org/bzr/bzr.dev/ I got this error:

    Andrew> ShortReadvError: readv() read unknown bytes rather than unknown bytes at
    Andrew> unknown for "http://bazaar-
    Andrew> vcs.org/bzr/bzr.dev/.bzr/repository/packs/a3069b4df97462558e8666ff0cc72386.pack":
    Andrew> Server aborted the request

    Andrew> Also, it took 38m32s wall time!

Ouch.

    Andrew> This is repeatable. (It's slightly exacerbated by the fact that bzr is
    Andrew> uninterruptible by Ctrl-C or Ctrl-\ during this, apparently due to being
    Andrew> inside pycurl; I think there's already a bug about that).

I don't remember a bug about this, but even, we can hardly fix
it, the workaround is to use urllib instead.

    Andrew> At Robert's suggestion, I bypassed my home network's squid proxy. This
    Andrew> avoids the problem; the pull succeeds in slightly over 3 minutes.

Robert, what made you think about that work-around ?

    Andrew> Here is the full .bzr.log contents for this invocation:

    Andrew> bzr arguments: [u'pull']
    Andrew> looking for plugins in /home/andrew/.bazaar/plugins
    Andrew> looking for plugins in /tmp/bzr.packs/bzrlib/plugins
    Andrew> Plugin name __init__ already loaded
    Andrew> Plugin name __init__ already loaded
    Andrew> encoding stdout as sys.stdout encoding 'UTF-8'
    Andrew> opening working tree '/home/andrew/code/bzr'
    Andrew> Using fetch logic to copy between KnitPackRepository('http://bazaar-vcs.org/bzr/bzr.dev/.bzr/repository/')(<RepositoryFormatKnitPack1>) and KnitPackRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/')(<RepositoryFormatKnitPack1>)

<snip/>
    Andrew> http readv of a3069b4df97462558e8666ff0cc72386.pack offsets => 649 collapsed 149
    Andrew> got pycurl error: 18, transfer closed with 162685 bytes remaining to read, (18, 'transfer closed with 162685 bytes remaining to read'), url: http://bazaar-vcs.org/bzr/bzr.dev/.bzr/repository/packs/a3069b4df97462558e8666ff0cc72386.pack

This is pycurl detecting a short read, to say the truth I never
encountered it myself, the code was ready for it though. packs
are really making life hard for our http implementations ;-)

Did your squid logs shed some light on why it occurred ?
Apparently the 169 ranges request was accepted so I wonder why it
decided to interrupt the transfer of the body part...

Anyway, that confirmed just what I was afraid of, it means readv
has to keep track of which offsets have been already transferred
to avoid requesting them again.

<snip/>

    Andrew> File "/tmp/bzr.packs/bzrlib/transport/http/_pycurl.py", line 304, in _curl_perform
    Andrew> extra='Server aborted the request')
    Andrew> ShortReadvError: readv() read unknown bytes rather t...

Read more...

Changed in bzr:
assignee: nobody → v-ladeuil
importance: Undecided → High
status: New → Incomplete
Vincent Ladeuil (vila)
Changed in bzr:
status: Incomplete → In Progress
Revision history for this message
Vincent Ladeuil (vila) wrote :

A fix was released but I'm not able to reproduce the bug, so reopen it with more info if you can.

Changed in bzr:
milestone: none → 1.0alpha2
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.