Too verbose debug log file:: What can we do about it?

108 views
Skip to first unread message

ISHIKAWA,chiaki

unread,
Apr 22, 2022, 3:22:40 AM4/22/22
to Thunderbird Developers, dev-platform
(I set reply-to to thunderbird developers list, but this is relevant to
dev-platform, too.)

I develop local patches for TB locally under Debign GNU/Linux.

I need to check the sanity of patches when they are applied to Windows
and MacOS version.
For that I trust tryserver to run the tests for these binaries.

A few years ago, it was possible to look at the log of debug version
to see what went wrong with my patches on systems I did not have on
tryserver. It was not easy, mind you, but not impossible.
By "what went wrong", I mean I could see a test failed and not only
that could focus on the cause of the failure with additional debug
logging using the existing warning/error messages as clue.

Unfortunately, for the last 12+ months, the debug log got way too
verbose for me to cull essential information from the log.
And this has hampered my attempt to merge my patches against the
latest C-C tree (M-C tree) and get the tests going.
I simply cannot easily spot where my patches screws up internal
processing easily.

Cause of too verbose message problems:

The problems of too verbose log files I see are caused by many
factors, but my taken on the state of affairs is as follows.

Item 1. C++/C sources suffer from the lack of a proper INFORMATIONAL
logging.

Those of you who are familiar with syslog/rsyslog logging know the
LEVEL of messages: this is related to the notion of urgency or
priority of messages to be logged.
We can specify a level and only log the messages with that priority
and above.

Problem with C++/C macros is that most of the macros for debugging
purposes lack the notion of INFORMATIONAL messages. The macros are
about something went wrong, so abort with messages.: NS_ABORT, NS_ASSERTION,
MOZ_ASSERT, etc.
something went wrong, so print an error message, but go on.
something seems fishy, so print a warning message, and go on.:
NS_WARNING, etc.

There are legitimate cases where the developers would like to know if
certain situation arises or not or how frequently they occur, but
currently the developers simply use NS_WARNING type macros and so we
have so many warnings which may not be WARNING at all, and actually
only INFORMATIONAL.
This adds to the messages that are actually of information nature, but
printed as warnings.

Item 2. I raised a few issues regarding the verbose warnings lately when
I found
the current state of verbose debug log file is getting out of hands
even for someone who has waded through it for the last several years or
more.

https://bugzilla.mozilla.org/show_bug.cgi?id=1695139

(actually many more in the past.)

It seems that the particular messages turn out to be of no concern to
mere mortals
So they could actually be turned into INFORMATIONAL category as noted
in Item 1.
Also, my take on the issue is that not many people look at the debug
log on tryserver. I have tough time to search for other people
submitting debug build and test on tryserver.
( I suspect only when the patch breaks, people use it?
A comprehensive patch set of mine to introduce buffered output to TB
(e.g. Bug 1242042 )
is rather sweeping changes that have known to break Windows versions in
the past, and MacOS version once. So I need to run debug build often.
Most of the time I run tests locally under linux before submitting
tryserver jobs.
Occasionally I have to make sure Windows and MacOS version at least run! )

ITEM 3. FYI, JS scripts at least have a notion of a crude level.
error, warn, debug, log for console messages and prefix them
with console.error, console.warn, console.debug, console.log.
I think this is in the right direction.
I would add console.info as logical next step.

Well, what I want to see to improve the state of affairs concerning
debug log is this:

Suggestion (a) I would suggest that we implement INFORMATIONAL logging
macros for
C++/C, that prefix the message with "INFO:".
This helps us to weed out INFORMATIONAL messages from the debug log to focus
on essential warnings and errors.


Suggestion (b) Filtering of log files

With macros for informational messages, we can institute a filtering
of debug log files by eliminating a few offending verbose messages and
informational messages to home in on the essential errors and
warnings.

We leave the original debug log file intact and provide it, of course,
but tryserver should
produce the filtered sanitized version that is easy for ordinary
developers to inspect.

Yes, (b) can be implemented locally by each developer to satisfy their
tastes for the local debug test runs, BUT I believe tryserver ought to
create a debug log file that would be meaningful for someone who sees
it for the first time.
(Well, I may be the only person in the world who regularly checks the
content of debug log file at least locally. Ugh...)

I am not sure what should the filtering be like. I would like to know
input from those in the know.

My initial consideration which I would implement locally first is,
- INFORMATIONAL messages be removed from the sanitized
version. (Remember the original debug log file will be provided, too.)

