1034236 - Java implementation of the structuredlog API

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Testing, defect)

Description

[Ahmed Kachkach [:akachkach]]

To transit mochitest to structured logs (bug 886570), we'll need to change the robocop Java code to output structured logs. Specifically, the FennecMochitestAssert class ( http://dxr.mozilla.org/mozilla-central/source/build/mobile/robocop/FennecMochitestAssert.java#85 ). A utility class similar to the Python implementation (StructuredLogger) seems like the best way to achieve this.

It's still unsure if this bug blocks bug 886570 (currently trying to find an interim solution) but this will definitely be needed to convert all mochitests to structured logs.

Comment 1

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1034236-Java-implementation-of-StructuredLogger.patch

Initial patch; We'll probably need to include GSON (https://code.google.com/p/google-gson/) as a dependency to dump the messages in the JSON format.

Comment 2

[Chris Manchester (limited bugmail, email directly)]

(In reply to Ahmed Kachkach [:akachkach] from comment #1)
> Created attachment 8450570 [details] [diff] [review]
> 0001-Bug-1034236-Java-implementation-of-StructuredLogger.patch
> 
> Initial patch; We'll probably need to include GSON
> (https://code.google.com/p/google-gson/) as a dependency to dump the
> messages in the JSON format.

I see org.json.* in the tree a lot, maybe that will do the job?

Comment 3

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1034236-Java-implementation-of-StructuredLogger.patch

Didn't notice we were already using org.json!

Working implementation, adapted for org.json ; For now it automatically dumps the JSON to stdout, still unsure what's the best way to pass handlers here.

Comment 4

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1034236-Java-implementation-of-StructuredLogger.patch

Added a LoggerCallback interface used for passing arbitrary callbacks to the structured logger (to print on stdout, save to a file, etc.)

Comment 5

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

Comment on attachment 8452673 [details] [diff] [review]
0001-Bug-1034236-Java-implementation-of-StructuredLogger.patch

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

a lot of questions after reading this code, please resolve those.

I am still not sure how this will be used.  I would like to know if there is a second patch or what we plan to do with Robocop to make it use this new file.

::: build/mobile/robocop/StructuredLogger.java
@@ +10,5 @@
> +
> +import org.json.JSONObject;
> +
> +public class StructuredLogger {
> +    public static ArrayList<String> validTestStatus = new ArrayList(Arrays.asList("PASS", "FAIL", "TIMEOUT", "NOTRUN", "ASSERT"));

is there a possibility of todo here?  I see skip as a valid option for testend.

@@ +53,5 @@
> +    }
> +
> +    public void suiteStart(List<String> tests) {
> +        this.suiteStart(tests, null);
> +    }

I don't understand what suiteSTart is?  do we expect a full list of all tests that belong to the suite to be passed in?

@@ +57,5 @@
> +    }
> +
> +    public void suiteEnd() {
> +        this.logData("suite_end");
> +    }

what defined a suite?

@@ +81,5 @@
> +            data.put("message", message);
> +        }
> +        if (expected.equals(status)) {
> +            data.put("expected", expected);
> +        }

I don't understand why we would put expected in here if it equals status, why not just put it in there all the time or do logic in here to print pass/fail?

@@ +88,5 @@
> +    }
> +
> +    public void testStatus(String test, String subtest, String status, String message) {
> +        this.testStatus(test, subtest, status, "PASS", message);
> +    }

what is a subtest?

@@ +108,5 @@
> +            data.put("extra", extra);
> +        }
> +        if (expected.equals(status) && !status.equals("SKIP")) {
> +            data.put("expected", expected);
> +        }

please document why we would not put expected in there if it is 'SKIP'

@@ +154,5 @@
> +        allData.put("action", action);
> +        allData.put("time", System.currentTimeMillis());
> +        allData.put("thread", JSONObject.NULL);
> +        allData.put("pid", JSONObject.NULL);
> +        allData.put("source", mName);

why do we have thread/pid in here and we don't use them?

@@ +175,5 @@
> +    }
> +
> +    private void logData(String action) {
> +        this.logData(action, new HashMap<String, Object>());
> +    };

nit: you have a trailing semicolon here, all other methods do not, keep it consistent.

Comment 6

[Ahmed Kachkach [:akachkach]]

Comment on attachment 8452673 [details] [diff] [review]
0001-Bug-1034236-Java-implementation-of-StructuredLogger.patch

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

Most of the comments refer to the structured logging API, not the implementation. Again, this is just translating the structured logging API to Java. More info here:
http://mozbase.readthedocs.org/en/latest/mozlog_structured.html

And especially the source of the Python StructuredLogger:
http://mozbase.readthedocs.org/en/latest/_modules/mozlog/structured/structuredlog.html#StructuredLogger

::: build/mobile/robocop/StructuredLogger.java
@@ +81,5 @@
> +            data.put("message", message);
> +        }
> +        if (expected.equals(status)) {
> +            data.put("expected", expected);
> +        }

This is actually a bug. It should be !expected.equals(status).
(and this is a convention with the structured logging API: if status == expected, we shouldn't have an expected field)

@@ +108,5 @@
> +            data.put("extra", extra);
> +        }
> +        if (expected.equals(status) && !status.equals("SKIP")) {
> +            data.put("expected", expected);
> +        }

