Ed Morley [:emorley] Reporter
	Description • 11 years ago

Stupid logger prefix :-/

(In reply to Phil Ringnalda (:philor) from bug 917817 comment #7)
> At least in the case of mochitests, that made the log line "16:49:56    
> INFO -  Mochitest ERROR | TEST-UNEXPECTED-FAIL | runtests.py | Timed out
> while waiting for server startup.
> " as in
> 
> Starting annotatedsummary log generation
> * Search term: "TEST-UNEXPECTED-FAIL"
>   Removing cached bug suggestions
>   BzAPI query: 1092ms
>   Bugs returned: 464

	Ed Morley [:emorley] Reporter
	Comment 1 • 11 years ago

The problem is mozlog's separator. We should use something else.

https://github.com/mozilla/mozbase/blob/master/mozlog/mozlog/logger.py#L139

    def format(self, record):
        record.message = record.getMessage()

        # Handles padding so record levels align nicely
        if len(record.levelname) > self.level_length:
            pad = 0
            if len(record.levelname) <= self.max_level_length:
                self.level_length = len(record.levelname)
        else:
            pad = self.level_length - len(record.levelname) + 1
        sep = '|'.rjust(pad)
        fmt = '%(name)s %(levelname)s ' + sep + ' %(message)s'
        return fmt % record.__dict__

	Ed Morley [:emorley] Reporter
	Comment 2 • 11 years ago

Bah, ok, so third time lucky.

mozlog has a testFail log level, which we can use to prefix the TEST-UNEXPECTED-FAIL correctly. We should just fix mochitest/runtests.py to use that.

To make things more confusing, the mochitest/runtests.py log.* calls use mozlog, whereas automation.py (and thus b2gautomation.py & runreftest.py) & runxpcshelltests.py use the Python logger directly, and only the former adds the prefix.

	Ed Morley [:emorley] Reporter
	Comment 3 • 11 years ago

(In reply to Ed Morley [:edmorley UTC+1] from comment #2)
> To make things more confusing, the mochitest/runtests.py log.* calls use
> mozlog, whereas automation.py (and thus b2gautomation.py & runreftest.py) &
> runxpcshelltests.py use the Python logger directly, and only the former adds
> the prefix.

So in the latter things like:
log.error("TEST-UNEXPECTED-FAIL | foo | bar")
...are not only correct, but necessary; unlike with mozlog.

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

(In reply to Ed Morley [:edmorley UTC+1] from comment #3)
> (In reply to Ed Morley [:edmorley UTC+1] from comment #2)
> > To make things more confusing, the mochitest/runtests.py log.* calls use
> > mozlog, whereas automation.py (and thus b2gautomation.py & runreftest.py) &
> > runxpcshelltests.py use the Python logger directly, and only the former adds
> > the prefix.
> 
> So in the latter things like:
> log.error("TEST-UNEXPECTED-FAIL | foo | bar")
> ...are not only correct, but necessary; unlike with mozlog.

Jeff is currently working on getting reftests off of automation.py. I think very soon, there will be nothing using it anymore and mozlog will be the de-facto standard. Also, I don't think runxpcshelltests use automation.py, though I could be mistaken.

	Ed Morley [:emorley] Reporter
	Comment 5 • 11 years ago

Using log.testFail() gets us the correct prefix:
https://github.com/mozilla/mozbase/blob/master/mozlog/mozlog/logger.py#L52

	Ed Morley [:emorley] Reporter
	Comment 6 • 11 years ago

(In reply to Andrew Halberstadt [:ahal] from comment #4)
> Also, I don't think runxpcshelltests use automation.py,
> though I could be mistaken.

It doesn't use mozlog either sadly:
http://mxr.mozilla.org/mozilla-central/source/testing/xpcshell/runxpcshelltests.py#34

	Joel Maher ( :jmaher ) (UTC -8)
	Comment 7 • 11 years ago

android unittests will continue to use automation.py (or some renamed version of it)

	Joel Maher ( :jmaher ) (UTC -8)
	Comment 8 • 11 years ago

Comment on attachment 811161 [details] [diff] [review]
Patch v1

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

While this looks good, I suspect this will have problems with android automation.  As this is error formatting for tbpl parsers, I am more than happy to r+.  Please test on try server and ensure that android has access to log.testFail

	Ed Morley [:emorley] Reporter
	Comment 9 • 11 years ago

With an added log.testFail() that will trigger on every run, for testing:
https://tbpl.mozilla.org/?tree=Try&rev=dc693ea9d743

Will look into this later, though print is looking pretty appealing at this point...

	Ed Morley [:emorley] Reporter
	Comment 10 • 11 years ago

The current code imports mozlog but doesn't actually use it for the logger object 'log', this revised version fixes that.

New try run;
remote:   https://tbpl.mozilla.org/?tree=Try&rev=4aa3129d4ea2

Will save re-review until that's green.

	Ed Morley [:emorley] Reporter
	Comment 11 • 11 years ago

Sigh, trying again, broke the last patch when rebasing:
remote:   https://tbpl.mozilla.org/?tree=Try&rev=c61055220596

	Chris Manchester (limited bugmail, email directly)
	Comment 12 • 10 years ago

Pretty sure structured logging (bug 886570) fixed this (the tbplformatter doesn't do any prefixing for the "log" action).

	Ed Morley [:emorley] Reporter
	Comment 14 • 10 years ago

(In reply to Chris Manchester [:chmanchester] from comment #12)
> Pretty sure structured logging (bug 886570) fixed this (the tbplformatter
> doesn't do any prefixing for the "log" action).

Good spot, thank you :-)