- Too many verbose messages should be considered first as candidate of
filtering and announced when the filtering rule changes.
"Too many" is rather subjective, let's call it more than 1000 times.
There ARE messages that appear more than 1000 times, mind you during
the whole test run.

These steps should clean up the cluttered debug log files hopefully.

At least, filtering of messages should motivate those responsible for
the code that creates the messages to either modify the message to
INFORMATIONAL category if they are not WARNING/ERROR category.
Or look at the nature of the issues in more detail.

I am hoping that there are people with similar sentiment regarding
debug log files.

Of course, warnings ARE important.
For example, I spotted a missed case handling lately due to a warning I
had not seen before.
https://bugzilla.mozilla.org/show_bug.cgi?id=1762161

The problem with today's debug log is that "noise" is burying essential
messages.  :-(

Chiaki


PS: FYI, these are the most frequent warnings and errors from a run on
April 5th.
(That are recorded by an old script I have been using.
I am adding some more rules to extract different warnings/errors each
month, and so WEBRENDER warnings and some
which I mentioned above are not in this list.

Unfortunately, I have found out that the RAW local debug log file and
tryserver debug log files have different format. So, I cannot use the
filtering shell script to analyze the tyrserver log file easily.
I have been analyzing the local debug log file reasonably
well. Without automated summary, I cannot really do anything with
debug log file very well.

The numbers are crude indicators.
There are tests that are not executed due to the early failures, or
outright crashes, etc.

10 top most warnings coming from /libeditor/ during local mochitest
run of debug version of TB.
(TB has to create messages and editing is done actually to underlying HTML
document, BTW.)

   ========================================
   Firstly, warnings under /libeditor/
   ========================================

4982: Main Thread] WARNING:
HTMLEditor::GetAbsolutelyPositionedSelectionContainer() reached <html>
element: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLAbsPositionEditor.cpp:95
525: Main Thread] WARNING: mozInlineSpellChecker::Cleanup() failed, but
ignored: 'NS_SUCCEEDED(rvIgnored)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:609
396: Main Thread] WARNING: '!aNode', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:3268
48: Main Thread] WARNING: Perhaps, <br> element position has been moved
to different point by mutation observer: 'currentPoint ==
pointToInsert', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLEditSubActionHandler.cpp:1252
41: Main Thread] WARNING: '!mSelection', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:6052
40: Main Thread] WARNING: '!editableContent', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLEditUtils.h:764
15: Main Thread] WARNING:
TopLevelEditSubActionData::AddRangeToChangedRange() failed:
'NS_SUCCEEDED(rv)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:6412
15: Main Thread] WARNING:
TopLevelEditSubActionData::AddNodeToChangedRange() failed, but ignored:
'NS_SUCCEEDED(rvIgnored)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:6541
15: Main Thread] WARNING: HTMLEditor::DeleteNodeWithTransaction()
failed: 'NS_SUCCEEDED(rv)', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLEditSubActionHandler.cpp:963

10 most frequent warnings outside /libeditor/
(They are all above 1000 times threshold incidently.)

    ========================================
    Other than /libeditor/
    ========================================

2947: Main Thread] WARNING: Scrolled rect smaller than scrollport?: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/generic/nsGfxScrollFrame.cpp:7154
2164: Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/base/nsGlobalWindowOuter.cpp:4147
2074: Main Thread] WARNING: Failed to retarget HTML data delivery to the
parser thread.: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/parser/html/nsHtml5StreamParser.cpp:1198
1659: Main Thread] WARNING: XPCOM object nsStringBuffer released from
static ctor/dtor: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsTraceRefcnt.cpp:206
1564: Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_DoneGC'
discarded: actor cannot send: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/ProtocolUtils.cpp:504
1563: Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_StartedGC'
discarded: actor cannot send: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/ipc/glue/ProtocolUtils.cpp:504
1402: Main Thread] WARNING: '!inner', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/ipc/jsactor/JSWindowActorProtocol.cpp:184
1168: Compositor] WARNING: Possibly dropping task posted to updater
thread: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/gfx/layers/apz/src/APZUpdater.cpp:365
1076: Main Thread] WARNING:
'!ClientIsValidPrincipalInfo(mClientInfo.PrincipalInfo())', file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/clients/manager/ClientSource.cpp:183
1011: Main Thread] WARNING: no request to cancel: file
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgProtocol.cpp:763

[end of memo]


Klaus Bartosch

unread,
Apr 22, 2022, 3:53:48 AM4/22/22
to dev-pl...@mozilla.org, ishi...@yk.rim.or.jp
On 22 Apr 2022 09:22, ISHIKAWA,chiaki wrote:
> Unfortunately, for the last 12+ months, the debug log got way too verbose

