Closed Bug 1095026 Opened 6 years ago Closed 6 years ago

Use mozlog.structured logging instead of raw print in mozregression

Categories

(Testing :: mozregression, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: parkouss, Assigned: parkouss)

References

Details

Attachments

(1 file, 2 obsolete files)

Mozregression currently do raw print statements, but it will be a good enhancement to use mozlog.structured instead.

The main goal is to hide the subprocesses output by default (for example output them with the debug level, hidden by default).

It will also allow to control output automatically from the command line once argparse will be used instead of optparse, see http://mozbase.readthedocs.org/en/latest/mozlog_structured.html#integration-with-argparse.
See also Bug 1095032.
Depends on: 1095891
Hey,

There is the patch that uses mozlog instead of print statements.

Well I hope I used mozlog well, it's hard to find information about mozlog other than mozlog.structured. I looked at the mozversion code base to find the mozlog.getLogger call and how it is integrated with argparse.

With this patch the output is like this:

mozregression --good 2014-11-09 --bad 2014-11-10
mozregression INFO | Got as far as we can go bisecting nightlies...
mozregression INFO | Ensuring we have enough metadata to get a pushlog...
mozregression INFO | Getting http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/11/2014-11-09-03-02-05-mozilla-central/firefox-36.0a1.en-US.linux-x86_64.txt
mozregression INFO | Getting http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/11/2014-11-10-03-02-04-mozilla-central/firefox-36.0a1.en-US.linux-x86_64.txt
mozregression INFO | Last good revision: d380166816dd (2014-11-09)
mozregression INFO | First bad revision: d380166816dd (2014-11-10)
...

For me it's OK but maybe it will be better to have a less verbose output - we can adapt the formatter in this case.

Also, I was hopping that we could set the debug level from the command line, but I don't see how. Did I missed something, or maybe it will be added later in mozlog ?


$ mozregression -h
usage: 
 mozregression [OPTIONS] [[--bad BAD_DATE]|[--bad-release BAD_RELEASE]] [[--good GOOD_DATE]|[--good-release GOOD_RELEASE]]
 mozregression [OPTIONS] --inbound --bad-rev BAD_REV --good-rev GOOD_REV

optional arguments:
...

Output Logging:
  Each option represents a possible logging format and takes a filename to
  write that format to, or '-' to write to stdout.

  --log-unittest LOG_UNITTEST
                        Unittest style output
  --log-raw LOG_RAW     Raw structured log messages
  --log-html LOG_HTML   HTML report
  --log-tbpl LOG_TBPL   TBPL style log format
  --log-xunit LOG_XUNIT
                        xUnit compatible XML
  --log-mach LOG_MACH   Human-readable output
  --log-mach-verbose    Enables verbose mode for the given formatter.
  --log-mach-level LOG_MACH_LEVEL
                        A least log level to subscribe to for the given
                        formatter (debug, info, error, etc.)
  --log-tbpl-level LOG_TBPL_LEVEL
                        A least log level to subscribe to for the given
                        formatter (debug, info, error, etc.)
Assignee: nobody → j.parkouss
Status: NEW → ASSIGNED
Attachment #8521503 - Flags: review?(wlachance)
Comment on attachment 8521503 [details] [review]
Use mozlog instead of raw print statements

Good start but there are some places where you're still using the old logging API and some usage could be better. Unfortunately the example code we provide for structured logging hasn't fully kept up with API changes, filed bug 1097901 to partially address that. I'd also like to see us fix bug 1014760 to reduce confusion.
Attachment #8521503 - Flags: review?(wlachance) → review-
Thanks, I will work on it.

I added some comments on github. Something bother me with this api: get_default_logger returns None when there is no logger defined previously with set_default_logger.

I think that's the reason why in mozversion we still use the old api too: http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozversion/mozversion/mozversion.py#32.

As the set_default_logger call is usually made in main, if someone use some code as a library (ie import the module, call a function without calling main) this will result in a crash because all loggers wil be None.

