883299 - Log coordinates for touch events that Marionette initiates

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Dave Hunt [:davehunt] [he/him] ⌚BST]

In order to assist debugging issues when automating interactions, it would be useful to log the coordinates received by Marionette. From this, we may be able to tell when we are way off from the intended target.

Comment 1

[Malini Das [:mdas] - Away, not checking bugmail]

Marionette only dispatches events, it doesn't receive any, unless I'm missing something? We can add the optional logging for the dispatched event's coordinates.

Comment 2

[Dave Hunt [:davehunt] [he/him] ⌚BST]

This was something discussed last week. Perhaps it wouldn't be Marionette listening to these events, but the idea was to somehow enable a mode that would listen, and log all such events. This would allow us to compare our assumptions regarding the interactions to the actual interactions received. Perhaps Jonathan can recall this discussion and give more detail regarding where this could be implemented?

Comment 3

[Jonathan Griffin (:jgriffin)]

That about sums it up.  In some kind of debug mode, Marionette could attach event listeners to each frame (in "capture" mode), and then report them before they descend down the DOM tree to their target element.  We'd then have some kind of record about what events are generated by manual interactions with Gaia, which would make debugging touch-related problems easier.

Comment 4

[Jonathan Griffin (:jgriffin)]

wait, is this a dupe of bug 883305?

The other thing we want is to be able to log all the touch events that Marionette initiates, so we can see if the coordinates it's using match our expectations.

Comment 5

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Ah right, this bug was originally for logging the touch events that Marionette initiates, and there's bug 883305 for what is described in comment 2. Feel free to mark this as a dupe and open a new bug. Sorry for the noise.

Comment 6

[Jonathan Griffin (:jgriffin)]

We'll just re-purpose this bug!

Comment 7

[Malini Das [:mdas] - Away, not checking bugmail]

Attachment: Log the coordinates of dispatched event

Is this the kind of logging statement you're looking for? It tells you the type of event we're dispatching and the coordinates relative to the viewport, but it can be changed to absolute coordinates if you prefer. We can also add target element information, like the target element's id, or something like that as well. Not sure what level of detail you're looking for.

Comment 8

[Malini Das [:mdas] - Away, not checking bugmail]

Attachment: Log the coordinates of dispatched event

whoops, I rolled up some of my own debugging lines I was just using in the last patch:P

Comment 9

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 765006 [details] [diff] [review]
Log the coordinates of dispatched event

Review of attachment 765006 [details] [diff] [review]:
-----------------------------------------------------------------

Yeah, that's the kind of thing. I think relative to the viewport would actually be most useful. I think we should also get Zac and Bob's thoughts on this. Also, would this end up in the console, logcat, or a log file?

Comment 10

[Bob Silverberg [:bsilverberg]]

I agree that relative to the viewport would be best, and extra information you can provide about the element (you mentioned id) would be nice to have too. I'm not sure what other information might be available, so I'm not sure what else to ask for. This sounds like a good start.

Comment 11

[Malini Das [:mdas] - Away, not checking bugmail]