I can wholeheartedly agree with that. We run Thunderbird in a debug build for development and the amount of console output is a real concern, especially from the Editor, as far as output from Mozilla platform code is concerned. I think it's fair to say that the Thunderbird compose window doesn't use the Mozilla editor in a way that wasn't intended, so most of the output is unexpected. There is also a lot of debug coming out of DOM. Chiaki already compiled a good overview.

KB.

Emilio Cobos Álvarez

unread,
Apr 22, 2022, 6:53:34 AM4/22/22
to Thunderbird Developers, dev-platform


On 4/22/22 09:22, ISHIKAWA,chiaki wrote:
> Problem with C++/C macros is that most of the macros for debugging
> purposes lack the notion of INFORMATIONAL messages. The macros are
> about something went wrong, so abort with messages.: NS_ABORT,
> NS_ASSERTION,
> MOZ_ASSERT, etc.
> something went wrong, so print an error message, but go on.
> something seems fishy, so print a warning message, and go on.:
> NS_WARNING, etc.

So this is only about debug asserts / warnings / NS_ENSURE_* macros,
right? Because MOZ_LOG does support a variety of log levels:


https://searchfox.org/mozilla-central/rev/6da1ebe13b260efabd88eb98dec5fa8ee65987b2/xpcom/base/Logging.h#62-69

Anyways, I agree that warnings that happen all the time should probably
not be warnings. I'd recommend just filing bug and ni?ing the relevant
developer if you're seeing super-spammy warnings in test logs.

I think Eric Rahm had a tool that used to keep track of this? Not sure
if somebody is maintaining / running that anymore, see:

https://bugzilla.mozilla.org/show_bug.cgi?id=765224

[..]

> Yes, (b) can be implemented locally by each developer to satisfy their
> tastes for the local debug test runs, BUT I believe tryserver ought to
> create a debug log file that would be meaningful for someone who sees
> it for the first time.
> (Well, I may be the only person in the world who regularly checks the
> content of debug log file at least locally. Ugh...)

Not really. I check them very often at least. Using rr it's very easy to
basically replay the run, save the log to a file, and go to the point of
the program where the warning / message / test failure you care about
happens.

[..]

> 10 top most warnings coming from /libeditor/ during local mochitest
> run of debug version of TB.

I suspect Thunderbird uses the editor much more heavily than Firefox, so
these aren't generally problems for most Gecko developers. If they're
causing trouble on Thunderbird, chances are you should look into those,
some of those look like potentially real bugs. Some others seem like
they can expectedly happen in some edge cases so maybe NS_WARNING isn't
quite warranted and that should be a MOZ_LOG or just be silent.

> 2947: Main Thread] WARNING: Scrolled rect smaller than scrollport?: file
> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/generic/nsGfxScrollFrame.cpp:7154

This one I just sent a patch to remove.

> 2164: Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file
> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/base/nsGlobalWindowOuter.cpp:4147

I see this on local Firefox startup too, and it's harmless:

https://bugzilla.mozilla.org/show_bug.cgi?id=1765961

> 1659: Main Thread] WARNING: XPCOM object nsStringBuffer released from
> static ctor/dtor: file
> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsTraceRefcnt.cpp:206

This one is probably something in Thunderbird having an `static
nsString` or so, should be fixed rather than the warning being suppressed.

> '!ClientIsValidPrincipalInfo(mClientInfo.PrincipalInfo())', file
> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/clients/manager/ClientSource.cpp:183

This one seems like it should be investigated in comm-central. Seems
like it might be expected for some URIs? If it's harmless probably can
be turned into a log message.

> 1011: Main Thread] WARNING: no request to cancel: file
> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgProtocol.cpp:763

This one seems TB specific as well.

Cheers,

-- Emilio

ISHIKAWA,chiaki

unread,
Apr 22, 2022, 7:54:28 PM4/22/22
to Thunderbird Developers, dev-platform, Emilio Cobos Álvarez
Thank you for the comment.

On 2022/04/22 19:53, Emilio Cobos Álvarez wrote:
>
>
> On 4/22/22 09:22, ISHIKAWA,chiaki wrote:
>> Problem with C++/C macros is that most of the macros for debugging
>> purposes lack the notion of INFORMATIONAL messages. The macros are
>> about something went wrong, so abort with messages.: NS_ABORT,
>> NS_ASSERTION,
>> MOZ_ASSERT, etc.
>> something went wrong, so print an error message, but go on.
>> something seems fishy, so print a warning message, and go on.:
>> NS_WARNING, etc.
>
> So this is only about debug asserts / warnings / NS_ENSURE_* macros,
> right? Because MOZ_LOG does support a variety of log levels:
>
>
> https://searchfox.org/mozilla-central/rev/6da1ebe13b260efabd88eb98dec5fa8ee65987b2/xpcom/base/Logging.h#62-69
>
>
Yes and no.

