Crash on subtree where child dir used to be a peer and was copied with mods

Is this a public repository and is it reproducible ?

Does the repository contain any revisions pushed using bzr-svn?

Unfortunately this is not a public repository, so I'm not able to point to it. The error is reproducable in that it happens every time, but I haven't figured out a way to reproduce the error with a demo repository.

I have been using bzr-svn with it since early 0.4.x, so it's possible there is something bad that happened back then, but svn itself is happy, and the repository still works fine with bzr-svn as long as I don't try to operate on a parent of the tree that's having the problem.

Is there some information that I could query out of the repository (e.g. bzr-svn props, etc) that would useful?

Another odd thing: "bzr log" and "bzr vis" both work, but "bzr log -v" fails with the same error described above.

More specifically about bzr vis: it shows the revision graph and short log messages, but clicking on any revision to get more info results in the same traceback (but it doesn't crash bzr vis).

Okay, this is *TOTAL MINDLESS HACK AND SLASH*, but for kicks I tried to just ignore the errors with the following patch and see what else fails. But as far as I can tell, everything appears to be "working". Again, this is provided in case this gives information about the root cause. I don't think this is actually a correct way to fix this. (You probably know that better than me!)

--- /usr/lib/python2.5/site-packages/bzrlib/plugins/svn/fileids.py.orig 2008-12-03 09:04:05.000000000 -0700
+++ /usr/lib/python2.5/site-packages/bzrlib/plugins/svn/fileids.py 2008-12-03 09:05:28.000000000 -0700
@@ -188,11 +188,17 @@
         """
         for p in changes:
             if changes[p][0] == 'M' and not delta.has_key(p):
- delta[p] = map[p][0]
+ try:
+ delta[p] = map[p][0]
+ except KeyError:
+ pass

         for x in sorted(delta.keys(), reverse=True):
             if delta[x] is None:
- del map[x]
+ try:
+ del map[x]
+ except KeyError:
+ pass
                 for p in map.keys():
                     if p.startswith(u"%s/" % x):
                         del map[p]

With the above patch, doing a "bzr log -v", actually works up until a specific revision, but then results in the following traceback:

bzr: ERROR: exceptions.KeyError: u'linux_driver/loadXilinxDriver'

Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 893, in run_bzr_catch_errors
    return run_bzr(argv)
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 839, in run_bzr
    ret = run(*run_argv)
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 539, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 853, in ignore_pipe
    result = func(*args, **kwargs)
  File "/usr/lib/python2.5/site-packages/bzrlib/builtins.py", line 1873, in run
    limit=limit)
  File "/usr/lib/python2.5/site-packages/bzrlib/log.py", line 182, in show_log
    start_revision, end_revision, search, limit)
  File "/usr/lib/python2.5/site-packages/bzrlib/log.py", line 225, in _show_log
    for revs in revision_iterator:
  File "/usr/lib/python2.5/site-packages/bzrlib/log.py", line 367, in _generate_deltas
    revs = [(rev[0], rev[1], delta) for rev, delta in izip(revs, deltas)]
  File "/usr/lib/python2.5/site-packages/bzrlib/plugins/svn/repository.py", line 337, in get_deltas_for_revisions
    yield self.get_revision_delta(revision)
  File "/usr/lib/python2.5/site-packages/bzrlib/plugins/svn/repository.py", line 361, in get_revision_delta
    reporter.finish()
  File "/usr/lib/python2.5/site-packages/bzrlib/plugins/svn/fetch.py", line 194, in close
    return self._close()
  File "/usr/lib/python2.5/site-packages/bzrlib/plugins/svn/fetch.py", line 533, in _close
    self.editor.delta.modified.append((self.path, self.editor._get_new_id(self.path), entry_kind, text_changed, metadata_changed))
  File "/usr/lib/python2.5/site-packages/bzrlib/plugins/svn/fetch.py", line 593, in _get_new_id
    return self._idmap[path][0]
KeyError: u'linux_driver/loadXilinxDriver'

bzr 1.9 on python 2.5.2 (linux2)
arguments: ['/usr/bin/bzr', 'log', '-v']
encoding: 'UTF-8', fsenc: 'UTF-8', lang: 'en_US.UTF-8'
plugins:
  bisect /home/wjlanda/.bazaar/plugins/bisect [1.1.0pre0]
  bzrtools /usr/lib/python2.5/site-packages/bzrlib/plugins/bzrtools [1.9.1]
  cvsps_import /usr/lib/python2.5/site-packages/bzrlib/plugins/cvsps_import [unknown]
  gtk /usr/lib/python2.5/site-packages/bzrlib/plugins/gtk [0.96.0dev1]
  launchpad /usr/lib/python2.5/site-packages/bzrlib/plugins/launchpad [unknown]
  loom /usr/lib/python2.5/site-packages/bzrlib/plugins/loom [1.4.0dev0]
  rebase /usr/lib/python2.5/site-packages/bzrlib/plugins/rebase [0.4.1]
  search /usr/lib/python2.5/site-packages/bzrlib/plugins/search [1.6.0dev3]
  stats /usr/lib/python2.5/site-packages/bzrlib/plugins/stats [unknown]
  svn /usr/lib/python2.5/site-packages/bzrlib/plugins/svn [0.4.15dev0]
  upload /usr/lib/python2.5/site-packages/bzrlib/plugins/upload [0.1.0]
*** Bazaar has encountered an internal error.
    Please report a bug at https://bugs.laun...

I should have included the svn diff of that revision:

$ svn diff -r627:628

Property changes on: linux_driver/loadXilinxDriver
___________________________________________________________________
Added: svn:executable
   + *

Hopefully, some of this is helpful ...

Thanks, that helps. Any chance you can paste the output of "svn log -v 627:628" as well?

So fwiw, it seems like when doing the analysis for file ids, bzr doesn't pick up files that have just changed their properties, not their contents.

Here is the log. As you can see from the diff and this log, you are right: it is only a property change, not a content change on this file.

$ svn log -v -r627:628
------------------------------------------------------------------------
r628 | xxxxxxx | 2008-09-19 12:24:48 -0600 (Fri, 19 Sep 2008) | 1 line
Changed paths:
   M /trunk/.../software/src/linux_driver/loadXilinxDriver

Make loadXilinxDriver script executable.
------------------------------------------------------------------------

Thanks.

Unfortunately, it doesn't seem to be caused just by the fact that it is a property-only commit, so I can't reproduce (or debug) it here yet.

Unfortunately I can't provide access to the repository itself, but is there some way I could run this with some instrumentation that would give you more information?

I will also try this with the latest 0.5 branch and see what happens.

Just for reference, this does still happen with bzr 1.10 and bzr-svn 0.5 HEAD.

I'm trying narrow this down little by little. First thing I found by adding some prints:

In fieldids.py -> update_map, it dies on:
  delta[p] = map[p][0]

I put some prints before this to show map and p. One thing that is interesting is that in map, all of the files in all of the subdirectories of the directory I'm in are there as keys, EXCEPT the "linux_driver" directory. It doesn't show up in the map at all, nor do any of it's files. So it's not just the one file, it's anything in that subdirectory.

Strangely, if I run the same thing (bzr up) in the linux_driver subdirectory, it doesn't crash, but it also doesn't call update_map at all.

Anyway, I'll keep trying to track this down, and I'll post more as I find it.

Okay, I've got a reproduction recipe. This happens when a directory is moved with simultaneous modifications from being a peer to being a child.

Here we go. There are still a couple print lines in update_map that I've left in just to better see what is failing.

$ mkdir /tmp/bzr-svn-304134
$ cd /tmp/bzr-svn-304134
$ svnadmin create svn-repos
$ svn co file://`pwd`/svn-repos svn-co
$ cd svn-co/
$ svn mkdir subdir1 subdir2
A subdir1
A subdir2
$ cd subdir1
$ touch file1 file2
$ svn add *
A file1
A file2
$ cd ..
$ cd subdir2/
$ touch file3 file4
$ svn add *
A file3
A file4
$ cd ..
$ svn commit -m "Initial tree."
Adding subdir1
Adding subdir1/file1
Adding subdir1/file2
Adding subdir2
Adding subdir2/file3
Adding subdir2/file4
Transmitting file data ....cd
Committed revision 1.
$ cd subdir1/
$ svn mkdir subdir3
A subdir3
$ touch subdir3/file5
$ touch subdir3/file6
$ svn add subdir3/*
A subdir3/file5
A subdir3/file6
$ svn commit -m "More files."
Adding subdir1/subdir3
Adding subdir1/subdir3/file5
Adding subdir1/subdir3/file6
Transmitting file data ..
Committed revision 2.
$ cd ..
$ ls
subdir1 subdir2
$ cd subdir2/
$ vi file3 # add a line
$ vi file4 # add a line
$ touch file7
$ svn add file7
A file7
$ svn ps svn:executable true file4
property 'svn:executable' set on 'file4'
$ svn status
M file3
MM file4
A file7
$ cd ..
$ svn status
M subdir2/file3
MM subdir2/file4
A subdir2/file7
$ svn mv subdir2/ subdir1/
A subdir1/subdir2
D subdir2/file3
D subdir2/file4
D subdir2/file7
D subdir2
$ svn status
A + subdir1/subdir2
M + subdir1/subdir2/file3
MM + subdir1/subdir2/file4
A + subdir1/subdir2/file7
D subdir2
D subdir2/file3
D subdir2/file4
$ svn commit -m "Directory move with modifications."
Adding subdir1/subdir2
Sending subdir1/subdir2/file3
Sending subdir1/subdir2/file4
Adding subdir1/subdir2/file7
Deleting subdir2
Transmitting file data ...
Committed revision 3.
$ ls
subdir1
$ svn up
At revision 3.
$ bzr up
Initialising Subversion metadata cache in /home/wjlanda/.bazaar/svn-cache/5ba257ea-9eb4-402c-af49-55ecc81b2ba0
revid = svn-v4:5ba257ea-9eb4-402c-af49-55ecc81b2ba0::0
delta = {u'': '0@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2F'}
update_map top
revid = svn-v4:5ba257ea-9eb4-402c-af49-55ecc81b2ba0::1
delta = {u'subdir2': '1@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir2', u'subdir1': '1@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir1', u'subdir2/file3': '1@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir2%2Ffile3', u'subdir2/file4': '1@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir2%2Ffile4', u'subdir1/file2': '1@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir1%2Ffile2', u'subdir1/file1': '1@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir1%2Ffile1'}
update_map top
revid = svn-v4:5ba257ea-9eb4-402c-af49-55ecc81b2ba0::2
delta = {u'subdir1/subdir3': '2@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir1%2Fsubdir3', u'subdir1/subdir3/file5': '2@5ba257ea-9eb4-402c-af49-55ecc81b2ba0:%2Fsubdir...

BTW, just to clarify with the example tree I sent. If you run bzr up from svn-co it works fine, but it crashes if you run bzr up from svn-co/subdir1. That is shown in the example, but I just want to point it out since it's easy to miss that detail.

Thanks, that is *very* useful. I don't have much time right now, but I'll have a closer look later this week. We should make sure this gets fixed before 0.5.

I just wanted to point out two other aspects of this bug:

1) Since we got to the bottom of this, the summary is actually misleading. This doesn't just affect lightweight checkouts, but also any other bzr operation on a subtree with the property demonstrated above. This prevents branch, checkout on a subtree where this already exists, and bzr pull if it happens after-the-fact.

2) This cannot always be worked around. In my case, I was able to operate on a different subtree (since it was a lightweight checkout), but I've found a case much more insidious. We have some repositories that used to use /some/path/project and later switched to using /some/path/{trunk,tags,branches}/project. But since now trunk contains directories that used to be peers, and many of them had simultaneous modifications[*], now it's impossible to use bzr-svn on trunk, which pretty much rules out it's use entirely.

Anyway, just a few more bug conditions to consider. I'm looking forward to this fix in 0.5 because it's really a blocker for case #2. Please let me know if you have trouble reproducing or need more test cases. (I thought of trying to fix it myself, but I'm not sure where to start because it appears that the root cause is somewhat removed from where the problem is detected.)

[*] I'm not entirely sure if that's REQUIRED to make this bug happen or not, but it's a property that's true in the reproduction recipe I posted.

Here is a shorter reproduction recipe:

svnadmin create repos
svn co file://`pwd`/repos svn-wc
cd svn-wc/
svn mkdir parent
svn commit -m "Added parent."
svn mkdir peer
svn commit -m "Added peer"
echo "A" > peer/file
svn add peer/file
svn commit -m "Added file"
svn up
echo "B" > peer/file
svn mv peer/ parent/child
svn commit -m "Made peer a child, with mods."
svn up
bzr up # works
cd parent/
svn up
bzr up # crashes
bzr: ERROR: exceptions.KeyError: u'child/file'

Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 893, in run_bzr_catch_errors
    return run_bzr(argv)
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 839, in run_bzr
    ret = run(*run_argv)
  File "/usr/lib/python2.5/site-packages/bzrlib/commands.py", line 539, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/usr/lib/python2.5/site-packages/bzrlib/builtins.py", line 1184, in run
    tree = WorkingTree.open_containing(dir)[0]
  File "/usr/lib/python2.5/site-packages/bzrlib/workingtree.py", line 333, in open_containing
    return control.open_workingtree(), relpath
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 819, in open_workingtree
    return SvnWorkingTree(self, self.local_path, self.open_branch())
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 114, in __init__
    self._update_base_revnum(max_rev)
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 542, in _update_base_revnum
    self.read_working_inventory()
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 413, in read_working_inventory
    add_dir_to_inv(u"", rootwc, None)
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 375, in add_dir_to_inv
    (id, revid) = find_ids(entry, rootwc)
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 352, in find_ids
    relpath)
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 279, in path_to_file_id
    entry = self.basis_tree().id_map[rp.decode("utf-8")]
  File "/home/wjlanda/.bazaar/plugins/svn/workingtree.py", line 534, in basis_tree
    self.base_tree = SvnBasisTree(self)
  File "/home/wjlanda/.bazaar/plugins/svn/tree.py", line 232, in __init__
    workingtree.branch.mapping)
  File "/home/wjlanda/.bazaar/plugins/svn/repository.py", line 451, in get_fileid_map
    return self.fileid_map.get_map(revmeta.get_foreign_revid(), mapping)
  File "/home/wjlanda/.bazaar/plugins/svn/fileids.py", line 304, in get_map
    self.actual.update_map(map, revid, idmap, changes)
  File "/home/wjlanda/.bazaar/plugins/svn/fileids.py", line 202, in update_map
    delta[inv_p] = map[inv_p][0]
KeyError: u'child/file'

bzr 1.11rc1 on python 2.5.2 (linux2)
arguments: ['/usr/bin/bzr', 'up']
encoding: 'UTF-8', fsenc: 'UTF-8', lang: 'en_US.UTF-8'
plugins:
  bzrtools /usr/lib/python2.5/site-packages/bzrlib/plugins/bzrtools [1.10]
  cvsps_import /usr/lib/python2.5/site-packages/bzrlib/plugins/cvsps_import [unknown]
  gtk /usr/lib/python2.5/site-packages/bzrlib/plug...

Hi Wesley,

On Wed, Jan 14, 2009 at 03:28:53PM -0000, Wesley J. Landaker wrote:
> I just wanted to point out two other aspects of this bug:

> 1) Since we got to the bottom of this, the summary is actually
> misleading. This doesn't just affect lightweight checkouts, but also any
> other bzr operation on a subtree with the property demonstrated above.
> This prevents branch, checkout on a subtree where this already exists,
> and bzr pull if it happens after-the-fact.
I haven't seen this being reproduced without a lightweight checkout
or stacked branch yet. At least the cases in the bug report so far are
all related to lightweight checkouts.

> 2) This cannot always be worked around. In my case, I was able to
> operate on a different subtree (since it was a lightweight checkout),
> but I've found a case much more insidious. We have some repositories
> that used to use /some/path/project and later switched to using
> /some/path/{trunk,tags,branches}/project. But since now trunk contains
> directories that used to be peers, and many of them had simultaneous
> modifications[*], now it's impossible to use bzr-svn on trunk, which
> pretty much rules out it's use entirely.
If you remove the svn-cache for your repository, you should be able to
do a normal "bzr branch" on the svn url. The problem is that this bug
corrupts the cache when used on a lightweight checkout.

I do plan to get this bug fixed before 0.5 final. Thanks for looking
into it.

Cheers,

Jelmer

Okay, I can confirm that removing the cache after triggering this bug lets a normal bzr branch or checkout of the affected subtree work.