Don't you think it should provide a default logger, or at least raise an appropriate exception to indicate that mozlogging must be setup before use ?
(In reply to Julien Pagès from comment #4)

> As the set_default_logger call is usually made in main, if someone use some
> code as a library (ie import the module, call a function without calling
> main) this will result in a crash because all loggers wil be None.

So as I found out from jgraham last night, apparently calling setup_logging will actually call set_default_logger for you:

http://mozbase.readthedocs.org/en/latest/mozlog_structured.html#mozlog.structured.commandline.setup_logging

I missed that originally... updated the docs in bug 1097901 so that hopefully someone else won't have the same misinterpretation.
 
> Don't you think it should provide a default logger, or at least raise an
> appropriate exception to indicate that mozlogging must be setup before use ?

Yes, I think it's a problem that the rest of mozbase is still using this API that is basically deprecated. Filed bug 1098592 to hopefully resolve the issue.
Well I have updated the pull request.

Output looks great with the mach formatter, and command line handling is fine, for example:

mozregression --good 2014-11-09 --bad 2014-11-11 --log-mach-level DEBUG

simply enable debug output.

I am still not convinced with some parts of mozlog api:

 - It is not easily possible to use a global, package-level logger. We now have multiple lines like "self._logger = get_default_logger('mozregression')" (one for each class that need logging) and it seems strange to me as we manipulate the same thing even if there is multiple variables. But I suppose it is a design decision; and maybe I'm just reluctant to embrace reform here. :)
 - logger.info (and warn, debug, etc) calls do not take arguments like the standard python logger. I found it useful and readable to write "log.info('this is %s on %s', arg, arg2)" instead of "log.info('this is %s on %s' % (arg, arg2))"
 - The way StructuredLogger is implemented is a bit magical: there is no methods like 'info', 'debug' directly in the class. This makes "interface checking" tools like pylint throw wrong errors like "E: 47, 8: Instance of 'StructuredLogger' has no 'info' member (no-member)"

Well about the patch, I hope this times it's better!
Attachment #8521503 - Attachment is obsolete: true
Attachment #8523405 - Flags: feedback?(wlachance)
Comment on attachment 8523405 [details] [review]
Use mozlog instead of raw print statements

Looks good, some minor comments in the PR. Also, I get this traceback when I get to the point of bisecting inbound, probably easily fixed:

Traceback (most recent call last):
  File "/home/wlach/src/mozregression/bin/mozregression", line 9, in <module>
    load_entry_point('mozregression==0.25', 'console_scripts', 'mozregression')()
  File "/home/wlach/src/mozregression/mozregression/regression.py", line 448, in cli
    app()
  File "/home/wlach/src/mozregression/mozregression/regression.py", line 446, in <lambda>
    get_date(options.bad_date))
  File "/home/wlach/src/mozregression/mozregression/regression.py", line 255, in bisect_nightlies
    self.bisect_nightlies(good_date, mid_date)
  File "/home/wlach/src/mozregression/mozregression/regression.py", line 255, in bisect_nightlies
    self.bisect_nightlies(good_date, mid_date)
  File "/home/wlach/src/mozregression/mozregression/regression.py", line 219, in bisect_nightlies
    self.bisect_inbound()
  File "/home/wlach/src/mozregression/mozregression/regression.py", line 149, in bisect_inbound
    self.inbound_runner.start(inbound_revisions[mid]['timestamp'])
  File "/home/wlach/src/mozregression/mozregression/runnightly.py", line 331, in start
    if not self.install(date):
  File "/home/wlach/src/mozregression/mozregression/runnightly.py", line 324, in install
    if not self.app.download(date=date):
  File "/home/wlach/src/mozregression/mozregression/runnightly.py", line 117, in download
    self._logger.info("Using local file: %s" % dest)
AttributeError: 'FirefoxInbound' object has no attribute '_logger'
Attachment #8523405 - Flags: feedback?(wlachance) → feedback+
(In reply to William Lachance (:wlach) from comment #7)
> Comment on attachment 8523405 [details] [review]
> Use mozlog instead of raw print statements
> 
> Looks good, some minor comments in the PR. Also, I get this traceback when I
> get to the point of bisecting inbound, probably easily fixed:
> ...

Thanks for that!

I missed it because we do not call __init__ when inheriting from some classes in mozregression. I may open a bug to refactor this a bit, to make things simpler.
Attachment #8523405 - Attachment is obsolete: true
Attachment #8524320 - Flags: review?(wlachance)
Comment on attachment 8524320 [details] [review]
Use mozlog instead of raw print statements

This works great, thanks! Sorry for the review delay. The one thing missing was making the mozlog requirement explicit in setup.py. Added that in a followup.
Attachment #8524320 - Flags: review?(wlachance) → review+
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Depends on: 1105837
You need to log in before you can comment on or make changes to this bug.