Yes, MOZ_LOG is a nice way to capture information from already
well-thought out processing.
However, can we use that on tryserver?

My point is that during development lots of macros are used by
programmers to leave a clue as to what could have possibly go wrong or
to obtain INFO-like data to guide the optimization.
For that purpose, we need to introduce macro for INFO.


> Anyways, I agree that warnings that happen all the time should
> probably not be warnings. I'd recommend just filing bug and ni?ing the
> relevant developer if you're seeing super-spammy warnings in test logs.
>
> I think Eric Rahm had a tool that used to keep track of this? Not sure
> if somebody is maintaining / running that anymore, see:
>
>   https://bugzilla.mozilla.org/show_bug.cgi?id=765224


Interesting I already argued for macros for gathering INFO-like
information SEVEN (7) years ago in the bugzilla.
( My comment is https://bugzilla.mozilla.org/show_bug.cgi?id=765224#c6 )

We have not progressed much. :-(

>
> [..]
>
>> Yes, (b) can be implemented locally by each developer to satisfy their
>> tastes for the local debug test runs, BUT I believe tryserver ought to
>> create a debug log file that would be meaningful for someone who sees
>> it for the first time.
>> (Well, I may be the only person in the world who regularly checks the
>> content of debug log file at least locally. Ugh...)
>
> Not really. I check them very often at least. Using rr it's very easy
> to basically replay the run, save the log to a file, and go to the
> point of the program where the warning / message / test failure you
> care about happens.

Hmm... Interesting. I have not used rr for TB testing before myself.
I wonder if rr tool is relevant for TB.

>
> [..]
>
>> 10 top most warnings coming from /libeditor/ during local mochitest
>> run of debug version of TB.
>
> I suspect Thunderbird uses the editor much more heavily than Firefox,
> so these aren't generally problems for most Gecko developers. If
> they're causing trouble on Thunderbird, chances are you should look
> into those, some of those look like potentially real bugs. Some others
> seem like they can expectedly happen in some edge cases so maybe
> NS_WARNING isn't quite warranted and that should be a MOZ_LOG or just
> be silent.
>
I was under the impression that somebody would take care of the editor
mess. :-)

I mean I was explicitly told to stay away from these since they are in
M-C code. But I digress.

>> 2947: Main Thread] WARNING: Scrolled rect smaller than scrollport?:
>> file
>> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/generic/nsGfxScrollFrame.cpp:7154
>
> This one I just sent a patch to remove.

Great to heart that. So this is not really a warning for a real problem. (?)

>
>> 2164: Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file
>> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/base/nsGlobalWindowOuter.cpp:4147
>
> I see this on local Firefox startup too, and it's harmless:
>
>   https://bugzilla.mozilla.org/show_bug.cgi?id=1765961
I see.

Then this one is something I will remove by a local filtering tool somehow.


>
>> 1659: Main Thread] WARNING: XPCOM object nsStringBuffer released from
>> static ctor/dtor: file
>> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsTraceRefcnt.cpp:206
>
> This one is probably something in Thunderbird having an `static
> nsString` or so, should be fixed rather than the warning being
> suppressed.
>
These warnings have been here for a long time.
Problem is that one of the file caching code in TB has a bug and it
triggers a crash randomly depending on the order of releases of ojbects
during final GC run just before the final exit.
When the crash happens, these ctor/dtor warnings are not printed because
TB has already crashed.
I have a patch to take care of the issue of this random crash and thus
see these ctor/dtor warnings all the time locally all the time.
Maybe others do not see these often (?)

The bug I have mentioned is
https://bugzilla.mozilla.org/show_bug.cgi?id=1677202
heap-use-after-free with C-C TB during shutdown,
nsMsgDBService::~nsMsgDBService()

The patch I posted averts the crash with educated guess of what data
left in the cash should be ignored because it is quite likely a bogus
pointer to an object already released.

>
>> '!ClientIsValidPrincipalInfo(mClientInfo.PrincipalInfo())', file
>> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/clients/manager/ClientSource.cpp:183
>
> This one seems like it should be investigated in comm-central. Seems
> like it might be expected for some URIs? If it's harmless probably can
> be turned into a log message.

