Mozlog should be able to consume and output structured messages

RESOLVED FIXED

Status

defect
RESOLVED FIXED
6 years ago
6 years ago

People

(Reporter: chmanchester, Assigned: chmanchester)

Tracking

(Blocks 1 bug)

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 5 obsolete attachments)

Mozlog should be able to emit structured messages. Existing python harnesses (particularly mochitest) emit log messages relevant to test runs which we will want to consume in the same format as output generated from test assertions in Javascript.
Assignee

Updated

6 years ago
Blocks: 886570
This is a basic implementation of structured output from mozlog. The ouptut format here is based on the format implemented in bug 884397 (following the convention of underscore prefixing built in metadata). That format is not final, and therefore neither is this.
Attachment #769018 - Flags: feedback?(ahalberstadt)
Assignee

Updated

6 years ago
Attachment #769018 - Attachment is patch: true
Attachment #769018 - Attachment mime type: text/x-patch → text/plain
Comment on attachment 769018 [details] [diff] [review]
Implement structured output in mozlog.

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

Looks like a good start! Just a couple comments.

::: mozlog/mozlog/logger.py
@@ +62,5 @@
>          self.log(CRASH, message, *args, **kwargs)
>  
> +    def logStructured(self, message, params={}):
> +        """Logs a structured message object."""
> +        level = params.get("_level", INFO)

Change INFO to _default_level

@@ +79,5 @@
> +        self._counter = 0
> +
> +    def format(self, record):
> +        params = getattr(record, 'params')
> +        params["_id"] = self._counter

Is this going to interfere with the JS logger id's? Are they going to the same file?

@@ +82,5 @@
> +        params = getattr(record, 'params')
> +        params["_id"] = self._counter
> +        params["_time"] = int(round(record.created, 0))
> +        self._counter += 1
> +        return json.dumps(params)

Might be nice to allow users to pass in dumps' "indent" parameter in case they want to see a pretty printed version of the params.
Attachment #769018 - Flags: feedback?(ahalberstadt) → feedback+
As discussed today, mozlog should be able consume messages via a socket in order to log events from Javascript and Python to the same file, and to achieve consistency for IDs and timestamps.
Summary: Mozlog should be able to output structured messages → Mozlog should be able to consume and output structured messages
Do we really want to do that?  This will introduce a new requirement for mobile testing that the device and the runner are on the same network.  Although this is already a requirement for mochitests and reftests, it is not currently a requirement for xpcshell tests or Marionette tests, and there are some cases for which we probably do not want this as a requirement (e.g., Marionette tests).

What about the idea of simply merging two separate files using synchronized timestamps?
The difficulty pointed out with merging separate files was that we are relying on consistency between timestamps generated from separate sources (python and javascript), which may not be reliable in general. The idea was to have one message source send messages directly to the other, and have the receiver generate all message timestamps/ids.

I didn't take the mobile case into account when thinking about this - this may require a different approach.
Another option is to tail -f a logfile created by the JS bits; this might work similarly to how we scan stdout for output at present.
I expect this will ultimately need to support a variety of message sources, but this is an initial implementation of a "log adapter" that consumes messages from a socket and feeds them through an existing logger, overwriting prior message metadata.
Attachment #769018 - Attachment is obsolete: true
Attachment #770565 - Flags: feedback?(ahalberstadt)
Comment on attachment 770565 [details] [diff] [review]
Implement structured output and message consumer in mozlog.

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

Seems like a good start.

::: mozlog/mozlog/loglistener.py
@@ +27,5 @@
> +            self._semaphore = threading.Semaphore(0)
> +
> +        self._socket = socket.socket()
> +        self._socket.bind((self._host, self._port))
> +        self._partialMessage = ''

nit: underscore instead of camelCase

@@ +33,5 @@
> +        self._thread = threading.Thread(target=self.receive_messages)
> +        self._thread.start()
> +
> +    def receive_messages(self):
> +        """Continually listens for log messages"""

I'm going to bet we'll want an optional timeout here. Probably easiest to use http://docs.python.org/2/library/socket.html#socket.socket.settimeout in the constructor.

