Chris Manchester (limited bugmail, email directly) Assignee
	Description • 11 years ago

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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 1 • 11 years ago

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.

	Andrew Halberstadt [:ahal]
	Comment 2 • 11 years ago

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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 3 • 11 years ago

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.

	Jonathan Griffin (:jgriffin)
	Comment 4 • 11 years ago

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?

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 5 • 11 years ago

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.

	Jonathan Griffin (:jgriffin)
	Comment 6 • 11 years ago

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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 7 • 11 years ago

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.

	Andrew Halberstadt [:ahal]
	Comment 8 • 11 years ago

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?

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 9 • 11 years ago

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.

	Andrew Halberstadt [:ahal]
	Comment 10 • 11 years ago

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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 11 • 11 years ago

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.

	Andrew Halberstadt [:ahal]
	Comment 12 • 11 years ago

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.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 13 • 11 years ago

This version adds manifest to master manifest, and omits the counter and associated id field as discussed on irc.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 14 • 11 years ago

Carrying forward r+. This is a whitespace-only change from the previous version.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 15 • 11 years ago

https://github.com/mozilla/mozbase/commit/2a13b845fc277a66f22f60d5f5f0f91066ca8fd8