Actually, when FF introduces Principal, etc. for coping with security
issues several years ago, TB developers were more or less at a loss what
it means for TB message streams, etc. since TB as far as I understand
does not grok javascript in HTML messages.
So probably Principal, etc. may not mean anything in TB.
But you are right, someone has to dig in deep to figure out what is
going on...


>
>> 1011: Main Thread] WARNING: no request to cancel: file
>> /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/base/src/nsMsgProtocol.cpp:763
>
> This one seems TB specific as well.

OK.

>
> Cheers,
>
>  -- Emilio
>

Thank you very much for your comments, Emilio.

I will remove a few types of messages locally by filtering to see if
I can come up with an easier to deal with debug log file.

Also, your comments may prompt TB developers who are familiar with code
that produced the frequent messages to take a look.
Or maybe I am too optimistic.

Chiaki

ISHIKAWA,chiaki

unread,
Apr 22, 2022, 8:14:24 PM4/22/22
to Thunderbird Developers, dev-platform
Oh well, maybe this is a good opportunity to hear if anyone has an idea
whether the following warnings can be safely ignored, too.
Or to be more precise, if they can be removed from the code.

My script to summarize warnings/errors from log file could not be
updated soon enough since there have been so many new warnings, etc.
over the last few months and the following warnings (rather frequent,
note 5k+ warnings at the top) were not in the previous summary.

The issue is reported in
https://bugzilla.mozilla.org/show_bug.cgi?id=1691761#c3
And it seems to be safely ignored. If so, I would appreciate if someone
can create a patch to remove them.

I think my extraction routine was created on the fly and was not tested
extensively yet, so I see some strange
duplication (but strange count) with 'WARN' marker in the message. But
you get the idea.

grep webrender log1402-mochitest-13.txt | grep -v gfx.webrender.all |
cut -d " " -f 5- | sort | uniq -c | sort -n -k 1 -r

   5425  webrender::renderer] asking to enable_gpu_markers but no
supporting extension was found
   1171  webrender::device::gl] Missing optimized shader source for
gpu_cache_update
    948  webrender::device::gl] Cropping texture upload Box2D((0, 0),
(0, 1)) to None
    367 WARN  webrender::renderer] asking to enable_gpu_markers but no
supporting extension was found
    162 WARN  webrender::device::gl] Cropping texture upload Box2D((0,
0), (0, 1)) to None
    107 WARN  webrender::device::gl] Missing optimized shader source
for gpu_cache_update
    106  webrender::device::gl] Attribute VertexAttribute { name:
"aUvRect2", count: 4, kind: F32 } is not found in the shader composite.
Expected at 7, found at -1
  [... omission ...]

TIA

Chiaki
> ------------------------------------------
> Thunderbird: Thunderbird Developers
> Permalink:
> https://thunderbird.topicbox.com/groups/developers/T320cf15a65f506c9-M5a099c6f56632d70bc1761bc
> Delivery options:
> https://thunderbird.topicbox.com/groups/developers/subscription
>

Gabriele Svelto

unread,
Apr 23, 2022, 5:25:08 PM4/23/22
to ISHIKAWA,chiaki, Thunderbird Developers, dev-platform, Emilio Cobos Álvarez
On 4/23/22 01:54, ISHIKAWA,chiaki wrote:
> Yes, MOZ_LOG is a nice way to capture information from already
> well-thought out processing.
> However, can we use that on tryserver?

Yes, you can do things like:

./mach try fuzzy --env MOZ_LOG="ObserverService:5"

Then pick the tasks you want to run and you'll get the same log messages
as you'd get locally.

That being said I think that the default amount of logspam that Gecko
spits out is excessive and I'd be very happy if more of it was put
behind MOZ_LOG so that it could only be enabled when it matters.

Gabriele
OpenPGP_signature

ISHIKAWA,chiaki

unread,
Apr 24, 2022, 10:23:42 PM4/24/22
to Thunderbird Developers, dev-platform
Thank you for the comment.

On 2022/04/24 6:25, Gabriele Svelto wrote:
> On 4/23/22 01:54, ISHIKAWA,chiaki wrote:
>> Yes, MOZ_LOG is a nice way to capture information from already
>> well-thought out processing.
>> However, can we use that on tryserver?
> Yes, you can do things like:
>
> ./mach try fuzzy --env MOZ_LOG="ObserverService:5"
>
> Then pick the tasks you want to run and you'll get the same log messages
> as you'd get locally.

This is very nice to hear.

Except:

Has anyone been able to use the above syntax to submit a C-C TB
build/test job to tryserver?

