Crash toggling off WorkView

[Bryce Harrington]

I ran gtg 0.3+bzr (from yesterday) on my (large) set of tasks ported from 0.2, and left it running overnight (no other changes to tasks had been done). WorkView had been turned on. Next morning I clicked WorkView and it crashed:

/home/bryce/src/gtg/new-scheduling/GTG/viewmanager/manager.py:207: GtkWarning: file /build/buildd/gtk+2.0-2.18.3/gtk/gtktreeview.c: line 5928 (validate_visible_area): assertion `has_child' failed.
There is a disparity between the internal view of the GtkTreeView,
and the GtkTreeModel. This generally means that the model has changed
without letting the view know. Any display from now on is likely to
be incorrect.

  gtk.main()
/home/bryce/src/gtg/new-scheduling/GTG/viewmanager/manager.py:207: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  gtk.main()
/home/bryce/src/gtg/new-scheduling/GTG/viewmanager/manager.py:207: Warning: g_object_set_property: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/new-scheduling/GTG/viewmanager/manager.py:207: Warning: g_value_unset: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/new-scheduling/GTG/taskbrowser/tasktree.py:377: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  value = model.get_value(iter, COL_TAGS)
Traceback (most recent call last):
  File "/home/bryce/src/gtg/new-scheduling/GTG/taskbrowser/tasktree.py", line 377, in _celldatafunction
    value = model.get_value(iter, COL_TAGS)
TypeError: unknown type (null)

/home/bryce/src/gtg/new-scheduling/GTG/tools/gtkcrashhandler.py:231: GtkWarning: file /build/buildd/gtk+2.0-2.18.3/gtk/gtktreeview.c: line 5928 (validate_visible_area): assertion `has_child' failed.
There is a disparity between the internal view of the GtkTreeView,
and the GtkTreeModel. This generally means that the model has changed
without letting the view know. Any display from now on is likely to
be incorrect.

  res = dialog.run()
/home/bryce/src/gtg/new-scheduling/GTG/tools/gtkcrashhandler.py:231: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  res = dialog.run()
/home/bryce/src/gtg/new-scheduling/GTG/tools/gtkcrashhandler.py:231: Warning: g_object_set_property: assertion `G_IS_VALUE (value)' failed
  res = dialog.run()
/home/bryce/src/gtg/new-scheduling/GTG/tools/gtkcrashhandler.py:231: Warning: g_value_unset: assertion `G_IS_VALUE (value)' failed
  res = dialog.run()
Traceback (most recent call last):
  File "/home/bryce/src/gtg/new-scheduling/GTG/taskbrowser/tasktree.py", line 377, in _celldatafunction
    value = model.get_value(iter, COL_TAGS)
TypeError: unknown type (null)

[Bryce Harrington (bryce)]

In the program output, prior to the crash, I'd noticed some odd messages. Don't know if these are relevant:

479@1 is removed
739@1 is removed
223@1 is removed
861@1 is removed
38@1 is removed
218@1 is removed
618@1 is removed
486@1 is removed
1159@1 is removed
972@1 is modified in the filteredtree
972@1 is modified, not to dis
972@1 is modified in the filteredtree
972@1 is only modified (todis,curdis)
<...>

