infinite loop in CachingLogWalker.fetch_revisions

[Martin von Gagern]

With bzr 1.5, subversion 1.5.0 rc5 and bzr-svn 0.4.10 I get an infinite loop when running this command:
bzr branch http://svn.unix-ag.uni-kl.de/vpnc/trunk

This whole issue might be related to my fix of bug #229419 by passing NULL as the paths argument of svn_ra_get_log2, in connection with patches to my Subversion according to http://svn.collab.net/viewvc/svn/trunk/subversion/libsvn_ra/ra_loader.c?r1=31470&r2=31425. So yes, it might be a bit early to cry, and it might be difficult to reproduce this with released code, but for developers working with snapshot versions it should be possible to address the issue.

I'm not a Python programmer, but I tracked the problem to CachingLogWalker.fetch_revisions:

                while self.saved_revnum < to_revnum:
                    for (orig_paths, revision, revprops) in self.actual._transport.iter_log(None, self.saved_revnum,
                                             to_revnum, self.actual._limit, True,
                                             True, []):

For some reason, iter_log immediately returns None here, therefore the for body won't get executed, therefore saved_revnum won't change, therefore the while will run over and over again.

Trying to figure out why the iterator returns no result is difficult. It seems that pdb has limited multithreading capabilities. Calling pdb.set_trace() inside logfetcher.run was my solution to achieve this.

It seems that in this case the server was sending an empty report, so that the receiver callback was never invoked to add elements. This might well be a bug in SVN, I don't know, but even if the server acts weird, you woudln't want this kind of inifinite loop, so a sanity check would be in order.

[Jelmer Vernooij (jelmer)]

That branch works fine here with Subversion 1.4 + patches.

I'll see if I can reproduce with 1.5 later today.

[Mirko Friedenhagen (mfriedenhagen)]

Propably this is what I am seeing as well when trying to catch up with the Hudson-Repo:

bzr pull hangs forever in transport.py:607 (def next). In the log-file I see entries like:

4.651 opening SVN RA connection to 'https://<email address hidden>/svn/hudson/trunk/hudson'
6.087 svn get-repos-root
6.676 svn get-uuid
6.689 svn get-latest-revnum
7.243 svn get-latest-revnum
7.798 svn log 9634:9770 None (limit: 0)
8.354 get_log2: None
[repeated until I hit Ctrl-C ...]
464.766 svn log 9634:9770 None (limit: 0)
465.321 get_log2: None

The second line is the result of muttering a bit more :-):
=== modified file 'transport.py'
--- transport.py 2008-06-02 20:52:24 +0000
+++ transport.py 2008-06-02 22:17:29 +0000
@@ -429,10 +429,12 @@
             paths = ["/"]
         self.mutter('svn log %r:%r %r (limit: %r)' % (from_revnum, to_revnum, paths, limit))
         if hasattr(svn.ra, 'get_log2'):