Many years ago, it did not work well and thus, since others reported
similar issues, I have been using the following for submitting a job to
tryserver. Maybe it does work now?

    hg push -f ssh://hg.mozilla.org/try-comm-central

Now, I have read the local script to create a tryserver job and realized
that maybe that was because MQ extension of HG was recommended and I
used it back then (not sure. I am not an expert of tyserver mechanism.)
Actually, I am still using it locally although it is NOT recommended
anymore. Switching fundamental tool usage pattern
is a burden for an occasional patch submitter. :-(

> That being said I think that the default amount of logspam that Gecko
> spits out is excessive and I'd be very happy if more of it was put
> behind MOZ_LOG so that it could only be enabled when it matters.
>
That would be great.

However, I am afraid that it does not happen overnight.
The sheer amount of NS_WARNING, etc. for debugging purposes during
development is
very large, and clutter up the debug log.

To think about the organization of data used by MOZ_LOG() takes a bit of
time obviously.
I surmise that use of other macros to print warnings and strange
conditions during initial development phase is much, much easier.
(We may even not know exactly the final neat output should be during
early development.)
So, from this angle,  I still push the creation of the development
macros for INFORMATIONAL message.
After the development of a feature, etc. settles down, the developers
might want to convert them to MOZ_LOG if they wish.
I wonder how many developers want to do that, though.
Also, MOZ_LOG usage may not sit well for the desire to detect very
strange situations (should not happen case, etc. But I may be wrong here.)

My original post is to mark INFORMATIONAL output as such and reduce what
is not essential.
To my delight, already some patches have been created to reduce clutter.
Obviously some messages are no longer thought to be useful after the
initial development process and the code has matured.

> Gabriele

Thank you for the information again.


Chiaki


Masayuki Nakano

unread,
Apr 26, 2022, 4:39:57 AM4/26/22
to Emilio Cobos Álvarez, Thunderbird Developers, dev-platform
On 22/04/22 19:53, Emilio Cobos Álvarez wrote:
> On 4/22/22 09:22, ISHIKAWA,chiaki wrote:
>> 10 top most warnings coming from /libeditor/ during local mochitest
>> run of debug version of TB.
>
> I suspect Thunderbird uses the editor much more heavily than Firefox,
> so these aren't generally problems for most Gecko developers. If
> they're causing trouble on Thunderbird, chances are you should look
> into those, some of those look like potentially real bugs.
>
Almost all of the warnings under `editor/libeditor` are unexpected
cases. So, I'd be happy you to file bugs for each set of the warnings.
Note that one failure causes multiple warnings to print the stack
because a lot of methods in editor is called by various callers and
various conditions.

It might be nicer to replace them with MOZ_LOG, but there are too many
warnings and they need to be replaced once. So it's hard to do it
without breaking my local patches...

ISHIKAWA,chiaki

unread,
May 26, 2022, 3:35:17 AM5/26/22
to dev-pl...@mozilla.org
Hi, Masayuki san
I did not realize almost all these warnings are from "UNEXPECTED CASES".
That is bad (!), indeed.

I am going to submit bug reports then later one by one to figure out
what causes these.

(Well, actually, as I compose a message using a DEBUG version of C-C TB
so without knowing it, I must have
encountered unexpected cases.)

For now, I have filed
https://bugzilla.mozilla.org/show_bug.cgi?id=1771270
C-C TB many warnings of the form, XPCOM object XXYYZ destroyed from
static ctor/dtor
This one seems to clutter up the ending part of each test and
may hinder people from analyzing OTHER shutdown-related problems. (I
have experienced segmentation errors during shutdown before.)

Will come back to editor problems hopefully in a month or two.


Chiaki


Masayuki Nakano

unread,
May 26, 2022, 10:28:38 PM5/26/22
to Thunderbird Developers, dev-platform
On 22/04/22 16:22, ISHIKAWA,chiaki wrote:
10 top most warnings coming from /libeditor/ during local mochitest
run of debug version of TB.
(TB has to create messages and editing is done actually to underlying HTML
document, BTW.)

   ========================================
   Firstly, warnings under /libeditor/
   ========================================

4982: Main Thread] WARNING: HTMLEditor::GetAbsolutelyPositionedSelectionContainer() reached <html> element: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLAbsPositionEditor.cpp:95
525: Main Thread] WARNING: mozInlineSpellChecker::Cleanup() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:609
396: Main Thread] WARNING: '!aNode', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:3268
48: Main Thread] WARNING: Perhaps, <br> element position has been moved to different point by mutation observer: 'currentPoint == pointToInsert', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLEditSubActionHandler.cpp:1252
41: Main Thread] WARNING: '!mSelection', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:6052
40: Main Thread] WARNING: '!editableContent', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLEditUtils.h:764
15: Main Thread] WARNING: TopLevelEditSubActionData::AddRangeToChangedRange() failed: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:6412
15: Main Thread] WARNING: TopLevelEditSubActionData::AddNodeToChangedRange() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/EditorBase.cpp:6541
15: Main Thread] WARNING: HTMLEditor::DeleteNodeWithTransaction() failed: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/editor/libeditor/HTMLEditSubActionHandler.cpp:963

