Filled leading two digits timestamp without leading space wanted for test suite log recording

[ISHIKAWA,chiaki]

Hi,

I am running TB test suite (mochitest) locally and have an issue at the
format of the timestamp of the log lines.
I am not sure when the time stamp became this way.
(I don't think I had this issue several years ago. Something must have
changed a year or so ago? Maybe around the time, mochitest replaced
mozmill test.)

Can we modify the test suite run script so that the timestamp prepended
to the log line
always has a filled two digits leading number, 0-filled if necessary,
WITHOUT leading space character?

Currently: the log lines when the leading number of the timestamp is one
digit, they
look like the following. Note the space character at the beginning of
the line. This causes a problem for simple-minded log summarizer.

 0:23.46 INFO runtests.py | Waiting for browser...
 0:49.50 GECKO(735766) #01: NS_DebugBreak
(/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsDebugImpl.cpp:497)
 0:49.50 GECKO(735766) #02: nsWindow::SetZIndex(int)
(/NEW-SSD/NREF-COMM-CENTRAL/mozilla/widget/gtk/nsWindow.cpp:2470)
 0:49.50 GECKO(735766) #03: UpdateNativeWidgetZIndexes(nsView*, int)
(/NEW-SSD/NREF-COMM-CENTRAL/mozilla/view/nsView.cpp:505)

I would like it to be: Note there is no leading space character.

00:23.46 INFO runtests.py | Waiting for browser...
00:49.50 GECKO(735766) #01: NS_DebugBreak
(/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsDebugImpl.cpp:497)
00:49.50 GECKO(735766) #02: nsWindow::SetZIndex(int)
(/NEW-SSD/NREF-COMM-CENTRAL/mozilla/widget/gtk/nsWindow.cpp:2470)
00:49.50 GECKO(735766) #03: UpdateNativeWidgetZIndexes(nsView*, int)
(/NEW-SSD/NREF-COMM-CENTRAL/mozilla/view/nsView.cpp:505)

This formatting would make it much easier for me to create a script to
pick up interesting lines and calculate
the counts from the log.

Currently a simple command as follows fails to produce a uniq count for
interesting lines.

grep ASSERTION log1439-mochitest.txt | cut --delimiter=" " -f 6- | \
    sort | uniq -c | sort -n -k 1 -r

E.g.  Split summary

This is from a real log of TB mochitest.

    947 Thread] ###!!! ASSERTION: Overwriting an existing document
channel!: '(loadFlags & nsIChannel::LOAD_REPLACE) ||
!(mDocumentRequest.get())', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsDocLoader.cpp:467
    359 Thread] ###!!! ASSERTION: Expected Mozilla child widget:
'!mContainer', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/widget/gtk/nsWindow.cpp:2434
    321 Thread] ###!!! ASSERTION:
GetMsgDatabase(getter_AddRefs(database)) returned failure.:
'NS_SUCCEEDED(rv)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgDBFolder.cpp:4724
    321 Thread] ###!!! ASSERTION: GetMessageHeader(msgKey, _retval)
returned failure: 'NS_SUCCEEDED(rv)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp:621
    174 Main Thread] ###!!! ASSERTION:
GetMsgDatabase(getter_AddRefs(database)) returned failure.:
'NS_SUCCEEDED(rv)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgDBFolder.cpp:4724
    174 Main Thread] ###!!! ASSERTION: GetMessageHeader(msgKey,
_retval) returned failure: 'NS_SUCCEEDED(rv)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp:621
     97 Main Thread] ###!!! ASSERTION: Expected Mozilla child widget:
'!mContainer', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/widget/gtk/nsWindow.cpp:2434

     ...

Note that the second and the seventh lines above are for the same
ASSERTION lines recorded at different times, but leading space character
at the beginning of the lines early in the log causes the early lines
counted separately.
Ditto for the third and the fifth lines, and the fourth and sixth lines.
(BTW, by counting the numbers it becomes obvious that the errors
recorded for GetMsgDatbase and GetMessageHeader are closely related.)

The counting discrepancy occurs because in later part of the log, the
leading number of the timestamp has two digits and there is no leading
space. This subtle difference fools a simple couting script.

E.g.

54:14.53 GECKO(769167) [Parent 769167, Main Thread] ###!!! ASSERTION:
GetMessageHeader(msgKey, _retval) returned failure: 'NS_SUCCEEDED(rv)',
file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/local/src/nsMailboxService.cpp:621

Still later, it becomes three digits and there is no space character.

100:00.82 INFO *** Start BrowserChrome Test Results ***
100:00.83 INFO checking window state

It should be a simple fix.
Someone in the know can point at the problematic output code and maybe I
can proceed from there.

TIA

Chiaki

[Jonathan Kew]

Try changing %2d to %02d in the format_seconds function at
https://searchfox.org/mozilla-central/rev/9902932742fcdce2c956eeb81fd38350f5394ab2/testing/mozbase/mozlog/mozlog/formatters/machformatter.py#37-40

Hope this helps,

JK

[Andrew Halberstadt]

Seems like a reasonable change and looks like Jonathan's suggestion should work.

Though if parsing logs you almost certainly want to use the raw structured logs. You can generate these by passing in, e.g `--log-raw <path/to/file>`. This will generate a JSON lines file where each line is a JSON object corresponding to the log line in question. We also upload these files as artifacts in CI for Gecko, e.g:

https://firefoxci.taskcluster-artifacts.net/ROMlTaU1SbauELCGueCH9w/0/public/test_info/mochitest-devtools-chrome_raw.log

You can see the expected format here:
https://firefox-source-docs.mozilla.org/mozbase/mozlog.html#data-format

Hope that helps!

Andrew

--
You received this message because you are subscribed to the Google Groups "dev-pl...@mozilla.org" group.
To unsubscribe from this group and stop receiving emails from it, send an email to dev-platform...@mozilla.org.
To view this discussion on the web visit https://groups.google.com/a/mozilla.org/d/msgid/dev-platform/677b1d6c-d177-0339-fa2e-9de642188d17%40gmail.com.

[ISHIKAWA,chiaki]

Dear Jonathan and Andrew,

This should help.

I did not realize we can produce JSON log files LOCALLY.
It might be worthwhile to investigate if I can use them for local
debugging. (Problem. of course, is that
I add unstructured dump messages to stderr on the fly during
C++ code debugging. I am not sure how they will picked up by the JSON
summarizer.)

Jonathan's one patch should go a long way for my immediate need temporarily.

Thank you again. I am glad I asked. :-))

Chiaki

> <mailto:dev-platform%2Bunsu...@mozilla.org>.