1529516 - Error stack for logging in TimedPromise only contains it's own frame

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, enhancement, P1)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Given that we raise/log the error of a TimedPromise in a callback using errors.stack() the resulted trace only contains the TimedPromise frame but nothing from above. As such it is pretty useless for debugging purposes.

With the above fixed we would clutter the log a lot for calls to Sleep(). As such I would suggest to add some kind of option to fully prevent logging.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1529516 - [marionette] Make stacktrace of logged TimedPromise contain the upper stack.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1529516 - [marionette] Use Promise instead of TimedPromise for Sleep(). r?ato

This is especially needed for "Sleep()", which by default runs
into a timeout condition, but logging it as warning would massively
clutter the log files.

Depends on D20637

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=164ab423002f6af618d9ec190094fa795aa4c391

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4e00119c579c
[marionette] Make stacktrace of logged TimedPromise contain the upper stack. r=ato
https://hg.mozilla.org/integration/autoland/rev/0c48c658c7cf
[marionette] Use Promise instead of TimedPromise for Sleep(). r=ato

Comment 5

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/4e00119c579c
https://hg.mozilla.org/mozilla-central/rev/0c48c658c7cf

Comment 6

[Noemi Erli[:noemi_erli]]

Backed out 2 changesets (Bug 1529516) per dev's request for causing issues with wdspec a=backout

Comment 7

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/mozilla-central/rev/9f20371d98ec
Backed out 2 changesets per dev's request for causing issues with wdspec a=backout

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Somehow the Sleep() command as heavily used in Action tests is causing a hang. Not sure how this can happen, beside that calling timer.initWithCallback() would raise an error which we don't handle. I will have to investigate it.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Maybe we can just go forward with https://phabricator.services.mozilla.com/D20637 and leave out the changes to Sleep, which are unrelated to this bug anyway. Applying the patch locally and fixing the merge conflicts I get correct output:

1577975040525	Marionette	WARN	TimedPromise timed out after 5000 ms: stacktrace:
TimedPromise/<@chrome://marionette/content/sync.js:244:13
TimedPromise@chrome://marionette/content/sync.js:229:10
GeckoDriver.prototype.maximizeWindow@chrome://marionette/content/driver.js:3194:11
Async*despatch@chrome://marionette/content/server.js:305:40
execute@chrome://marionette/content/server.js:275:16
onPacket/<@chrome://marionette/content/server.js:248:20
onPacket@chrome://marionette/content/server.js:249:9
_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20

I will obsolete the second attachment and do a new try push.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I filed bug 1606637 for the proposed changes to Sleep.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/839abbc18dd6
[marionette] Make stacktrace of logged TimedPromise contain the upper stack. r=ato,marionette-reviewers

Comment 12

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/839abbc18dd6