[orca-list] Debug.out analysis - Part 2 (was Re: Orca, problem with check lists?)

[Joanmarie Diggs <joanmarie diggs gmail com>]

This is Part 2 of my everything you ever wanted to know about debug.outs
(and a bunch of stuff perhaps you didn't want to know about them).

When we last saw Attila, he was in Ubuntu's update-manager, apparently
on AppArmor and pressed Down arrow. A lot of events came in, many of
which got queued up, and some of which have since been processed.
Because none of them were of interest (i.e. about the item which just
became unselected), we've not presented anything in Orca.

> From debug.out:

vvvvv PROCESS OBJECT EVENT object:active-descendant-changed vvvvv
OBJECT EVENT: object:active-descendant-changed         detail=(8,0,[table cell | ])
app.name='update-manager' name='updates' role='table' state='enabled focusable focused sensitive showing 
visible manages descendants' relations=''
LOCUS OF FOCUS: app='update-manager' name='' role='table cell'
                event='object:active-descendant-changed'
generate braille for app.name='update-manager' name='None' role='table cell' state='active checked enabled 
focusable focused selectable selected sensitive showing transient visible' relations=''

JOANIE: note, there's a ton more lines in the original debug.out related
to coming up with the formatting strings necessary to generate the
braille. I've deleted them.

BRAILLE LINE:  'update-manager Application Update Manager Frame ScrollPane updates Table Install ColumnHeader 
<x> Install apparmor-utils
Utilities for controlling AppArmor (Size: 102 KB)'
     VISIBLE:  '<x> Install apparmor-utils
Utili', cursor=1

generate speech for app.name='update-manager' name='None' role='table cell' state='active checked enabled 
focusable focused selectable selected sensitive showing transient visible' relations=''

JOANIE: note, there's a ton more lines in the original debug.out related
to coming up with the formatting strings necessary to generate the
speech. I've deleted them.

SPEECH OUTPUT: 'Install check box checked apparmor-utils
Utilities for controlling AppArmor (Size: 102 KB). '
^^^^^ PROCESS OBJECT EVENT object:active-descendant-changed ^^^^^

JOANIE: Finally, we presented something in response to an
object:active-descendant-changed event. Looking at the event, the app is
update-manager, the object is a table, the event indicates that the
active child/descendant in the table has changed. Which child? According
to detail1, I'd say the 9th child because we count from 0. Looking at
the any_data, that 9th child is an accessible table cell. On to the next
event.

DEQUEUED EVENT object:text-changed:insert <----------

vvvvv PROCESS OBJECT EVENT object:text-changed:insert vvvvv
OBJECT EVENT: object:text-changed:insert               detail=(0,79,This provides some useful programs to 
help create and manage AppArmor profiles.)
    app.name='update-manager' name='Description' role='text'
state='enabled focusable multi line sensitive visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:text-changed:insert ^^^^^

JOANIE: Remember in part one that some text got deleted from the
description as a result of the selection changing? Well, the above event
looks like update-manager putting some new text in its place. It's still
AppArmor related, so I guess there are multiple AppArmor packages and
that they all need updating. By the way, detail1 tells me that text was
inserted at an offset of 0, i.e. the first character; detail2 tells me
that the string is 79 characters long; the any_data tells me what got
inserted into that text object, namely "This provides some useful
programs to help create and manage AppArmor profiles." The fact that
there's not a zillion lines related to generating speech and braille
tells me that we didn't see any point in presenting this new text. Since
this description object is not what has focus, that makes sense. Also,
looking at the states ('enabled focusable multi line sensitive visible')
I see that 'showing' ain't there, but 'visible' is. Different
apps/toolkits get this backwards, but I'm taking these states to mean
the text/description beneath the table could be shown if Attila pushed
that toggle button. But that it's not showing because he didn't push it.

DEQUEUED EVENT object:text-caret-moved <----------

vvvvv PROCESS OBJECT EVENT object:text-caret-moved vvvvv
OBJECT EVENT: object:text-caret-moved                  detail=(79,0,None)
    app.name='update-manager' name='Description' role='text' state='enabled focusable multi line sensitive 
visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:text-caret-moved ^^^^^

JOANIE: And, just like when the text was removed, the fact that text got
inserted in the description has caused the caret to be moved. According
to detail1, the offset it moved to is 79. From the previous event we
know that a string that was 79 characters long just got inserted. So the
caret's at the end.

KEYEVENT: type=0
          hw_code=65
          modifiers=8192
          event_string=(space)
          is_text=True
          timestamp=6807581
          time=1270538359.433594

JOANIE: Aha! What we've been waiting for. Atilla pressed (type=0) the
space bar. That should have toggled the state. Let's see what happens
next:

orca.keyEcho: string to echo: space
orca.isModifierKey: returning: False
orca.isNavigationKey: returning: False
orca.isDiacriticalKey: returning: False
orca.isPrintableKey: returning: True
orca.keyEcho: speaking: space
orca.isModifierKey: returning: False
orca.isModifierKey: returning: False

JOANIE: Orca has to decide if this key should be spoken/echoed. That's
based on your keyecho settings, so it goes through and decides what sort
of key this is. Moving on.

KEYEVENT: type=1
          hw_code=65
          modifiers=8192
          event_string=(space)
          is_text=True
          timestamp=6807649
          time=1270538359.570481
orca.isModifierKey: returning: False
orca.isModifierKey: returning: False

JOANIE: Here's where Attila released the Space bar. The fact that no
events from update-manager are here strongly suggests that we didn't get
any events (of all of the types of events Orca listens for, anyway) in
response. But if you remember from part 1, sometimes they come in a wee
bit later and get queued, so we'll move on and hopefully we'll see
something to indicate that the state of the checkbox was toggled as a
result of space being pressed.

KEYEVENT: type=0
          hw_code=111
          modifiers=8192
          event_string=(Up)
          is_text=True
          timestamp=6808567
          time=1270538360.418893
orca.keyEcho: string to echo: Up
orca.isModifierKey: returning: False
orca.isNavigationKey: returning: True
orca.isModifierKey: returning: False
orca.isModifierKey: returning: False

JOANIE: Attila pressed Up Arrow.

---------> QUEUEING EVENT object:state-changed:selected
DEQUEUED EVENT object:state-changed:selected <----------

JOANIE: And we got an event immediately which we queued. The fact that
it's an indication that the selection changed (as we'd expect resulting
from Up Arrow) suggests that we're not going to be notified about the
state of that checkbox getting toggled. But we'll keep going....

