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

["David E. Price" <deprice cs utah edu>]

Hi, Joanie,

Thanks for this analysis. It is very helpful.

I've only had the chance to skim both of these messages, but I have a 
suggestion to bounce off the community. Do people think it would be 
useful to indicate the size of the event queue in the debug log each 
time a new event is enqueued? With this information provided when the 
event you are interested in is enqueued, you can skip down that many 
event processing blocks to find the processing of the event you are 
interested in.

dave


On 04/06/2010 08:55 AM, Joanmarie Diggs wrote:
> 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
>
>
> _______________________________________________
> Orca-list mailing list
> Orca-list gnome org
> http://mail.gnome.org/mailman/listinfo/orca-list
> Visit http://live.gnome.org/Orca for more information on Orca.
> The manual is at http://library.gnome.org/users/gnome-access-guide/nightly/ats-2.html
> The FAQ is at http://live.gnome.org/Orca/FrequentlyAskedQuestions
> Netiquette Guidelines are at http://live.gnome.org/Orca/FrequentlyAskedQuestions/NetiquetteGuidelines
> Log bugs and feature requests at http://bugzilla.gnome.org
> Find out how to help at http://live.gnome.org/Orca/HowCanIHelp
>