603@1 is modified in the filteredtree
603@1 is modified, not to dis
/home/bryce/src/gtg/new-scheduling/GTG/taskbrowser/tasktree.py:285: GtkWarning: gtk_tree_model_sort_row_inserted: assertion `elt != NULL' failed
  self.row_inserted(node_path, node_iter)
<...>

/home/bryce/src/gtg/new-scheduling/GTG/taskbrowser/tasktree.py:285: GtkWarning: /build/buildd/gtk+2.0-2.18.3/gtk/gtktreemodelsort.c:640: A node was inserted with a parent that's not in the tree.
This possibly means that a GtkTreeModel inserted a child node
before the parent was inserted.
  self.row_inserted(node_path, node_iter)
<...>

I had also noticed that the program was very slow to start up (slower than 0.2), and would periodically "freeze" (stopped redrawing, non-responsive to mouse, no output to stdout/stderr). It would come back after a few minutes.

[Lionel Dricot (ploum-deactivatedaccount)]

I did a few bad commits. I hope to have fixed them with rev. 784. For me, startup is really fast. Could you check with that revision ?

Thanks for reporting regression. Really useful information.

[Bryce Harrington (bryce)]

Reproduced the crash again this morning on 783. Will try updating to a newer rev.

[Bryce Harrington (bryce)]

The startup performance is still quite bad with latest; rev 780 started up fast for me (but had other issues.)

[Luca Invernizzi (invernizzi)]

in answer to Bryce, off topic for this bug:
The bad performance was caused by issuing a refilter of the tag tree each time a task was loaded. It's fixed in the latest trunk (787)

[Bryce Harrington (bryce)]

Yes, the performance seems a lot better now. The crash still reproduces though. It's weird, I only see it in the mornings after gtg has been running all night, or at least running for some period of time. If I load it up and right after that try manually toggling workview on and off it doesn't reproduce.

[Lionel Dricot (ploum-deactivatedaccount)]

I hate gtk.TreeView.

[Lionel Dricot (ploum-deactivatedaccount)]

Bryce : could it be related to a changing date ?

One explanation would be that, as the day as changed, the workview content is not the same. But because no task were changed, it was not refreshed.

Do you think it's a possible explanaiton ?

[Bryce Harrington (bryce)]

On Tue, Jun 15, 2010 at 07:32:58AM -0000, Lionel Dricot wrote:
> Bryce : could it be related to a changing date ?
>
> One explanation would be that, as the day as changed, the workview
> content is not the same. But because no task were changed, it was not
> refreshed.
>
> Do you think it's a possible explanaiton ?

That is a really good guess.

Unfortunately, today after updating to latest I learned that it now
crashes 100% of the time when I untoggle WorkView.

(Or I guess 'fortunately' in the sense that it's now much more easy to
reproduce... if it is indeed the same bug.) Now I get the following
crash error when untoggling:

$ ./gtg
/home/bryce/src/gtg/0.3-main/GTG/gtk/browser/tasktree.py:370:
GtkWarning: gtk_tree_model_sort_row_inserted: assertion `elt != NULL'
failed
  self.row_inserted(node_path, node_iter)
/home/bryce/src/gtg/0.3-main/GTG/gtk/manager.py:209: GtkWarning:
gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter,
tree_model_sort)' failed
  gtk.main()
/home/bryce/src/gtg/0.3-main/GTG/gtk/manager.py:209: Warning:
g_object_set_property: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/0.3-main/GTG/gtk/manager.py:209: Warning:
g_value_unset: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/0.3-main/GTG/gtk/browser/tasktree.py:466:
GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter,
tree_model_sort)' failed
  value = model.get_value(iter, COL_TAGS)
Traceback (most recent call last):
  File "/home/bryce/src/gtg/0.3-main/GTG/gtk/browser/tasktree.py", line
  466, in _celldatafunction
    value = model.get_value(iter, COL_TAGS)
TypeError: unknown type (null)

Perhaps model or iter needs to be checked for null values before
calling?

Bryce

[Lionel Dricot (ploum-deactivatedaccount)]

Please try rev. 808. I added a check for that.

[Bryce Harrington (bryce)]

On Tue, Jun 15, 2010 at 10:28:42AM -0000, Lionel Dricot wrote:
> Please try rev. 808. I added a check for that.

With version 810 it now crashes on startup:

$ ./gtg
PROBLEM: child 5@1 have the path [(1,)] but parent has (4,)
/home/bryce/src/gtg/gtg/GTG/gtk/browser/browser.py:900: GtkWarning: gtk_tree_model_sort_ref_node: assertion `VALID_ITER (iter, tree_model_sort)' failed
  self.task_tv.expand_row(path, False)
/home/bryce/src/gtg/gtg/GTG/gtk/browser/browser.py:900: GtkWarning: gtk_tree_model_sort_iter_has_child: assertion `VALID_ITER (iter, tree_model_sort)' failed
  self.task_tv.expand_row(path, False)