- return svn.ra.get_log2(self._ra, paths,
+ result = svn.ra.get_log2(self._ra, paths,
                            from_revnum, to_revnum, limit,
                            discover_changed_paths, strict_node_history, False,
                            revprops, rcvr, pool)
+ self.mutter("get_log2: %r" % result)
+ return result

         class LogEntry(object):
             def __init__(self, changed_paths, rev, author, date, message):

Software-Versions in use:
svn-trunk revision 31557
bzr-svn stable revno 1196
bzr 1.6b1 (tried 1.5 as well, no difference)

[Jelmer Vernooij (jelmer)]

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

Mirko Friedenhagen wrote:
> Propably this is what I am seeing as well when trying to catch up
> with the Hudson-Repo:
>
> bzr pull hangs forever in transport.py:607 (def next). In the
> log-file I see entries like:
>
> 4.651 opening SVN RA connection to
> 'https://<email address hidden>/svn/hudson/trunk/hudson' 6.087
> svn get-repos-root 6.676 svn get-uuid 6.689 svn get-latest-revnum
> 7.243 svn get-latest-revnum 7.798 svn log 9634:9770 None (limit:
> 0) 8.354 get_log2: None [repeated until I hit Ctrl-C ...] 464.766
> svn log 9634:9770 None (limit: 0) 465.321 get_log2: None
>
> The second line is the result of muttering a bit more :-): ===
> modified file 'transport.py' --- transport.py 2008-06-02
> 20:52:24 +0000 +++ transport.py 2008-06-02 22:17:29 +0000 @@
> -429,10 +429,12 @@ paths = ["/"] self.mutter('svn log %r:%r %r
> (limit: %r)' % (from_revnum, to_revnum, paths, limit)) if
> hasattr(svn.ra, 'get_log2'): - return
> svn.ra.get_log2(self._ra, paths, + result =
> svn.ra.get_log2(self._ra, paths, from_revnum, to_revnum, limit,
> discover_changed_paths, strict_node_history, False, revprops, rcvr,
> pool) + self.mutter("get_log2: %r" % result) +
> return result
>
> class LogEntry(object): def __init__(self, changed_paths, rev,
> author, date, message):
>
>
> Software-Versions in use: svn-trunk revision 31557 bzr-svn stable
> revno 1196 bzr 1.6b1 (tried 1.5 as well, no difference)
svn_get_log2() isn't supposed to return anything - it will call the
supplied callback function 'rcvr' with information so you'd probably
want to add a mutter there.

Cheers,

Jelmer
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iQCVAwUBSER+/Qy0JeEGD2blAQI4WAP/Xscra8uXp/IFUB6NhBmNXY6n4OQwEqQf
i/FUIAPJTuauMx/bMaz7adPwPiIBmQCZOI5Ua+sCUrZIrMLucNmLL+t1Q+nO7rV0
Qr1D4PBT8yJ3936FBgF8qIcC/qVg3Ur/q2cCWpw8T05XXPQHAqY7IMl//8H10aor
lPYPY7Yf9SA=
=eHZJ
-----END PGP SIGNATURE-----

[Jelmer Vernooij (jelmer)]

I can reproduce this problem now.

Subverison doesn't appear to be calling our callback function, which makes me doubt that specifying None for paths is the right solution. Perhaps another bug on subversions side? It seems like passing none for paths should return all changes rather than none.

[Martin von Gagern (gagern)]

Yes, this does look like another bug on the subversion side. Probably an incompatibility between the 1.5 library and an 1.4 server out there.

I had a look at the network traffic from both my failing svn-1.5 setup and the working 1.4 ubuntu binary package. Two notable differences:

1. the old lib passes <S:path></S:path> along with the log-report request. So setting the path to [""] instead of ["/"] or None should be a solution that works with all libraries, getting rid of the version check and avoiding complaints by the assertion check inside subversion. I guess that's the correct (i.e. working) fix for bug 229419.

2. The new lib performs most requests, including the one for log-report, on the selected subtree instead of the base path of the repository. In terms of efficiency, this does seem a good idea. However, this means that revisions only affecting other parts of the tree won't be included. Therefore the logwalker never reaches to_revnum, still resulting in an infinite look. As there is some strange request for "PROPFIND /vpnc/trunk/.." in the traffic, this might be yet another bug in subversion, I'm still investigating this.

[Jelmer Vernooij (jelmer)]

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

Martin von Gagern wrote:
> Yes, this does look like another bug on the subversion side.
> Probably an incompatibility between the 1.5 library and an 1.4
> server out there.
>
> I had a look at the network traffic from both my failing svn-1.5
> setup and the working 1.4 ubuntu binary package. Two notable
> differences:
>
> 1. the old lib passes <S:path></S:path> along with the log-report
> request. So setting the path to [""] instead of ["/"] or None
> should be a solution that works with all libraries, getting rid of
> the version check and avoiding complaints by the assertion check
> inside subversion. I guess that's the correct (i.e. working) fix
> for bug 229419.
There is a difference between [""] and ["/"] - [""] means the current
directory, ["/"] means the root of the repository. This is relevant
since it is not always possible to connect to the root of the repository.

Cheers,

jelmer

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

iQCVAwUBSEUlowy0JeEGD2blAQJ2yQP+I47L6bLGpR9di2DzVa5rEhpH7g00SAcT
usjY0FxXlZOtdJbo0v+n3YnlcOF06WdVh8qOW6ew1Kp6dfGWEFAAGP7KJRm1BCl1
2mLsXpMuZV/DHuqSkPttgirWsMexsY8vUMvcR2pmb7t5+vB3g5hkSSCUDoIxGmur
Fn9I8IUY8yE=
=a18W
-----END PGP SIGNATURE-----

[Martin von Gagern (gagern)]

Status update on what's happening with this bug here.

bzr-svn is designed not to force connection to the root of the repository in order to avoid bug #80553. As svn-1.5 no longer allows access to the log of / from any connection, the log cache had to be redesigned to work with partial logs. This has the added benefit of not requiring full logs when working on a small part of really large projects. It makes the cache handling more complicated, though, and in some situations cached data has to be re-requested.

The related branch svn-1.5 contains a proposed solution for this issue, so have a look at its merge status.

[Mirko Friedenhagen (mfriedenhagen)]

Hello Martin,

I am using bzr-1.6b1, svn built from trunk revision 31634 and your svn-1.5-branch. Pulling into my existing copy of the hudson-trunk (password for guest is empty), I receive:

--- snip ---
(uiserver):u42913263:~/bzr/hudson/trunk > bzr pull -Dtransport -v
Using saved location: https://guest:@hudson.dev.java.net/svn/hudson/trunk/hudson/
bzr-svn is not up to date with installed bzr version 1.6b1.
There should be a newer version of bzr-svn available.
python: subversion/libsvn_subr/path.c:439: svn_path_is_empty: Assertion `is_canonical(path, strlen(path))' failed.
Aborted
--- snap ---

Pulling freshly from start, removing svn-cache beforehand produces the same error-message:

--- snip ---
(uiserver):u42913263:~/bzr/hudson > bzr checkout svn+https://guest:@hudson.dev.java.net/svn/hudson/trunk/hudson/ trunk-new
bzr-svn is not up to date with installed bzr version 1.6b1.
There should be a newer version of bzr-svn available.
Initialising Subversion metadata cache in /kunden/homepages/32/d184636148/htdocs/.bazaar/svn-cache/71c3de6d-444a-0410-be80-ed276b4c234a
python: subversion/libsvn_subr/path.c:439: svn_path_is_empty: Assertion `is_canonical(path, strlen(path))' failed.
Aborted
--- snap ---

The cache is filled containing a cache-4 db of 9.4 MB.

Regards
Mirko

[Mirko Friedenhagen (mfriedenhagen)]

Same happens with bzr-1.5.

[Jelmer Vernooij (jelmer)]

The limit stuff has been removed.