754873 - fennec automated tests should capture logcat output while test is running

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

In a test result such as https://tbpl.mozilla.org/php/getParsedLog.php?id=11727341&tree=Try&full=1 , it would be very helpful to have the logcat output for the full run of the actual test (from app/test launch to finish).  The only logcat-y bits that I see are stuff that's dumped during reboot, but that seems to have the interesting bits already out of the buffer.

Comment 1

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Looks like /system/bin/logcat exists on devices; something like:

First flush/clear the logcat output before running a test:
  /system/bin/logcat -c

Then after a test, dump to a file:
  /system/bin/logcat -d -f outfile.txt

and then pull outfile.txt over.

(/system/bin/logcat -? will show some other options)

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: add logcat output to reftest (0.9)

this patch does two things:
1) allows for remote reftest to be used as a harness and not a script.  I found that if there was an exception, we were calling sys.exit(..).  Also passing in args was impossible.

2) what this bug is titled.  This is the logcat information and appears to work fairly reasonable.  This does not cover the entire history of logcat during the test run.  What this does is capture the relevant logcat information that it finds in the log buffer shortly before the app finished/quit.

This could use some cleanup, but it gets the ball rolling.

Comment 3

[William Lachance (:wlach)]

Comment on attachment 628493 [details] [diff] [review]
add logcat output to reftest (0.9)

In general looks ok. I have some architectural nits, but if it's urgent to get more information I would be ok with this going in as-is.

--

Nit #1:

I would prefer to add some commands to manipulate/save logcats at the devicemanager level. I've already written such code for Eideticker:

https://github.com/mozilla/eideticker/blob/49bf9cdb0f8ffe2295b5a5c20f62a34afb0fc0ef/src/eideticker/eideticker/device.py#L67

The fact that you've written very similar code is a sign that we should try and solve this problem at a higher level of abstraction. :) I think it should be possible to come up with a nice API for this.

Nit #2:

+    for line in data:
+        if not line.startswith("D/dalvikvm") and \
+           not line.startswith("V/WifiMonitor") and \
+           not line.startswith("V/WifiStateTracker") and \
+           not line.startswith("D/ConnectivityService") and \
+           not line.startswith("I/wpa_supplicant"):

I'd prefer if we could filter these out beforehand and I believe we can by doing something like:

<foo>:S

e.g.

logcat dalvikvm:S

See here for more info:

http://www.herongyang.com/Android/Debug-adb-logcat-Command-Argument-Output-Filter.html

Comment 4

[Jonathan Griffin (:jgriffin)]

I have a similar need in B2G, which I've also solved with a one-off.  Note that logcat only stores some maximum amount of data in the log (on my device it is 2MB; but it may vary); if there is more data than that, it deletes lines at the top of the log.  So if there is > 2MB of data (which happens easily with mochitest), just doing logcat -d at the end of the test run won't give you everything.

For B2G I'm thinking of spinning a thread to read the realtime output of logcat (no arguments) to avoid this issue.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

I am open to anything.  If we can do a thread or something similar in sutagent or thereabouts, I am very open to capturing the logcat output for the entire test run.  

:wlach, thanks for the tips, I will look at filtering out the biggest noisemakers via logcat commandline.

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: collect logcat information on mochitest + reftest (2.0)

this patch is updated with some of the feedback.  This puts an api in devicemanager to record and retrieve logcat information.  I have tested this on try server and we get the appropriate logcat information in the logs!  Also this works well for local sut or adb usage.

What this doesn't do is spin it off in a thread, so we are limited by the buffer size.  I think for now that is acceptable, but with the way the API is designed we can replace the devicemanager bits to do that successfully.

In addition, I clean up the remotereftest script so that we can treat it as a module rather than a shell script.

Comment 7

[William Lachance (:wlach)]

Comment on attachment 630972 [details] [diff] [review]
collect logcat information on mochitest + reftest (2.0)

Thanks for following up on this. Looks good. I have just one serious problem with this patch. In this function in dmADB/dmSUT:

+  def getLogcat(self, filename):
+    #TODO: when recordLogcat spawns off, this will just terminate the collector
+    self.checkCmdAs(["shell", "/system/bin/logcat", "-d", "-f", "%s/logcat.log" % self.getDeviceRoot(), "dalvikvm:S ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S"])
+
+    self.getFile('%s/logcat.log' % self.getDeviceRoot(), 'logcat.log')
+    fHandle = open('logcat.log')
+    data = fHandle.readlines()
+    fHandle.close()
+    return data

You don't clean up either the local or remote version of logcat.log after using it. Also, you're not using the filename parameter AFAICT. This is a bit messy. I think we can do better.

I think we can replace both these functions with a simpler version in devicemanager. Something like:

def getLogCat(self):
  buf = StringIO.StringIO()
  if self.shell(["/system/bin/logcat", "-d", "dalvikvm:S ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S"], buf) != 0:
    return None
  return str(buf.getvalue()[0:-1]).rstrip()

I also would recommend putting all this logcat stuff in droid.py's DroidSUT or DroidADB classes (and then modifying mochitest to use those), as this is VERY android-specific.

Comment 8

[William Lachance (:wlach)]

(In reply to William Lachance (:wlach) from comment #7)
> Comment on attachment 630972 [details] [diff] [review]

> I also would recommend putting all this logcat stuff in droid.py's DroidSUT
> or DroidADB classes (and then modifying mochitest to use those), as this is
> VERY android-specific.

Actually I guess this stuff would be usable by B2G as well. Disregard that comment, probably best to just put this in devicemanager for now.

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

to do this via self.shell(), won't work without modifying devicemanagerSUT shell to add a su -c.

Comment 10

[William Lachance (:wlach)]

See bug 754873 on making execute-as-root the default inside the agent.

Comment 11

[William Lachance (:wlach)]

Sorry, seems like I have a case of the Mondays. I mean bug 763497.

Comment 12

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: collect logcat information on mochitest + reftest (3.0)

updated and tested on try server.

Comment 13

[William Lachance (:wlach)]

Comment on attachment 632677 [details] [diff] [review]
collect logcat information on mochitest + reftest (3.0)

Looks good now, thanks. We may eventually want to make the logging settings configurable, but we can do that later.

Comment 14

[Joel Maher ( :jmaher ) (UTC -8)]

inbound:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3bffe02b6223

Comment 15

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/3bffe02b6223

Comment 16

[Kartikaya Gupta (email:[e-mail])]

Is this only for reftests? It would be nice to have this for all android tests (such as to diagnose the talos redness currently happening on inbound)

Comment 17

[Joel Maher ( :jmaher ) (UTC -8)]

I have a patch for talos, but it creates red jobs due to the log parsing stuff.  I think it finds strings in the logcat output and marks the job red.

Comment 18

[Kartikaya Gupta (email:[e-mail])]

Is the patch on a bug somewhere? It would still be useful for me if I can push it to try and get logcat output.

Comment 19

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: talos should output logcat information (1.0)

and the bugs eventually get resolved

Comment 20

[Joel Maher ( :jmaher ) (UTC -8)]

not sure why this was resolved, it is reopened now.

Comment 21

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: talos should output logcat information (2.0)

thanks to :wlach for reminding me about the devicemanager api for doing this.  Simplified code, tested locally == WIN!

Comment 22

[Jeff Hammel]

Comment on attachment 669693 [details] [diff] [review]
talos should output logcat information (2.0)

lgtm

Comment 23

[Joel Maher ( :jmaher ) (UTC -8)]

http://hg.mozilla.org/build/talos/rev/066af6a96478