bzr branch from launchpad disconnected after exactly one hour

Andrew -- thanks for posting this!

It's pretty likely that you're being cut off by the idle timeout, but not at all clear why the connection was idle for an hour. That really shouldn't happen. You say this is repeatable?

Are you branching into a shared repo? I could just about imagine that a cross-format fetch might stall like this.

On Mon, 15 Mar 2010 17:00:10 Michael Hudson wrote:
> It's pretty likely that you're being cut off by the idle timeout, but
> not at all clear why the connection was idle for an hour. That really
> shouldn't happen. You say this is repeatable?
>
> Are you branching into a shared repo? I could just about imagine that a
> cross-format fetch might stall like this.

Also the first branch into an empty shared repo is extremely slow for a large
tree.

Tim Penhey wrote:
> On Mon, 15 Mar 2010 17:00:10 Michael Hudson wrote:
>> It's pretty likely that you're being cut off by the idle timeout, but
>> not at all clear why the connection was idle for an hour. That really
>> shouldn't happen. You say this is repeatable?
>>
>> Are you branching into a shared repo? I could just about imagine that a
>> cross-format fetch might stall like this.
>
> Also the first branch into an empty shared repo is extremely slow for a large
> tree.

Yes, but the connection isn't idle all that time -- it's messages going
back and forth to walk over the revision graph that causes the slowness
AIUI.

Cheers,
mwh

Michael, Tim --

> It's pretty likely that you're being cut off by the idle timeout, but
> not at all clear why the connection was idle for an hour.  That really
> shouldn't happen.  You say this is repeatable?

The connection wasn't idle -- the progress line was updating steadily
right up to the hour mark, then stopped.

I tried it 3-4 times, IIRC, and all hung at an hour. Also (as I now
know from trying the suggested workaround of splitting the branch up
into an initial revision-limited branch followed by pulls with
progressively higher revision limits) that a pull time out if the
revisions it's inserting are big enough. That happened twice.

> Are you branching into a shared repo?  I could just about imagine
> that a cross-format fetch might stall like this.

I didn't use a shared repo -- I only expect to need one web2py branch.

-- Pat

Wondering if there's any progress on the one hour timeout issue? I just tried bzr branch with web2py again, and it hung and then timed out an hour later, just as in this report.

Note this branch is into an empty directory. Here's where it stopped:
$ bzr branch --use-existing-dir lp:~mdipierro/web2py/devel web2py
- 104344KB 30KB/s | Fetching revisions:Inserting stream

And an hour later:
FATAL ERROR: Server unexpectedly closed network connection
bzr: ERROR: Connection closed: Unexpected end of message. Please check connectiv
ity and permissions, and report a bug if problems persist.

IIRC the conclusion before was that there was a very large revision, and a lot of behind the scenes activity, but not what launchpad monitors to determine if the connection is idle. In the original case, the existence of a large revision was confirmed, and the same hang and timeout was reproduced on a single revision, by doing a bzr branch to rev 1, then bzr pull to extract individual revsions, one at a time.

My network connection is DSL but not a really expensive high-speed line. The last time I needed to branch web2py, the "workaround" was to find someone with a very high-speed connection who did the branch, tarred up the result and sent it to me.

Proposed solution was to have lp monitor both ports (or however the activity is partitioned). Proposed temporary workaround was to increase the "idle" timeout.

One contributing factor here is that the branch lp:~mdipierro/web2py/devel is in an old bzr format and it will be faster for all involved if the owner upgrades it.

To summarize, there are three phases:

0-60m bzr slowly pulls stuff
60-120m bzr apparently stuck doing nothing
120m server disconnects the client

It's not surprising that the client's disconnected after an hour of inactivity; in fact that's a feature. The real problem is that we hang for an hour before that. It would be highly useful to get a traceback during that phase.

Its possibly the 'convert revs on server' if the target branch is a 2a format.

