Closed Bug 1047277 Opened 5 years ago Closed 5 years ago

Improve HAL's components logging story

Categories

(Core :: Hardware Abstraction Layer (HAL), defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla35

People

(Reporter: gsvelto, Assigned: gsvelto)

References

Details

Attachments

(1 file, 3 obsolete files)

+++ This bug was initially created as a clone of Bug #1045524 +++

Currently the various HAL components use a mix of the following functions to report warnings, errors and other messages:

- __android_log_print() via various macros (LOG(), LOGE(), LOGW(), OOM_LOG())

- g_printerr() in code using glib functionality

- printf_stderr() here and there

- NS_WARNING() and NS_ERROR() likewise

Those should be replaced by the existing HAL_LOG() macro (as well as HAL_ERR() for errors we care about in production builds, see bug 1045524). HAL_LOG() itself is being used with double-parentheses around its parameters possibly as a workaround for missing or broken __VA_ARGS__ support, that should also be changed since we're already using __VA_ARGS__ throughout the rest of the codebase.

There's also some Mac-specific logging code but that is present in files we've imported from an external project so there's no need to touch it.
Quick work in progress that uses HAL_LOG() and HAL_ERR() for anything. Before completing it however I still need to tackle a few things:

- I'd like to remove the logging functions from hal/Hal.h because that's a public header and there's no point in having them there.

- I'd also like to preserve the existing prefixes that were used in __android_log_write() invocations.

- I'm unsure what to do with OOM_LOG(), I know we're often using it to figure out what went wrong when a process was reaped by the LMK but there's likely better ways to do it. Still it's probably useful to preserve its output in the logcat by default because people are relying on it.

- Finally I want to verify how hard it is to redirect PR_LOG()'s output to the logcat.
Yeah - OOM_LOG is specifically for grabbing log messages from the kernel's dmesg log and putting them into logcat.

It's gonk specific.

If we were to disable it, the logical place would be at the end of the EnsureKernelLowMemKillerParamsSet function (where it's constructed).

But I think that it's important, since there is no other indication of a process being killed via LMK that shows up in logcat.
So this is the more-or-less complete patch. To summarize what I did:

- I've split the logging macros out of Hal.h and moved them into the private HalLog.h header file

- The macros are now using __VA_ARGS__ so I've removed the double-parentheses from everywhere

- I've replaced all other custom logging functions with HAL_LOG() and HAL_ERR() except for OOM_LOG() since it serves an important purpose and must be in logcat

I'll be shooting an e-mail to dev-platform soon to ask for feedback as to whether this should follow the standard behavior of having logging completely disabled in non-debug builds or if we should enable it at least in engineering (userdebug?) builds.
Assignee: nobody → gsvelto
Attachment #8466107 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #8467126 - Flags: feedback?(dhylands)
The previous patch was missing the new hal/HalLog.h file, it's fixed in this one.
Attachment #8467126 - Attachment is obsolete: true
Attachment #8467126 - Flags: feedback?(dhylands)
Attachment #8467775 - Flags: feedback?(dhylands)
Comment on attachment 8467775 [details] [diff] [review]
[PATCH v2] Hide HAL's logging macros from the public headers and convert all components to use them

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

Overall this looks fine to me.

If all of the compilers that are used support __VA_ARGS__ then it seems reasonable to switch, and that's the only real concern I have.

::: hal/HalWakeLock.cpp
@@ +136,5 @@
>    }
>  
>    nsCOMPtr<nsIPropertyBag2> props = do_QueryInterface(aSubject);
>    if (!props) {
> +    HAL_LOG("ipc:content-shutdown message without property bag as subject");

This was an NS_WARNING, so it would probably be good to keep the "warningness" of it and create a HAL_WARN or HAL_WARNING.

::: hal/gonk/GonkSwitch.cpp
@@ +107,5 @@
>      ScopedClose autoClose(fd);
>      char state[16];
>      ssize_t bytesRead = read(fd, state, sizeof(state));
>      if (bytesRead < 0) {
> +      HAL_LOG("Read data from %s fails", statePath.get());

This feels like an error

::: hal/linux/UPowerClient.cpp
@@ +186,5 @@
>    GError* error = nullptr;
>    mDBusConnection = dbus_g_bus_get(DBUS_BUS_SYSTEM, &error);
>  
>    if (!mDBusConnection) {
> +    HAL_LOG("Failed to open connection to bus: %s\n", error->message);

What does g_printerr do?
This seems to impact linux builds as well, so we may want to do both gprinterr and HAL_LOG?
Attachment #8467775 - Flags: feedback?(dhylands) → feedback+
Thanks for the feedback Dave, and sorry for the late action but I've been stuck with gaia blockers in the meantime :-/

(In reply to Dave Hylands [:dhylands] from comment #5)
> If all of the compilers that are used support __VA_ARGS__ then it seems
> reasonable to switch, and that's the only real concern I have.

Try builds seem green across all architectures so we should be safe.

> This was an NS_WARNING, so it would probably be good to keep the
> "warningness" of it and create a HAL_WARN or HAL_WARNING.

I've looked a little bit into it and it turns out that NS_WARNING not only prints stuff out (via PR_LOG()) but can also suspend the process, trap to trigger the debugger or even abort depending on the configuration. So on second thought I've left all the NS_WARNING()/NS_ERROR() calls untouched.

> ::: hal/gonk/GonkSwitch.cpp
> @@ +107,5 @@
> >      ScopedClose autoClose(fd);
> >      char state[16];
> >      ssize_t bytesRead = read(fd, state, sizeof(state));
> >      if (bytesRead < 0) {
> > +      HAL_LOG("Read data from %s fails", statePath.get());
> 
> This feels like an error

Fixed.

> ::: hal/linux/UPowerClient.cpp
> @@ +186,5 @@
> >    GError* error = nullptr;
> >    mDBusConnection = dbus_g_bus_get(DBUS_BUS_SYSTEM, &error);
> >  
> >    if (!mDBusConnection) {
> > +    HAL_LOG("Failed to open connection to bus: %s\n", error->message);
> 
> What does g_printerr do?
> This seems to impact linux builds as well, so we may want to do both
> gprinterr and HAL_LOG?

It just prints to stderr via glib by default, I think we can safely remove those calls:

https://developer.gnome.org/glib/unstable/glib-Warnings-and-Assertions.html#g-printerr
Attachment #8467775 - Attachment is obsolete: true
Attachment #8494497 - Flags: review?(dhylands)
Comment on attachment 8494497 [details] [diff] [review]
[PATCH v3] Hide HAL's logging macros from the public headers and convert all components to use them

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

Just thought I'd mention that NS_WARNING and NS_ERROR are no-ops in non-debug builds.
Attachment #8494497 - Flags: review?(dhylands) → review+
Thanks for the review, the try run is here: https://tbpl.mozilla.org/?tree=Try&rev=fc1a64491ccf
https://hg.mozilla.org/mozilla-central/rev/932a92a16c29
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla35
Flags: qe-verify-
You need to log in before you can comment on or make changes to this bug.