(In reply to Dave Hunt (:davehunt) from comment #9)
> Comment on attachment 765006 [details] [diff] [review]
> Log the coordinates of dispatched event
> 
> Review of attachment 765006 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Yeah, that's the kind of thing. I think relative to the viewport would
> actually be most useful. I think we should also get Zac and Bob's thoughts
> on this. Also, would this end up in the console, logcat, or a log file?

This will show up in both the logcat and in the marionette.log which is in the profile.

Comment 12

[Malini Das [:mdas] - Away, not checking bugmail]

scratch that, just the logcat. dump() goes to the logcat only

Comment 13

[Zac C (:zac)]

Sounds good.

Comment 14

[Malini Das [:mdas] - Away, not checking bugmail]

Attachment: Log the coordinates of dispatched event

I've added the id and the tag name of the targetted element, since often times in gaia, there is no id, but I found that the tag name does help identify what is being targeted at those coordinates.

There are no targets in mouse events, just coordinates, so I didn't include a target in the log message. You can find the element under the coordinate at which the event is being dispatched, but it may not be related to the actual touch event's target, and so it might be more confusing than helpful.

Comment 15

[Malini Das [:mdas] - Away, not checking bugmail]

oh and that patch cleans up some useless lines

Comment 16

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 766843 [details] [diff] [review]
Log the coordinates of dispatched event

Review of attachment 766843 [details] [diff] [review]:
-----------------------------------------------------------------

This looks good to me, although I haven't tested it as it would require me to build locally which I'm not currently set up for. Would you like me to do this? Also, would it be possible to add this (and potentially other Marionette logging from logcat) available through the marionette.get_logs method? This would be useful for diagnosing failures without the potentially unrelated noise, and we could gather these logs on failure for the reports.

Comment 17

[Malini Das [:mdas] - Away, not checking bugmail]

Sure we can add that to the logs, I'll have to write up a new patch. I'll add the logs with log level 'marionette debug', so when you call get_logs, you'll see any marionette specific debug messages in there. You can also view them by doing

adb logcat | grep Marionette

Comment 18

[Malini Das [:mdas] - Away, not checking bugmail]

Attachment: Log the coordinates of dispatched event to logcat and get_logs

This adds the dump lines to the marionette logger as well, so you can retrieve them using

marionette_session.get_logs()

I've tested it locally and it works as expected.

Comment 19

[Jonathan Griffin (:jgriffin)]

Comment on attachment 767923 [details] [diff] [review]
Log the coordinates of dispatched event to logcat and get_logs

Review of attachment 767923 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/marionette/marionette-listener.js
@@ +583,5 @@
>   */
>  function emitTouchEvent(type, touch) {
> +  let loggingInfo = "Marionette: emitting Touch event of type " + type + " to element with id: " + touch.target.id + " and tag name: " + touch.target.tagName + " at coordinates (" + touch.clientX + ", " + touch.clientY + ") relative to the viewport";
> +  dump(loggingInfo);
> +  marionetteLogObj.log(loggingInfo, "marionette debug");

We don't have pre-defined log levels, but the default level is "INFO", so should this just be "DEBUG"?

@@ +601,5 @@
>   */
>  function emitMouseEvent(doc, type, elClientX, elClientY, detail, button) {
> +  let loggingInfo = "Marionette: emitting Mouse event of type " + type + " at coordinates (" + elClientX + ", " + elClientY + ") relative to the viewport";
> +  dump(loggingInfo);
> +  marionetteLogObj.log(loggingInfo, "marionette debug");

Same as above.

Comment 20

[Malini Das [:mdas] - Away, not checking bugmail]

I used "marionette debug" so if anyone is actually using the log() command with their own debug messages using the "debug" level, then they don't get marionette's debug messages mixed in with it, so it's a 'reserved' log level. I can change it if you prefer, I don't think anyone is really using the log feature anyway, and it's not scoped out in webdriver.

Comment 21

[Jonathan Griffin (:jgriffin)]

I'd rather use something like "trace" in that case, in order to avoid conflating namespace and level.

Comment 22

[Malini Das [:mdas] - Away, not checking bugmail]

"trace" works, I'll use that in the patch and push it, thanks.

Comment 23

[Malini Das [:mdas] - Away, not checking bugmail]

landed in m-i:

https://hg.mozilla.org/integration/mozilla-inbound/rev/eeb93bc152f8

Comment 24

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/eeb93bc152f8

Comment 25

[Zac C (:zac)]

This is being logged directly into the console and polluting our test results.

I thought it would be in logcat, or disabled by default.

How do we turn it off?

Comment 26

[Jonathan Griffin (:jgriffin)]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/dea280fa5d3a

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g18_v1_1_0_hd/rev/dea280fa5d3a