1091413 - [mozlog] xpcshell-test PROCESS_OUTPUT when running a single test is too verbose

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

I often run individual xpcshell tests, and often these tests cause log output to be dump()'d (typically via a DumpAppender added to relevant logs.

Now when I run the tests, it's very difficult to read the test output.  For example:

 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.BrowserIDManager	INFO	initializeWithCurrentIdentity has no user logged in
" (pid:13704 command:['o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\xpcshell.exe', '-g', 'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin', '-a', u'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\browser', '-r', 'o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.manifest', '-m', '-s', '-e', 'const _HTTPD_JS_PATH = "o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.js";', '-e', 'const _HEAD_JS_PATH = "o:/src/mozilla-git/gecko-dev/testing/xpcshell/head.js";', '-e', 'const _TESTING_MODULES_DIR = "o:\\\\src\\\\mozilla-git\\\\gecko-dev\\\\obj-release\\\\_tests\\\\modules\\\\";', '-f', 'o:\\src\\mozilla-git\\gecko-dev\\testing\\xpcshell\\head.js', '-p', 'c:\\users\\skip\\appdata\\local\\temp\\tmpsfs06h', '-e', 'const _SERVER_ADDR = "localhost"', '-e', u'const _HEAD_FILES = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_appinfo.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/common/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_http_server.js"];', '-e', 'const _TAIL_FILES = [];', '-e', u'const _TEST_FILE = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"];', '-e', u'const _TEST_NAME = "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"', '-e', '_execute_test(); quit(0);'])
 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.BrowserIDManager	INFO	Username changed. Removing stored credentials.
" (pid:13704 command:['o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\xpcshell.exe', '-g', 'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin', '-a', u'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\browser', '-r', 'o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.manifest', '-m', '-s', '-e', 'const _HTTPD_JS_PATH = "o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.js";', '-e', 'const _HEAD_JS_PATH = "o:/src/mozilla-git/gecko-dev/testing/xpcshell/head.js";', '-e', 'const _TESTING_MODULES_DIR = "o:\\\\src\\\\mozilla-git\\\\gecko-dev\\\\obj-release\\\\_tests\\\\modules\\\\";', '-f', 'o:\\src\\mozilla-git\\gecko-dev\\testing\\xpcshell\\head.js', '-p', 'c:\\users\\skip\\appdata\\local\\temp\\tmpsfs06h', '-e', 'const _SERVER_ADDR = "localhost"', '-e', u'const _HEAD_FILES = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_appinfo.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/common/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_http_server.js"];', '-e', 'const _TAIL_FILES = [];', '-e', u'const _TEST_FILE = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"];', '-e', u'const _TEST_NAME = "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"', '-e', '_execute_test(); quit(0);'])
 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.BrowserIDManager	ERROR	Could not authenticate: no user is logged in
" (pid:13704 command:['o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\xpcshell.exe', '-g', 'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin', '-a', u'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\browser', '-r', 'o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.manifest', '-m', '-s', '-e', 'const _HTTPD_JS_PATH = "o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.js";', '-e', 'const _HEAD_JS_PATH = "o:/src/mozilla-git/gecko-dev/testing/xpcshell/head.js";', '-e', 'const _TESTING_MODULES_DIR = "o:\\\\src\\\\mozilla-git\\\\gecko-dev\\\\obj-release\\\\_tests\\\\modules\\\\";', '-f', 'o:\\src\\mozilla-git\\gecko-dev\\testing\\xpcshell\\head.js', '-p', 'c:\\users\\skip\\appdata\\local\\temp\\tmpsfs06h', '-e', 'const _SERVER_ADDR = "localhost"', '-e', u'const _HEAD_FILES = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_appinfo.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/common/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_http_server.js"];', '-e', 'const _TAIL_FILES = [];', '-e', u'const _TEST_FILE = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"];', '-e', u'const _TEST_NAME = "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"', '-e', '_execute_test(); quit(0);'])
 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.Service	INFO	Loading Weave 1.38.0