Hi, I investigated (and already fixed) some warnings related to editing. As far as I've investigated, all of the investigated ones detected bugs. So, just silence the warnings is not good. At least file a bug for individual warning.

-- 
Masayuki Nakano <masa...@d-toybox.com>
Working on DOM, Events, editor and IME handling for Gecko

ISHIKAWA,chiaki

unread,
May 28, 2022, 8:33:27 PM5/28/22
to dev-pl...@mozilla.org
Thank yo very much.

I thought I sent out an e-mail stating that I would be working on
filings the warnings coming from files in /editor/ directory in a next
month or so after cleaning up my patches that I have been working on the
last few weeks..
(But I could not find the e-mail. Hmm.)

I will study your bugzillas and I will file missed situations, if any.

Thank you again!

Chiaki
> * Bug 1766764 - WARNING: Failed to remove transaction listener from
> the editor: 'removedTransactionListener', file
> /builds/worker/checkouts/gecko/editor/composer/nsEditingSession.cpp:448
> <https://bugzilla.mozilla.org/show_bug.cgi?id=1766764>
> * Bug 1766956 - WARNING:
> nsRange::CompareBoundaryPoints(Range_Binding::START_TO_START)
> failed: file
> /builds/worker/checkouts/gecko/editor/libeditor/SelectionState.cpp:141
> <https://bugzilla.mozilla.org/show_bug.cgi?id=1766956>
> * Bug 1767386 - WARNING: '!document', file
> /builds/worker/checkouts/gecko/editor/libeditor/CSSEditUtils.cpp:562
> <https://bugzilla.mozilla.org/show_bug.cgi?id=1767386>
> * Bug 1767558 - WARNING: '!mLastFocusedWindow', file
> /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp:3253
> <https://bugzilla.mozilla.org/show_bug.cgi?id=1767558>
> * Bug 1726297 - `ContentEventHandler` shouldn't try to get text
> frame from white-space only text nodes
> <https://bugzilla.mozilla.org/show_bug.cgi?id=1726297>
> * Bug 1726298 - `ContentEventHandler` should guess caret rect from
> parent frames when there is no text
> <https://bugzilla.mozilla.org/show_bug.cgi?id=1726298>
>
> --
> Masayuki Nakano <masa...@d-toybox.com>
> Working on DOM, Events, editor and IME handling for Gecko
>
> --
> 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/565efa95-b4ee-2e86-c8a7-ae3161f39eb9%40d-toybox.com
> <https://groups.google.com/a/mozilla.org/d/msgid/dev-platform/565efa95-b4ee-2e86-c8a7-ae3161f39eb9%40d-toybox.com?utm_medium=email&utm_source=footer>.


ISHIKAWA,chiaki

unread,
Jun 1, 2022, 11:05:26 AM6/1/22
to Thunderbird Developers, dev-platform, Gabriele Svelto
On 2022/04/24 6:25, Gabriele Svelto wrote:
> ./mach try fuzzy --env MOZ_LOG="ObserverService:5"
>
> Then pick the tasks you want to run and you'll get the same log messages
> as you'd get locally.

Hi,

Per your suggestion, I am trying to see if I can pass environment
variables to task cluster job.
(If indeed I can pass environment variables, I may put some of my debug
messages behind MOZ_LOG after a while. Maybe not immediately.)

Unfortunately, something is wrong.
Either my terminal emulator is too dumb (I am using a terminal emulator
under linux), or
this |fuzzy||'s task selection feature does not work with C-C submission
(?).
I didn't get to choose tasks to run when I tried the following command
in mozilla/comm subdirectory.

        ../do-make-tb.sh  try fuzzy --env MOZ_LOG="ObserverService:5"

In my setup, |../d-make-tb.sh| essentially invokes mozilla/mach command
after
setting up various environmental variables for my local build and test.
So it is a simple wrapper for |mach| command.
So it boils down to

      mozilla/make try fuzzy --env MOZ_LOG="ObserverService:5"