vvvvv PROCESS OBJECT EVENT object:state-changed:selected vvvvv
OBJECT EVENT: object:state-changed:selected            detail=(1,0,None)
---------> QUEUEING EVENT object:state-changed:selected
---------> QUEUEING EVENT object:state-changed:selected
---------> QUEUEING EVENT object:state-changed:selected
    app.name='update-manager' name='None' role='table cell' state='checked enabled focusable selectable 
selected sensitive showing transient visible' relations=''
---------> QUEUEING EVENT object:selection-changed
---------> QUEUEING EVENT object:text-changed:delete
---------> QUEUEING EVENT object:text-caret-moved
^^^^^ PROCESS OBJECT EVENT object:state-changed:selected ^^^^^

JOANIE: So several things just occurred. It looks an awful lot like we
just processed the event we just queued (since it's the same type).
However, keep in mind that in part 1 we got tons of events which we
haven't processed yet. Amongst those events were state-changed:selected
events with detail1 == 0 (the thing that was arrowed off of). I don't
recall seeing the ones with detail1 == 1 (the thing that was arrowed
to). So this event is almost certainly something we queued up from part
1. Looking at the states (they're listed on a line in between a bunch of
new events which just came in as a result of Up Arrow being pressed) has
state checked. So this is the first column of the row that Attila
arrowed down to in part 1. Why don't we present it? It's already the
locus of focus as a result of the active-descendant-changed event above.
In other words, we know you're already here. Moving on.

DEQUEUED EVENT object:state-changed:selected <----------

vvvvv PROCESS OBJECT EVENT object:state-changed:selected vvvvv
OBJECT EVENT: object:state-changed:selected            detail=(1,0,None)
    app.name='update-manager' name='apparmor
User-space parser utility for AppArmor (Size: 342 KB)' role='table cell' state='enabled focusable selectable 
selected sensitive showing single line transient visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:state-changed:selected ^^^^^

JOANIE: Here's column 2 of the row Attila moved down to earlier.

DEQUEUED EVENT object:state-changed:selected <----------

vvvvv PROCESS OBJECT EVENT object:state-changed:selected vvvvv
OBJECT EVENT: object:state-changed:selected            detail=(0,0,None)
    app.name='update-manager' name='None' role='table cell' state='active checked enabled focusable focused 
selectable sensitive showing transient visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:state-changed:selected ^^^^^

JOANIE: Here's a table cell giving up selection/focus (detail1 == 0). It
has state 'checked' so it's column 1 of the table.

DEQUEUED EVENT object:state-changed:selected <----------

vvvvv PROCESS OBJECT EVENT object:state-changed:selected vvvvv
OBJECT EVENT: object:state-changed:selected            detail=(0,0,None)
---------> QUEUEING EVENT object:active-descendant-changed
---------> QUEUEING EVENT object:text-changed:insert
    app.name='update-manager' name='apparmor-utils
Utilities for controlling AppArmor (Size: 102 KB)' role='table cell' state='enabled focusable selectable 
sensitive showing single line transient visible' relations=''
---------> QUEUEING EVENT object:text-caret-moved
KEYEVENT: type=1
          hw_code=111
          modifiers=8192
          event_string=(Up)
          is_text=True
          timestamp=6808623
          time=1270538360.478145
orca.isModifierKey: returning: False
orca.isModifierKey: returning: False
^^^^^ PROCESS OBJECT EVENT object:state-changed:selected ^^^^^

JOANIE: Another table cell giving up selection/focus. This one has the
text/app information so we know that Apparmor-utils was arrowed away
from.

vvvvv PROCESS OBJECT EVENT object:selection-changed vvvvv
OBJECT EVENT: object:selection-changed                 detail=(0,0,None)
    app.name='update-manager' name='updates' role='table' state='enabled focusable focused sensitive showing 
visible manages descendants' relations=''
^^^^^ PROCESS OBJECT EVENT object:selection-changed ^^^^^

JOANIE: The table announced what we already know.

DEQUEUED EVENT object:text-changed:delete <----------

vvvvv PROCESS OBJECT EVENT object:text-changed:delete vvvvv
OBJECT EVENT: object:text-changed:delete               detail=(0,79,This provides some useful programs to 
help create and manage AppArmor profiles.)
    app.name='update-manager' name='Description' role='text' state='enabled focusable multi line sensitive 
visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:text-changed:delete ^^^^^

JOANIE: the old description got nuked.

DEQUEUED EVENT object:text-caret-moved <----------

vvvvv PROCESS OBJECT EVENT object:text-caret-moved vvvvv
OBJECT EVENT: object:text-caret-moved                  detail=(0,0,None)
    app.name='update-manager' name='Description' role='text' state='enabled focusable multi line sensitive 
visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:text-caret-moved ^^^^^

JOANIE: The caret moved as a result of the change in description text.
And what you're about to see next is the new active-descendant-changed
event telling us what now has focus/became selected. So this is the
thing that was arrowed Up to. Because we tackle object events in order,
this is something that happened well past the point where Attila toggled
the state of the checkbox. Conclusion: Update-manager is not telling us
when the state of a checkbox is toggled -- at least not using any events
that we're listening for, and we listen for quite a few. What I'd expect
to see is something like an object:state-changed:checked event with
detail1 being a boolean (0 means it is now unchecked; 1 means it is now
checked). So that's not a bug in Orca. It's either a bug in
update-manager itself, or in the widget they are using.

DEQUEUED EVENT object:active-descendant-changed <----------

vvvvv PROCESS OBJECT EVENT object:active-descendant-changed vvvvv
OBJECT EVENT: object:active-descendant-changed  detail=(6,0,[table cell | ])
    app.name='update-manager' name='updates' role='table' state='enabled focusable focused sensitive showing 
visible manages descendants' relations=''
LOCUS OF FOCUS: app='update-manager' name='' role='table cell'
                event='object:active-descendant-changed'
generate braille for app.name='update-manager' name='None' role='table cell' state='active checked enabled 
focusable focused selectable selected sensitive showing transient visible' relations='' 

JOANIE: Removed a bunch of generator lines that were here, but notice
that the state for the table cell with the checkbox claims to be
checked.

SPEECH OUTPUT: 'Install check box checked apparmor
User-space parser utility for AppArmor (Size: 342 KB). '
^^^^^ PROCESS OBJECT EVENT object:active-descendant-changed ^^^^^

JOANIE: So according to detail1, we've gone from the child at index 8 to
the child at index 6. And, according to the any_data, that child happens
to be a table cell. That's consistent with the press of Up Arrow.

So as we've seen, the active-descendant-changed event is where we're
presenting the new location, including whether or not the checkbox in
the row which was just arrowed to is checked or unchecked. If it claims
to be checked, we present that; if it doesn't claim to be checked but is
toggle-able, we present that it is not checked. We have to trust that
the information we get is correct. 

It would appear from the reports on this list (as well as from taking a
look at the full debug.out, and from verifying things in Accerciser --
which is always a good idea), that we're not getting the correct
information w.r.t. the checked state. That's not entirely surprising
given that we're not being notified via an event that the state has been
toggled.

So I think the thing to do is file a single bug against update-manager
in launchpad. In that bug, indicate that the expected event is missing
and that the state set does not appear to be getting updated when a
cell/checkbox is toggled. Wait for a response, and go from there.

Make sense? If so, it would be awesome if whoever files the bug
announces when this has taken place (along with a link to the new bug)
on the list. That way folks can add themselves to the CC list of the bug
and we avoid filing duplicates.

Hope this is of some use.
--joanie