/home/bryce/src/gtg/gtg/GTG/gtk/browser/browser.py:900: GtkWarning: gtk_tree_model_sort_iter_next: assertion `tree_model_sort->stamp == iter->stamp' failed
  self.task_tv.expand_row(path, False)
PROBLEM: child 11@1 have the path [(0,)] but parent has (96,)
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: GtkWarning: /build/buildd/gtk+2.0-2.18.3/gtk/gtktreemodelsort.c:2334: There is a discrepancy between the sort model and the child model. The child model is advertising a wrong length for the root level.
  gtk.main()
PROBLEM: child 5@1 have the path [(1,)] but parent has (4,)
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  gtk.main()
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: Warning: g_object_set_property: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: Warning: g_value_unset: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/gtg/GTG/gtk/browser/tasktree.py:473: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  value = model.get_value(iter, COL_TAGS)
Traceback (most recent call last):
  File "/home/bryce/src/gtg/gtg/GTG/gtk/browser/tasktree.py", line 473, in _celldatafunction
    value = model.get_value(iter, COL_TAGS)
TypeError: unknown type (null)

Could the tasks have gotten corrupted by the earlier crashes?

[Bryce Harrington (bryce)]

I've seen three different modes of crashing:
  * Launch gtg with workview on. Toggle it -> crash
  * Launch gtg with workview off. Crashes immediately (no GUI shown). Only crash info is what's displayed on the console.
  * Launch gtg with workview off. Processes data, shows some warnings, gets most of the way done with displaying the GUI, and then crashes just before it looks like it'll be usable. Brings up a crash dialog.

[Bryce Harrington (bryce)]

Oddly, when I run it via 'strace ./gtg' I can't seem to get it to crash at all. Race condition?

[Bryce Harrington (bryce)]

I could recreate the crash running 'pdb gtg' but I guess the crash handler interferes with pdb or something, because I couldn't get a useful backtrace out of it. Haven't really used pdb before so this may be just due to tool ignorance.

[Bryce Harrington (bryce)]

I've gone back through past backups of my gtg tasks. Here's a list of
the backups I tested:

744K gtg-backup-20100107
3.4M gtg-backup-20100202 <-- No crashes
7.4M gtg-backup-20100315 <-- Crashes intermittently
7.9M gtg-backup-20100321 <-- Crashes regularly
8.2M gtg-backup-20100329 <-- Crashes regularly
8.7M gtg-backup-20100403 <-- Crashes regularly
8.8M gtg-backup-20100404 <-- Crashes regularly
5.4M gtg-backup-20100410 <-- Crashes regularly
6.0M gtg-backup-20100424 <-- Crashes regularly
7.0M gtg-backup-20100510 <-- Crashes regularly
7.7M gtg-backup-20100519 <-- Crashes regularly
8.5M gtg-backup-20100605 <-- Crashes regularly
9.7M gtg-backup-20100614 <-- Crashes regularly

Attached are the anonymized task files for 202 and 315.

[Bryce Harrington (bryce)]

Also, here is my ~/.config/gtg directory just in case it's useful.
I looked through the files there but didn't see anything that looked
worth fiddling with to test, aside from toggling workview on/off.

[Bryce Harrington (bryce)]

gtg --debug doesn't seem to provide much of interest:

2010-06-15 15:27:34,847 - DEBUG - tree:new_relationship:109 - new relationship between root and 1187@1
2010-06-15 15:27:34,847 - DEBUG - tree:new_relationship:109 - new relationship between root and 1187@1
2010-06-15 15:27:34,847 - DEBUG - tree:new_relationship:135 - * * * * * Relationship already existing
2010-06-15 15:27:34,848 - DEBUG - tree:new_relationship:109 - new relationship between root and 1188@1
2010-06-15 15:27:34,848 - DEBUG - tree:new_relationship:109 - new relationship between root and 1188@1
2010-06-15 15:27:34,848 - DEBUG - tree:new_relationship:135 - * * * * * Relationship already existing
2010-06-15 15:27:34,848 - DEBUG - tree:new_relationship:109 - new relationship between root and 1191@1
2010-06-15 15:27:34,848 - DEBUG - tree:new_relationship:109 - new relationship between root and 1191@1
2010-06-15 15:27:34,849 - DEBUG - tree:new_relationship:135 - * * * * * Relationship already existing
PROBLEM: child 5@1 have the path [(1,)] but parent has (5,)
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  gtk.main()
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: Warning: g_object_set_property: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/gtg/GTG/gtk/manager.py:209: Warning: g_value_unset: assertion `G_IS_VALUE (value)' failed
  gtk.main()