as was suggested in the original post.

I used to invoke the following command directly to submit try jobs.

       hg push -f ssh://hg.mozilla.org/try-comm-central

after adding a local patch that contains

        try: -b do -p all -u all -t none

Maybe |fuzzy| does not work as intended for C-C and I am better off with
|auto| subcommand?
In hindsight, maybe |mach try fuzzy ...| realized the existence of a
patch that contained "try: -b do -p all -u all -t none" and felt it did
not need to offer the job selection at all and proceed. How clever if
that was the case, but too clever for me :-(

I wonder what command syntax other TB  developers use for job submission.
|fuzzy|, |auto|, or whatever subcommand when they use |mach try ...| syntax?

In any case, the reason I was advised to use the arcane syntax for job
submission some years ago was that
I was using MQ extension of HG [ and still do. :-( ]
At the time it was pointed out the newer syntax may not work nicely with MQ.
I wish I recorded the time/date of the message.
But in my local script for task submission, I have the following comment
which I believe I copied and pasted from an announcement I saw in one of
the mozilla mailing list or newsgroup.

    # The aforementioned tools may not play all that nicely with
mercurial queues. If you use mq, you can still push to try manually.
First build your try syntax with the TryChooser web page. Then run:
    # $ hg qref --message "try: <your-computed-syntax-here>"
    # $ hg push -f try

Aha, I simply used Google search and realize the above is today in
https://wiki.allizom.org/ReleaseEngineering/TryServer

I used the above new syntax hoping to choose tasks as |mach try fuzzy
--help| suggested.
But it did not seem to ask me anything about job selection and just
submitted a job.
A surprise.

In my previous framework which I used up until half a day ago, I
submitted a task that contained
only the limited number of local patches (local MQ patches) which I
specify from local patch queue.
However, the newer syntax |mach try ...| certainly does not seem to play
nicely with MQ.
Either I  I have messed up local tree or it did not work as intended.

This time around ALL the local MQ patches were included in the submitted
job.
See the task cluster job.
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=dc9069bb62160b2fbd4a56376d16d4853c930f16

I only wanted to submit a task that contained the single change (
https://hg.mozilla.org/try-comm-central/rev/2d50d18e5995f9435c010208a285158076d7ebb0
) for testing purposes,  and as a matter of fact,
I had not intended to submit the job AT ALL.
I thought |fuzzy| would allow me a chance to exit without submitting for
real.
I would have experimented with task selection and if necessary exit it
with ^C once such fuzzy job selection screen showed up.
It did not.

From the progress in the said task, I think the local tree is in a
mysterious state, proper patches are not applied or something.
I may have to re-create the source and re-start. It is not a big deal.
Due to a couple of hardware malfunctions, I had to it twice this year.

Anyway, I would love to hear what is the preferred |mach try ...|
subcommand for C-C submission.

Also, does anyone still use MQ and have  this |mach try ...| command
work? If so, I would like to hear how.
I suspect a heavy editing of job submission scripts is in order in that
case.

TIA

Chiaki


ISHIKAWA,chiaki

unread,
Jun 2, 2022, 2:36:41 AM6/2/22
to dev-pl...@mozilla.org
I experimented a bit.
(It seems that the source tree was more or less OK. The compilation
error seemed to
be a temporal mismatch of M-C and C-C local trees?
In any case, I refreshed my local source tree and re-installed my patches.)

Is it possible that I can use the output of the following command (Note
|--no-push |)

    |mach command path|  try auto --env ENV1=test1 --env ENV2=test2
--no-push

and append to my local patch and then submit the job using the old syntax
   hg push -f ssh://hg.mozilla.org/try-comm-central
and get the desired behavior as far as the environment variables are
concerned?
(I thought I have seen a few such job submissions with JSON job
specification in try-comm-central in the past and was wondering how the
test and build targets were chosen in such job submissions.)

e.g. (Note that the env variables are specified in it.)
The above --no-push command produces in the standard output the
following JSON data.

{
    "parameters": {
        "optimize_strategies":
"gecko_taskgraph.optimize:tryselect.bugbug_reduced_manifests_config_selection_medium",
        "optimize_target_tasks": true,
        "target_tasks_method": "try_auto",
        "test_manifest_loader": "bugbug",
        "try_mode": "try_auto",
        "try_task_config": {
            "env": {
                "ENV1": "test1",   <---- Here.
                "ENV2": "test2"
            }
        }
    },
    "version": 2
}

TIA

Chiaki
Reply all
Reply to author
Forward
0 new messages