" (pid:13704 command:['o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\xpcshell.exe', '-g', 'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin', '-a', u'o:\\src\\mozilla-git\\gecko-dev\\obj-release\\dist\\bin\\browser', '-r', 'o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.manifest', '-m', '-s', '-e', 'const _HTTPD_JS_PATH = "o:/src/mozilla-git/gecko-dev/obj-release/dist/bin/components/httpd.js";', '-e', 'const _HEAD_JS_PATH = "o:/src/mozilla-git/gecko-dev/testing/xpcshell/head.js";', '-e', 'const _TESTING_MODULES_DIR = "o:\\\\src\\\\mozilla-git\\\\gecko-dev\\\\obj-release\\\\_tests\\\\modules\\\\";', '-f', 'o:\\src\\mozilla-git\\gecko-dev\\testing\\xpcshell\\head.js', '-p', 'c:\\users\\skip\\appdata\\local\\temp\\tmpsfs06h', '-e', 'const _SERVER_ADDR = "localhost"', '-e', u'const _HEAD_FILES = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_appinfo.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/common/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_helpers.js", "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/head_http_server.js"];', '-e', 'const _TAIL_FILES = [];', '-e', u'const _TEST_FILE = ["o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"];', '-e', u'const _TEST_NAME = "o:/src/mozilla-git/gecko-dev/obj-release/_tests/xpcshell/services/sync/tests/unit/test_fxa_migration.js"', '-e', '_execute_test(); quit(0);'])

is just 4 lines of output, and those lines are obscured by all the redundant process info printed for each line.  Compare this without those extra lines:

 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.BrowserIDManager	INFO	initializeWithCurrentIdentity has no user logged in
 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.BrowserIDManager	INFO	Username changed. Removing stored credentials.
 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.BrowserIDManager	ERROR	Could not authenticate: no user is logged in
 0:01.17 PROCESS_OUTPUT: Thread-1 "Sync.Service	INFO	Loading Weave 1.38.0

where the information is actually readable.

I can't find an option to mach to suppress this, but I assert that this level of detail is too verbose by default and there should be an option to enable it in special cases where it is relevant (and I'd also assert that simply including the PID in that first line next to "Thread-1" would be sufficient)

Comment 1

[Chris Manchester (limited bugmail, email directly)]

> I can't find an option to mach to suppress this, but I assert that this
> level of detail is too verbose by default and there should be an option to
> enable it in special cases where it is relevant (and I'd also assert that
> simply including the PID in that first line next to "Thread-1" would be
> sufficient)

I tend to agree. :jgraham, would other users of the machformatter be amenable to this change?

Comment 3

[Chris Manchester (limited bugmail, email directly)]

Noted in bug 1091627, passing '--log-tbpl -' to mach will result in an output format that's less noisy for this case as an immediate workaround.

Comment 4

[James Graham [:jgraham]]

Sure. Maybe we could do something even cleverer like the first time we see output from a command print

PID: 1234 command: ["xpcshell", "lots", "of", "args"]
PROCESS_OUTPUT: Thread-1 1234 "some output"

Then for remaining bits of output for the same PID just print the second of those lines.

(that format probably isn't exactly right, but you get the idea).

Comment 5

[Chris Manchester (limited bugmail, email directly)]

Attachment: Refrain from printing the command args with each call to process_output in mozlog's machformatter

Comment 6

[James Graham [:jgraham]]

Comment on attachment 8514322 [details] [diff] [review]
Refrain from printing the command args with each call to process_output in mozlog's machformatter

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

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +43,5 @@
>          self.has_unexpected = {}
>          self.last_time = None
>          self.terminal = terminal
>          self.verbose = False
> +        self._known_pids = set()

Well pids aren't really unique, but I think this is fine.

Comment 7

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

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

Comment 8

[Carsten Book [:Tomcat]]

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