Closed Bug 1091413 Opened 7 years ago Closed 7 years ago

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

Categories

(Testing :: Mozbase, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
mozilla36

People

(Reporter: markh, Assigned: chmanchester)

References

Details

Attachments

(1 file)

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)
> 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?
Flags: needinfo?(james)
Duplicate of this bug: 1091627
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.
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).
Flags: needinfo?(james)
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
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.
Attachment #8514322 - Flags: review?(james) → review+
https://hg.mozilla.org/mozilla-central/rev/fdc84bee1da6
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
You need to log in before you can comment on or make changes to this bug.