Again here, it's a bug: should've put !expected.equals(status).
For "SKIP", I have no idea. (as with the rest this is merely an implementation of the conventions we have in the Python API)

@@ +154,5 @@
> +        allData.put("action", action);
> +        allData.put("time", System.currentTimeMillis());
> +        allData.put("thread", JSONObject.NULL);
> +        allData.put("pid", JSONObject.NULL);
> +        allData.put("source", mName);

Currently set to NULL as they're required field, but not used anywhere. Just an interim solution. Ideally we'd have the thread id / pid of the process/thread running the tests.

@@ +175,5 @@
> +    }
> +
> +    private void logData(String action) {
> +        this.logData(action, new HashMap<String, Object>());
> +    };

Fixed!

Comment 7

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

please add a comment at the top of the file marking this with an MPL license and a link to the structured logging api.

if there are parts of the structured logging that you don't understand (i.e. the skip), please file bugs to update the documentation (or just find the answers and update)

Comment 8

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

Fixed bugs in the previous patch + added StructuredLogger.java to robocop's Makefile.in

By the way, this class will be used for bug 1034267. (I already have an initial patch, just having trouble compiling/executing robocop to test it)

Comment 9

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

Comment on attachment 8453262 [details] [diff] [review]
0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

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

please add a comment linking to the structured logging api documentation.

at the top, add:
http://dxr.mozilla.org/mozilla-central/source/build/mobile/robocop/FennecMochitestAssert.java#5

I assume a new patch with all items outlined here will be addressed if you are to carry forward the r+.

::: build/mobile/robocop/StructuredLogger.java
@@ +24,5 @@
> +    }
> +
> +    static class StandardLoggerCallback implements LoggerCallback {
> +        public void call(String output) {
> +            System.out.println(output);

we don't use system.out.println in robocop, instead we write to a file.  If this is written for posterity, please add a comment here explaining why we have it here and to NOT use it.

@@ +68,5 @@
> +
> +    public void testStatus(String test, String subtest, String status, String expected, String message) {
> +        status = status.toUpperCase();
> +        if (!StructuredLogger.validTestStatus.contains(status)) {
> +            throw new IllegalArgumentException("Unrecognised status: " + status);

s/Unrecognised/Unrecognized/

@@ +93,5 @@
> +
> +    public void testEnd(String test, String status, String expected, String message, Map<String, Object> extra) {
> +        status = status.toUpperCase();
> +        if (!StructuredLogger.validTestEnd.contains(status)) {
> +            throw new IllegalArgumentException("Unrecognised status: " + status);

s/Unrecognised/Unrecognized/

Comment 10

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8453262 [details] [diff] [review]
0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

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

::: build/mobile/robocop/StructuredLogger.java
@@ +12,5 @@
> +
> +public class StructuredLogger {
> +    public static ArrayList<String> validTestStatus = new ArrayList(Arrays.asList("PASS", "FAIL", "TIMEOUT", "NOTRUN", "ASSERT"));
> +    public static ArrayList<String> validTestEnd = new ArrayList(Arrays.asList("PASS", "FAIL", "OK", "ERROR", "TIMEOUT",
> +                                                                               "CRASH", "ASSERT", "SKIP"));

Why not private final? Also would use a set or maybe enum for both here.

@@ +43,5 @@
> +        this(name, null, new StandardLoggerCallback());
> +    }
> +
> +    public void suiteStart(List<String> tests, Map<String, Object> runInfo) {
> +        HashMap<String, Object> data = new HashMap<String, Object>();

I wonder whether we'll have a list of tests and info mapping available to us when we're using this is robocop.

@@ +144,5 @@
> +    }
> +
> +    private void log(String level, String message) {
> +        HashMap<String, Object> data = new HashMap<String, Object>();
> +        data.put("message", message);

Looks like you forgot to put the level in the map.

@@ +160,5 @@
> +            allData.put("component", mComponent);
> +        }
> +
> +        for (Map.Entry<String, Object> entry : data.entrySet())
> +        {

Brace on previous line?

@@ +161,5 @@
> +        }
> +
> +        for (Map.Entry<String, Object> entry : data.entrySet())
> +        {
> +            allData.put(entry.getKey(), entry.getValue());

So the idea is that the incoming data parameter should override everything in allData. As implemeneted I don't think there's ever an overlap in keys, but either way I think there's a version of this that has the same behavior without allocating a new map.

Comment 11

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

carry forward r+ from jmaher

Comment 12

[Ahmed Kachkach [:akachkach]]

Comment on attachment 8453358 [details] [diff] [review]
0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

Didn't see chmanchester's review. Will try to address those points first.

Comment 13

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

carry r+ forward from jmaher

Fixed the issues raised by chmanchester

Comment 14

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8453439 [details] [diff] [review]
0001-Bug-1034236-Java-implementation-of-StructuredLogger-.patch

1.) Is there a Try link handy for this? :)
2.) Please use the checkin-needed bug keyword. It plays more nicely with our bug marking tools. The checkin? flag is more intended for bugs with multiple patches landing at different times.

Comment 15

[Ahmed Kachkach [:akachkach]]

Sorry, forgot to do a try run. Here's one with the updated patch:

https://tbpl.mozilla.org/?tree=Try&rev=2c3e1f85927b

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/fx-team/rev/b578fd863c13

Comment 17

[Ryan VanderMeulen [:RyanVM]]

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