1611004 - Support logging of truncated payload (similar to Marionette)

Status: RESOLVED FIXED

(Testing :: geckodriver, enhancement, P1)

Description

[Nick Alexander :nalexander [he/him]]

Right now geckodriver logs the entire profile as a string as part of its options logging. That's often multiple megabytes of base64-encoded text. This ticket tracks abbreviating that (as chromedriver does), perhaps to

[task 2020-01-20T00:05:37.249Z] 00:05:36     INFO -  1579478736033	webdriver::server	DEBUG	-> POST /session {"desiredCapabilities":{"browserName":"firefox","pageLoadStrategy":"normal","moz:firefoxOptions":{"binary":"/builds/task_1579478599/fetches/node/bin/node","androidPackage":"org.mozilla.geckoview_example","androidActivity":"org.mozilla.geckoview_example.GeckoViewActivity","profile":"UEsDBA ... 10000 characters skipped ... ....", ...

or similar.

Comment 1

[Nick Alexander :nalexander [he/him]]

The code for chromedriver's truncation is around https://github.com/bayandin/chromedriver/blob/f4e99a6cfdc83df1e2c4bfc55b4a1759bbda078a/chrome/log.cc#L67.

Comment 2

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

Marionette itself actually truncates data which extends a specific threshold by using the preference marionette.log.truncate:
https://searchfox.org/mozilla-central/rev/e878e5b81bb319c141900ce9cfcde732df5c8449/testing/marionette/format.js#148

Note that we should still keep an option to disable this truncation behavior. It will help us to check the profile data when investigating trace logs from users of Selenium.

Comment 3

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

This is now causing issues on Treeherder for log parsing (bug 1790755) because the compressed content exceeds 5MB.

My proposal would be to change the -v argument of geckodriver to the following:

1. not set - default info logs only
2. -v - debug logs
3. -vv - trace logs but truncated
4. -vvv - trace logs not truncated

Comment 4

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

Note that this is not only about profile data but basically every payload that gets send or received by geckodriver. As such I've updated the bug's summary. Also for internal tests on Treeherder the profile issue is no longer present given that we now only pass the --profile argument to Firefox and no longer a base64 encoded string within the profile capability.

Comment 5

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

We discussed this on Element and the agreed on solution is the following:

1. Set the threshold for truncation to 1024 characters for both Marionette and geckodriver
2. Add a new CLI argument to geckodriver with the name --log-no-truncate

Comment 6

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

Attachment: Bug 1611004 - [geckodriver] Fix Markdown syntax for documentation.

Comment 7

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

Attachment: Bug 1611004 - [geckodriver] Truncate log entries if length exceeds 250 characters.

Depends on D161212

Comment 8

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

Attachment: Bug 1611004 - [geckodriver] Added --log-no-truncate argument.

Depends on D161213

Comment 9

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

Current situation:

✗ curl -I https://firefoxci.taskcluster-artifacts.net/Nzg1eeNwQHm9eRxbsD9Yiw/0/public/logs/live_backing.log
HTTP/2 200
content-type: text/plain; charset=utf-8
content-length: 5465778

With the patch:

✗ curl -I https://firefoxci.taskcluster-artifacts.net/C8AaEbYUTUmnB3KCx0WdSA/0/public/logs/live_backing.log
HTTP/2 200
content-type: text/plain; charset=utf-8
content-length: 3342437

Here an excerpt from a log with truncated content:
https://treeherder.mozilla.org/logviewer?job_id=395433518&repo=try&lineNumber=163967-163968

[task 2022-11-03T21:56:21.795Z] 21:56:21     INFO - PID 7644 | 1667512581794	Marionette	DEBUG	0 <- [1,18,{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:250:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"},null]
[task 2022-11-03T21:56:21.796Z] 21:56:21     INFO - PID 7644 | 1667512581794	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:250:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/70b457c35346
[geckodriver] Fix Markdown syntax for documentation. r=webdriver-reviewers,jgraham
https://hg.mozilla.org/integration/autoland/rev/a50438b9e5cf
[geckodriver] Truncate log entries if length exceeds 250 characters. r=webdriver-reviewers,jgraham
https://hg.mozilla.org/integration/autoland/rev/711dfd3885f5
[geckodriver] Added --log-no-truncate argument. r=webdriver-reviewers,jgraham

Comment 11

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/70b457c35346
https://hg.mozilla.org/mozilla-central/rev/a50438b9e5cf
https://hg.mozilla.org/mozilla-central/rev/711dfd3885f5