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

[Joanmarie Diggs <joanmarie diggs gmail com>]

Hey Attila.

> Joanmarie, I sending you the debug.out file and a screen shot, because 
> both two attachments is too big the list.

I got them. Thanks! And I'm going to take the opportunity to do the
analysis here, with you and the list. And I'm going to break it into
parts. This is Part 1. 

Note: If you don't care about debug.outs, now is the time to stop
reading. If you don't have much time at the moment, now is not the time
to continue reading. :-)

In a debug.out, you will typically see a key press event (type=0)
followed by stuff that resulted from that key press, followed by a key
release event (type=1). Here's an example from yours with my narrative
added (and prefixed with 'JOANIE'):


KEYEVENT: type=0
          hw_code=116
          modifiers=8192
          event_string=(Down)
          is_text=True
          timestamp=6805657
          time=1270538357.509267
orca.keyEcho: string to echo: Down
orca.isModifierKey: returning: False
orca.isNavigationKey: returning: True
orca.isModifierKey: returning: False
orca.isModifierKey: returning: False

JOANIE: Attila pressed Down Arrow.

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

JOANIE: As a result of that press, we got an
object:state-changed:selected event. That makes sense because you
changed selection in the list of available apps. So we queued the event.
Because we apparently didn't have other events in the queue at this
point, we immediately process it, as indicated by the next few lines.

vvvvv PROCESS OBJECT EVENT object:state-changed:selected vvvvv

JOANIE: when you see "vvvvv" it's the start of the processing.
debug.outs were (I suspect) created largely for a sighted audience and
v's look rather like downward pointing arrows. You can easily search
visually or non-visually for these indicators. Having said that, if
anyone would prefer some other indicator, that's fine with me. Anyhoo,
the above line is an indication that we've started processing the event.

OBJECT EVENT: object:state-changed:selected            detail=(0,0,None)

JOANIE: And what we know about this event is that detail1 is 0, detail2
is 0, and we didn't get any_data. Often detail2 is 0, and often we don't
get any_data. Depending on the event type, detail1 might be boolean (0
means False; 1 means True), it might be the index of a child (7 means
the seventh child; 8 means the eighth child), it might be a caret offset
(0 is the first character; 1 is the second character). For a
state-changed event, you should expect a boolean detail1. So the above
event means that something just got unselected. (What that is we're
about to find out. But first....)

---------> QUEUEING EVENT object:state-changed:selected
---------> QUEUEING EVENT object:selection-changed
---------> QUEUEING EVENT object:text-changed:delete

JOANIE: Three more events came in. Add them to the queue and get back to
what we were processing.

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

JOANIE: So the above tells us that the app which issued this event
(update-manager), the role of the object which issued it (a table cell),
and all of the states that object claims to have (active, checked,
enabled, etc., etc.). Put it all together and you've got a checked table
cell in update manager just gave up selection as a result of your
pressing Down Arrow. What follows is what we did as a result (speak
something, braille something, etc.)

---------> QUEUEING EVENT object:text-caret-moved

JOANIE: Ok, another event came in in the meantime, so we queued it. Back
to processing the current event.

^^^^^ PROCESS OBJECT EVENT object:state-changed:selected ^^^^^

JOANIE: When you see "^^^^^" (which looks like upward pointing arrows),
it means we're done with the event. So Orca didn't do anything in
response to this event. That makes sense. After all, you want to know
what was arrowed to (as indicated by it getting selected); not what you
just left.

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

JOANIE: So now we start tackling those events we queued earlier because
they came in while we were processing that object:state-changed:selected
event. Note that I'm going to start tackling each event in its entirety
now, because it's all the same process from above.

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
---------> QUEUEING EVENT object:text-caret-moved
    app.name='update-manager' name='apparmor
User-space parser utility for AppArmor (Size: 342 KB)' role='table cell' state='enabled focusable selectable 
sensitive showing single line transient visible' relations=''
^^^^^ PROCESS OBJECT EVENT object:state-changed:selected ^^^^^

JOANIE: So we just processed another object:state-changed:selected
event. (And queued three more events while doing it. We get lots of
events.) The event we just processed is also for a table cell in
update-manager which just became unselected. This one has the name of 
"apparmor User-space parser utility for AppArmor (Size: 342 KB)". So now
we know what row in the table you just left. Time to dequeue another
event and process it.

DEQUEUED EVENT object:selection-changed <----------

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 itself just announced that the selection changed
inside of it. Yeah, we knew that. Thanks, table. Moving on....

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

vvvvv PROCESS OBJECT EVENT object:text-changed:delete vvvvv
OBJECT EVENT: object:text-changed:delete               detail=(0,121,AppArmor Parser is a user level programs 
that is used to load in program profiles to the AppArmor Security kernel module.)
    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 Update Manager dialog includes near the bottom a toggle
button you can press to show the 'Description of update'. As you arrow
amongst items in the table, the description changes. What the above
event tells me is that as a result of Attila Down Arrowing off of the
AppArmor line, a bunch of text about AppArmor was deleted. The offset of
the first character deleted was 0 (detail1) and the length of the text
deleted was 121 characters (detail2). The text that was deleted was
"AppArmor Parser is a user level programs that is used to load in
program profiles to the AppArmor Security kernel module." (any_data). No
point in presenting this to the user, so we didn't.

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=''
KEYEVENT: type=1
          hw_code=116
          modifiers=8192
          event_string=(Down)
          is_text=True
          timestamp=6805718
          time=1270538357.569385
orca.isModifierKey: returning: False
orca.isModifierKey: returning: False
^^^^^ PROCESS OBJECT EVENT object:text-caret-moved ^^^^^

JOANIE: Looks like we got a event to tell us that the caret moved in the
description text object whose text just got deleted. Based on detail1,
the caret is now at offset of 0. Who cares, right? So we didn't present
it. While we were considering what to do about that caret-moved event,
we got another event indicating that Attila had released Down Arrow key.
Does that mean we're done? And why didn't Orca say anything when he
arrowed to a new item in the table? Remember, while we were processing
events, a bunch more came in and we added them to the queue. We just
haven't gotten to the ones which are worth presenting yet. But we're
about to. :-) And that will be part 2. So stay tuned. (And if you have
any questions about the above stuff, please respond here so that we can
all benefit.)