887888 - Bug 829211 made Android Panda logs repeat every line twice

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Phil Ringnalda (:philor)]

From https://bugzilla.mozilla.org/show_bug.cgi?id=829211#c39

> I'm not sure whether there are any critical results to this, or just
> aesthetic and annoyance results, but that had the effect of making the panda
> unittests double-log everything, e.g.
> 
> https://tbpl.mozilla.org/php/getParsedLog.php?id=24637979&tree=Mozilla-
> Inbound
> 
> 16:59:56     INFO -  4916 INFO TEST-PASS |
> /tests/dom/workers/test/test_atob.html | Saw all values
> 06/26/2013 16:59:56: INFO:  4916 INFO TEST-PASS |
> /tests/dom/workers/test/test_atob.html | Saw all values
> 16:59:56     INFO -  4917 INFO TEST-END |
> /tests/dom/workers/test/test_atob.html | finished in 449ms
> 06/26/2013 16:59:56: INFO:  4917 INFO TEST-END |
> /tests/dom/workers/test/test_atob.html | finished in 449ms

Comment 1

[Phil Ringnalda (:philor)]

Well, one more-than-aesthetic result, I'm not willing to copy-paste doubled lines into a bug, and I'm not willing to take the time to delete every other line in a textarea full of copy-pasted log chunk, so I'm mostly just retriggering android intermittents rather than filing them.

Comment 2

[Ryan VanderMeulen [:RyanVM]]

This makes Android log parsing significantly more difficult.

Comment 3

[Kim Moir [:kmoir] ET]

I looked at this on Friday but haven't found the source of the problem yet, still looking....

Comment 4

[Kim Moir [:kmoir] ET]

Attachment: patch

This fixed the issue in staging

Comment 5

[Kim Moir [:kmoir] ET]

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

No it didn't, I was looking at the wrong device. Not sure how to fix this since this approach didn't work.

Comment 6

[Aki Sasaki (not active)]

I think the only way I know of around this is somehow allowing for no logger in sut_lib.py.

I know creating a second logging object in mozharness will cause double logging to occur.  I think this is a basic flaw in the python logging object... global scope.

Comment 7

[Justin Wood (:Callek)]

Attachment: [mozharness] do it

This does it in staging, e.g. http://dev-master01.build.scl1.mozilla.com:8036/builders/Android%204.0%20Panda%20mozilla-central%20opt%20test%20robocop-1/builds/228/steps/run_script/logs/stdio

Comment 8

[Aki Sasaki (not active)]

Comment on attachment 772655 [details] [diff] [review]
[mozharness] do it

self.add_failure(...) will log the failure and make sure we don't exit 0, but the script will continue; is this desired behavior?

Comment 9

[Justin Wood (:Callek)]

[12:47:34]	Callek|buildduty	aki: different topic: Bug 887888 -- we want to be sure to run http://mxr.mozilla.org/build/source/mozharness/scripts/android_panda.py#395 -- but beyond that running anything else is undesireable
[12:48:15]	aki	Callek|buildduty: then you can self.close_request(); self.fatal("clear reason why we're dying")
[12:48:42]	Callek|buildduty	aki: ahhh ok
[12:48:45]	aki	or better yet, self.critical("preparing to die because reason"); self.close_request(); self.fatal("ok now dying")
[12:48:56]	=-=	dminor|lunch is now known as dminor
[12:49:03]	Callek|buildduty	aki: need a new r? for that or should I just land with that change?
[12:49:11]	aki	i'm ok either way
[12:49:23]	aki	if you want another look i can
[12:49:31]	Callek|buildduty	ok, I'll likely fix that up later today or early tomorrow and land
[12:49:32]	Callek|buildduty	thanks
[12:49:39]	Callek|buildduty	copies convo to bug for history

Comment 10

[Justin Wood (:Callek)]

In production

Comment 12

[Ed Morley [:emorley]]

This is unfortunately still happening, eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=25283167&tree=Mozilla-Inbound
{
06:11:14     INFO -  DMError: Automation Error: Timeout in command activity
07/15/2013 06:11:14: INFO:  DMError: Automation Error: Timeout in command activity
06:11:14     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
07/15/2013 06:11:14: INFO:  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
}

Comment 13

[Justin Wood (:Callek)]

Ooooo, ffs, I merged the wrong damn patch :( (how did that happen)

Wrong patch was http://hg.mozilla.org/build/mozharness/rev/f38888be196c

Backed out in  https://hg.mozilla.org/build/mozharness/rev/d8365831a23b

And now landed in https://hg.mozilla.org/build/mozharness/rev/c8f22b42b51e

Comment 14

[Aki Sasaki (not active)]

Merged to mozharness production.

Comment 15

[Justin Wood (:Callek)]

And I'm soooo bad at properly landing patches today:

remote:   https://hg.mozilla.org/build/mozharness/rev/0bdefe5db1e4 (backout)
remote:   https://hg.mozilla.org/build/mozharness/rev/4bf1acfecd9c (default)
remote:   https://hg.mozilla.org/build/mozharness/rev/4f5d43dc602a (merge)