fwiw on my home ADSL connection, I can branch from there in about 18m, pulling down 600MB of revision history, without apparently hanging at any point. I could try slowing it down and see what happens after an hour.

Pat, just to confirm there's no destination repository, can you please
run 'bzr info' in the directory where you're trying to make your new
branch.

On Mon, Sep 27, 2010 at 8:56 PM, Martin Pool <email address hidden> wrote:

> One contributing factor here is that the branch
> lp:~mdipierro/web2py/devel is in an old bzr format and it will be faster
> for all involved if the owner upgrades it.
>
> To summarize, there are three phases:
>
> 0-60m bzr slowly pulls stuff
> 60-120m bzr apparently stuck doing nothing
> 120m server disconnects the client
>
> It's not surprising that the client's disconnected after an hour of
> inactivity; in fact that's a feature.
>

> The real problem is that we hang
> for an hour before that. It would be highly useful to get a traceback
> during that phase.
>

That's not what I understood from the investigation that has already been
done, but I could be wrong... It sounds as though there is *no* period of
inactivity. There are *not* two separate one hour intervals involved.
Rather, the bzr activity that is going on is not regarded as activity by
launchpad. During the one hour of what launchpad regards as inactivity, bzr
is busy doing something relating to a single enormous revision, which is
possibly a collection of a large number of merged revisions.

So rather than three phases:

0 to N hours: bzr is visibly making progress.
N to N+1 hours: bzr stops visibly making progress.
N+1 hour: bzr exits with error.

-- Pat

On Mon, Sep 27, 2010 at 9:29 PM, Martin Pool <email address hidden> wrote:

> Pat, just to confirm there's no destination repository, can you please
> run 'bzr info' in the directory where you're trying to make your new
> branch.
>

Too late -- I needed that exact directory to be functional (it's hard-linked
from elsewhere so can't change it). So it's already had a bzr checkout done
into it.

-- Pat

On Mon, Sep 27, 2010 at 9:28 PM, Martin Pool <email address hidden> wrote:

> fwiw on my home ADSL connection, I can branch from there in about 18m,
> pulling down 600MB of revision history, without apparently hanging at
> any point. I could try slowing it down and see what happens after an
> hour.
>

Then your connection is considerably faster than mine.

bzr was reporting rates of 30KB/sec on mine.

-- Pat

@#11 I think that's the timeline I was describing too. I don't think it's ever more than 1 hour of actual useful work, is it? Then there's one hour stuck, then that phase is terminating by the whole program erroring.

I just tested this with an additional 1000ms latency on eth0, and it completed in 43m, probably not enough to provoke whatever's happening at the 1h mark. I would have thought that if there was something CPU-bound that caused a long hang, it would show up in this. This branching used only 36s cpu time locally, so it seems unlikely that could blow out to 1h of work unless your machine is much slower. It may be you have some kind of environment where things do become much worse.

Do you now have a working branch or are you still blocked?

> @#11 I think that's the timeline I was describing too. I don't think
> it's ever more than 1 hour of actual useful work, is it?

Considerably more than 1 hour. IIRC it ran for about 5-6 hours before it
quit updating. And we did track it down to a single huge revision. During
the previous investigation, I pulled one revision at a time. I don't have
the revision #.

> Then there's one hour stuck,

Or one hour spent fussing with that one huge revision. I believe that this
is also documented -- these is a description of what it's doing during that
time.

> then that phase is terminating by the whole program erroring.
>

And then it gets disconnected at the launchpad end. The local bzr just
reports that.

-- Pat

This is likely to have been caused by bug 556132, which is now fixed. Searching google for "ssh rekey hour" finds plenty of FAQs about various SSH clients (e.g. SSH Corp's client) that automatically initiate a rekey after exactly one hour by default, perhaps current OpenSSH does too, and that would have provoked this problem. So perhaps we should close this bug.

I agree this is very likely a dupe. It has been fixed on Launchpad and does not need an upgrade to your bzr client. If it happens again, please let us know.