855407 - Route tests output to the metrotestharness console

Status: RESOLVED FIXED

(Firefox for Metro Graveyard :: Tests, defect)

Description

[Jim Mathies [:jimm]]

I believe we'll need this for proper tbpl integration. Currently metrotestharness makes a call to Windows, which launches the default browser (Metro Firefox). So normally in local runs we use test log files to check output. But I think for tbpl, test chatter needs to go to the slave harness console that launches metrotestharness. 

I'm not 100% sure how this all works. Filing this bug for figuring it out.

Comment 1

[Jim Mathies [:jimm]]

Looking at browser-chrome output, I see we have something running that catches this output - 

MultiFileLogger online at 20130327 04:23:49 in c:\talos-slave\test

Maybe we can latch into that? I'd appreciate some guidance from rel eng, not sure how to address this.

Comment 2

[Armen [:armenzg]]

I would have to hack mozharness to allow us to run these tests.

Do you want to wait until I have that in place?
You could then run locally exactly what we would run in production.

Comment 3

[Jim Mathies [:jimm]]

(In reply to Armen Zambrano G. [:armenzg] from comment #2)
> I would have to hack mozharness to allow us to run these tests.
> 
> Do you want to wait until I have that in place?
> You could then run locally exactly what we would run in production.

I'm not sure I understand. Would you be hacking mozharness to get it to pick up test output from logs, or..?

Comment 4

[Armen [:armenzg]]

Hrmm

I think if you run this directly you would be able to see how it works for browser-chrome:
hg clone http://hg.mozilla.org/build/mozharness
python mozharness/scripts/desktop_unittest.py --cfg unittests/win_unittest.py --mochitest-suite chrome --download-symbols ondemand

I think we look at the stdout [1] and then create TinderboxPrint line [2].

[1]
11:15:57     INFO -  940 INFO TEST-START | Shutdown
11:15:57     INFO -  941 INFO Passed: 819
11:15:57     INFO -  942 INFO Failed: 0
11:15:57     INFO -  943 INFO Todo:   0
11:15:57     INFO -  944 INFO SimpleTest FINISHED
11:15:57     INFO -  945 INFO TEST-INFO | Ran 0 Loops
11:15:57     INFO -  946 INFO SimpleTest FINISHED

[2]
11:15:59     INFO -  INFO | automation.py | Application ran for: 0:00:36.785000
11:15:59     INFO -  INFO | zombiecheck | Reading PID log: c:\users\cltbld\appdata\local\temp\tmpx_rmlhpidlog
11:15:59     INFO -  SUCCESS: The process with PID 852 has been terminated.
11:15:59     INFO -  SUCCESS: The process with PID 3108 has been terminated.
11:15:59     INFO -  SUCCESS: The process with PID 2960 has been terminated.
11:15:59     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
11:15:59     INFO -  INFO | runtests.py | Running tests: end.
11:15:59     INFO - Return code: 0
11:15:59     INFO - TinderboxPrint: mochitest-plugins<br/>819/0/0
11:15:59     INFO - # TBPL SUCCESS #
11:15:59     INFO - The mochitest suite: plugins ran with return status: SUCCESS
11:15:59     INFO - Copying logs to upload dir...
11:15:59     INFO - mkdir: c:\talos-slave\test\build\upload\logs

Comment 5

[Jim Mathies [:jimm]]

Ok, so desktop_unittest.py launches runtets.py, which launches metrotestharness.exe, which asks Windows to launch the browser.

I guess we need to find a way to get at the test output generated in the browser. We could generate and tail test output logs maybe, or we could try to hook up stdout/stderr somehow.

I'll poke around to see what I can come up with.

Comment 6

[Jim Mathies [:jimm]]

Attachment: patch

Comment 7

[Jim Mathies [:jimm]]

Attachment: patch

sorry for the review spam, minor nit in comments touched up.

Comment 9

[Tim Abraldes [:TimAbraldes] [:tabraldes]]

Comment on attachment 730388 [details] [diff] [review]
patch

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

This looks fine as is, just some clean-up comments.  I assume this is tested and works as expected.

::: browser/app/nsBrowserApp.cpp
@@ +106,5 @@
> +#ifdef XP_WIN
> +/*
> + * AttachToTestsConsole - Windows helper for when we are running
> + * in the immersive environment. Firefox is launched by Windows in
> + * a response to a request by metrotestharness, which is launched

nit: "in response" instead of "in a response"

@@ +109,5 @@
> + * in the immersive environment. Firefox is launched by Windows in
> + * a response to a request by metrotestharness, which is launched
> + * by runtests.py. As such stdout in fx doesn't point to the right
> + * stream. This helper touches up stdout such that test output gets
> + * gets routed to the console the tests are run in.

nit: the word "gets" is repeated

@@ +128,5 @@
> +    return;
> +  }
> +
> +  // Set the c runtime handle
> +  int stdOut = _open_osfhandle((intptr_t)winOut, _O_APPEND);

I noticed that we're opening the file descriptor for append, but later when we open the stream we open for write.  It probably won't affect functionality, but just to make our intention more explicit could we change one of the calls so that they match?

@@ +133,5 @@
> +  if (stdOut == -1) {
> +    OutputDebugStringW(L"Could not open c-runtime handle.\n");
> +    return;
> +  }
> +  FILE *fp = _fdopen(stdOut, "w");

Here we're opening the stream for write, but previously we opened the file descriptor for append.  It probably won't affect functionality, but just to make our intention more explicit could we change one of the calls so that they match?

@@ +352,5 @@
>          if (isspace(*ptr)) {
>            *ptr = '\0';
>            ptr++;
> +          // Check for the console id the metrotestharness passes in, we need
> +          // to connect up to this so test output goes to the right place.

This code won't find the "testconsoleid=" if it's the first parameter.  That probably won't ever happen, but maybe we could do our processing of the "testconsoleid=" paramater after we've already populated newArgv?

@@ +354,5 @@
>            ptr++;
> +          // Check for the console id the metrotestharness passes in, we need
> +          // to connect up to this so test output goes to the right place.
> +          if (ptr && !strncmp(ptr, "testconsoleid=", 14)) {
> +            DWORD processId = strtol(ptr+14, nullptr, 10);

This would look cleaner to me if we defined a string constant for "testconsoleid=" at the top of the file; I'll call that kConsoleIdArg here.

That lets us also define a constant that holds onto the length of that string, e.g. "const kConsoleIdArgLen = strlen(kConsoleIdArg);"

Then this section can be rewritten as:
if (!strcmp(ptr, kConsoleIdArg)) {
  DWORD processId = strtol(ptr+kConsoleIdArgLen, nullptr, 10);

Note that stricmp isn't necesary (meaning that we can use strcmp instead) since kConsoleIdArg is always null-terminated and so the comparison will always stop after kConsoleIdArgLen comparisons.  It is also not necessary to check "if (ptr)" since there's no way it could have become null.

Comment 10

[Jim Mathies [:jimm]]

(In reply to Tim Abraldes (:tabraldes) (:TimAbraldes) from comment #9)

updated per comments up to this point.

> @@ +352,5 @@
> >          if (isspace(*ptr)) {
> >            *ptr = '\0';
> >            ptr++;
> > +          // Check for the console id the metrotestharness passes in, we need
> > +          // to connect up to this so test output goes to the right place.
> 
> This code won't find the "testconsoleid=" if it's the first parameter.  That
> probably won't ever happen, but maybe we could do our processing of the
> "testconsoleid=" paramater after we've already populated newArgv?

I'm not worried about this, testconsoleid= is always appended on the end of the parameter string by metrotestharness.

> 
> @@ +354,5 @@
> >            ptr++;
> > +          // Check for the console id the metrotestharness passes in, we need
> > +          // to connect up to this so test output goes to the right place.
> > +          if (ptr && !strncmp(ptr, "testconsoleid=", 14)) {
> > +            DWORD processId = strtol(ptr+14, nullptr, 10);
> 
> This would look cleaner to me if we defined a string constant for
> "testconsoleid=" at the top of the file; I'll call that kConsoleIdArg here.

good catch, I like using constants as well.


> That lets us also define a constant that holds onto the length of that
> string, e.g. "const kConsoleIdArgLen = strlen(kConsoleIdArg);"
> 
> Then this section can be rewritten as:
> if (!strcmp(ptr, kConsoleIdArg)) {
>   DWORD processId = strtol(ptr+kConsoleIdArgLen, nullptr, 10);
> 
> Note that stricmp isn't necesary (meaning that we can use strcmp instead)
> since kConsoleIdArg is always null-terminated and so the comparison will
> always stop after kConsoleIdArgLen comparisons.  It is also not necessary to
> check "if (ptr)" since there's no way it could have become null.

Interesting point. I've always assumed the null check only applied to str1, but I guess str2 can act as a stop as well from looking at the ansi spec.

Comment 11

[Jim Mathies [:jimm]]

> > Note that stricmp isn't necesary (meaning that we can use strcmp instead)
> > since kConsoleIdArg is always null-terminated and so the comparison will
> > always stop after kConsoleIdArgLen comparisons.  It is also not necessary to
> > check "if (ptr)" since there's no way it could have become null.
> 
> Interesting point. I've always assumed the null check only applied to str1,
> but I guess str2 can act as a stop as well from looking at the ansi spec.

pfft, nm. This doesn't work since ptr = "consoleid=1234". :) strcmp won't find a match, we need to use strncmp. I updated to use the constant though.

Comment 12

[Jim Mathies [:jimm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/17b7d2222f14

Comment 13

[Jim Mathies [:jimm]]

Looks like this triggered leaks on inbound. RyanVM is going to back it out to see.

Comment 14

[Ryan VanderMeulen [:RyanVM]]

These are the leaks we saw:
https://tbpl.mozilla.org/php/getParsedLog.php?id=21245110&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=21245265&tree=Mozilla-Inbound

However, I couldn't get them to appear again to save my life, so I can't say with any certainty whether this really caused the leaks or not :(

Comment 15

[Jim Mathies [:jimm]]

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

Comment 16

[Ryan VanderMeulen [:RyanVM]]

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