/home/bryce/src/gtg/gtg/GTG/gtk/browser/tasktree.py:473: GtkWarning: gtk_tree_model_sort_get_value: assertion `VALID_ITER (iter, tree_model_sort)' failed
  value = model.get_value(iter, COL_TAGS)
Traceback (most recent call last):
  File "/home/bryce/src/gtg/gtg/GTG/gtk/browser/tasktree.py", line 473, in _celldatafunction
    value = model.get_value(iter, COL_TAGS)
TypeError: unknown type (null)

2010-06-15 15:27:34,969 - DEBUG - browser:on_task_added:1316 - Add task with ID: 544@1
2010-06-15 15:27:34,994 - DEBUG - browser:on_task_added:1316 - Add task with ID: 545@1
2010-06-15 15:27:35,019 - DEBUG - browser:on_task_added:1316 - Add task with ID: 546@1
2010-06-15 15:27:35,045 - DEBUG - browser:on_task_added:1316 - Add task with ID: 547@1
2010-06-15 15:27:35,071 - DEBUG - browser:on_task_added:1316 - Add task with ID: 548@1
2010-06-15 15:27:35,096 - DEBUG - browser:on_task_added:1316 - Add task with ID: 549@1
2010-06-15 15:27:35,121 - DEBUG - browser:on_task_added:1316 - Add task with ID: 550@1
2010-06-15 15:27:35,150 - DEBUG - browser:on_task_added:1316 - Add task with ID: 552@1
2010-06-15 15:27:35,176 - DEBUG - browser:on_task_added:1316 - Add task with ID: 554@1
... continues hundreds of lines ...

[Bryce Harrington (bryce)]

My dpkg.log for the past month and a half, just in case the issue
is a changed dependency. I browsed through the logs but nothing jumped
out at me.

[Bryce Harrington (bryce)]

After commenting out the crash handler and hooking up pdb properly, I got a trace:

(Pdb) bt
  /usr/bin/pdb(1306)<module>()
-> pdb.main()
  /usr/lib/python2.6/pdb.py(1283)main()
-> pdb._runscript(mainpyfile)
  /usr/lib/python2.6/pdb.py(1202)_runscript()
-> self.run(statement)
  /usr/lib/python2.6/bdb.py(368)run()
-> exec cmd in globals, locals
  <string>(1)<module>()
  /home/bryce/src/gtg/gtg/gtg(53)<module>()
-> sys.exit(GTG.gtg.main(options, args))
  /home/bryce/src/gtg/gtg/GTG/gtg.py(123)main()
-> manager = Manager(req, config)
  /home/bryce/src/gtg/gtg/GTG/gtk/manager.py(67)__init__()
-> self.open_browser()
  /home/bryce/src/gtg/gtg/GTG/gtk/manager.py(123)open_browser()
-> self.browser = TaskBrowser(self.req, self, self.config)
> /home/bryce/src/gtg/gtg/GTG/gtk/browser/browser.py(143)__init__()
-> self.task_tv.expand_all()

I poked around a bit more but other than identifying it has something to do with task_tv (which I guess was already pretty evident), I didn't spot anything else that'd shed light on it.

Oh, I did notice that the bug is surprisingly inconsistent. Sometimes gtg comes up and works fine with or without workview, no crashes at all, sometimes it crashes right away, sometimes only after the gui is done loading. I've a sense that the bigger the task list the more likely it is to crash, but haven't any evidence that this is the case.

Hopefully all this data gives you some clues.

[Lionel Dricot (ploum-deactivatedaccount)]

There seems to be a race condition in the current task tree.

At some point, a parent node will advertize itself as having a child but the child will still be in the virtualroot of the filtered tree.

On the other hand, the parent will not be added in the TaskTree, thus not allowing us to put the child in another place than the root.

This race conditions is the root cause of every crash I've seen so far with your data.

I did not identified where that race condition appear. As a workaround, I now remove from the virtual_root any node that is advertized as a child of another node. This (and many other fixes), allows you data to crash a lot less. But still, they crash, meaning that there's still an issue somewhere.

This is a very good stress test.

What would be good is to build some unit tests that load your data and play a bit with trees and filters. That would allow us to catch easily regression but also performances regressions (by having a test on the total time needed to run the test).

[Bryce Harrington (bryce)]

Hey! Sorry I've been mostly gone this past week (family member had a surgery), and firing up trunk gtg I see it has massively improved. Startup performance is *tons* better (I thought something was wrong, it was so fast!), and so far I am unable to reproduce this WorkView crash (after a couple hour's playing with it).

Thanks for all the hard work on this Lionel, I can see from the bzr log you knocked some serious bugs out. :-)

(I guess this bug report can be closed now?)

[Lionel Dricot (ploum-deactivatedaccount)]

It is considered as fixed by Bryce. I still can see some crashes when running debug.sh -s bryce but it seems to not be related.

[Lionel Dricot (ploum-deactivatedaccount)]

Bryce > There's indeed a problem now. The load is so fast that we sometime have a race condition that cause some garbage in the console. Also, I'm not sure that the workview count is exact.

[Bryce Harrington (bryce)]

On Wed, Jun 23, 2010 at 07:39:19AM -0000, Lionel Dricot wrote:
> Bryce > There's indeed a problem now. The load is so fast that we
> sometime have a race condition that cause some garbage in the console.

Heh, guess that's kind of a good problem to have... I've not seen the
console garbage myself. Fwiw, gtg did not crash at all today, and I
used it pretty heavily (and restarted it multiple times.)

> Also, I'm not sure that the workview count is exact.

The inaccuracy I've seen in the workview count is that it does not
include counts of grandchildren. This is already reported in the bug
tracker.

Bryce