@@ +46,5 @@
> +    def process_message(self, data):
> +        """Processes data from a connected log source. Messages are assumed
> +        to be newline delimeted, and generally well-formed JSON."""
> +        for part in data.split('\n'):
> +            msgString = self._partialMessage + part

underscore

@@ +52,5 @@
> +                msg = json.loads(msgString)
> +                self._partialMessage = ''
> +                self._logger.logStructured(msg.get('action', 'UNKNOWN'), msg)
> +                if self._debug:
> +                    self._semaphore.release()

If this is being accessed by consumers it shouldn't have an _ prefix. Though I think doing the release() here and making the consumers of mozlog responsible for acquire() is a bad idea. We should either make them responsible for everything, or make it completely transparent. Also, how come this is only if debug is True?
Attachment #770565 - Flags: feedback?(ahalberstadt) → feedback+
This version makes use of a callback rather than a semaphore to deal with message receipt, and SocketServer instead of raw sockets to avoid hard coding ports.
Attachment #770565 - Attachment is obsolete: true
Attachment #772131 - Flags: review?(ahalberstadt)
Comment on attachment 772131 [details] [diff] [review]
Implement structured output and message consumer in mozlog.

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

Looks good, thanks for implementing the callback method! I'm going to r- for now because I don't know whether we should worry about improving the API at this point or not (as per comment below). If we decide not to worry about it yet I'll change to an r+ when the nits are addressed.

general nit: I know we're using a mixture of camel case and underscores in mozlog, which isn't great.. But I think all new variable names should conform to the PEP 8 standard (http://www.python.org/dev/peps/pep-0008/#naming-conventions) i.e underscores for variables and functions, camel case for classes.

::: mozlog/tests/test_logger.py
@@ +1,5 @@
> +# This Source Code Form is subject to the terms of the Mozilla Public
> +# License, v. 2.0. If a copy of the MPL was not distributed with this file,
> +# You can obtain one at http://mozilla.org/MPL/2.0/.
> +
> +from mozlog import *

nit: import * is a pet peeve of mine, it trips up syntax checkers and makes it harder to follow code paths

@@ +28,5 @@
> +
> +        # Prevents tests from producing output via a default handler.
> +        for h in self.logger.handlers:
> +            self.logger.removeHandler(h)
> +        self.logger.addHandler(self.handler)

I think this code demonstrates that the mozlog API is way too inflexible. This has nothing to do with your patch, but I think we'll need to fix it up a bit. Then again doing so will likely break backwards compatibility, so maybe we should just not worry about it for now..

@@ +142,5 @@
> +
> +        # Sleeps prevent folding all into single send, so listener is forced
> +        # to reconstruct partial messages.
> +        sock.sendall(messageString[:8])
> +        time.sleep(.01)

Is there anyway to avoid using sleeps? I don't really understand the comment.
Attachment #772131 - Flags: review?(ahalberstadt) → review-
This patch addresses comments and includes small fix to the way levels are specified in structured messages. Let's discuss about API improvements and decide if we should make any here or spin off a general Mozlog improvements bug.
Attachment #772131 - Attachment is obsolete: true
Comment on attachment 772416 [details] [diff] [review]
Implement structured output and message consumer in mozlog.

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

Looks good, thanks. One thing I missed from previous review, you should add the mozlog manifest to the root manifest: https://github.com/mozilla/mozbase/blob/master/test-manifest.ini

Is this bug blocking other work you're doing? If so then maybe we should just land this as it shouldn't cause any problems. Otherwise if changing the API around is something you're interested in, we can certainly look into it now.
Attachment #772416 - Flags: review+
Assignee

Updated

6 years ago
See Also: → 891488
This version adds manifest to master manifest, and omits the counter and associated id field as discussed on irc.
Attachment #772416 - Attachment is obsolete: true
Carrying forward r+. This is a whitespace-only change from the previous version.
Assignee: nobody → cmanchester
Attachment #772834 - Attachment is obsolete: true
Attachment #774319 - Flags: review+
https://github.com/mozilla/mozbase/commit/2a13b845fc277a66f22f60d5f5f0f91066ca8fd8
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.