716400 - Use calendar specific logging methods in calendar provider code

Status: NEW

(Calendar :: General, enhancement)

Description

[Stefan Fleiter (:sfleiter)]

All calendar providers use cal.LOG, cal.WARN and cal.ERROR from calUtils.js.
The log messages
- partially contain the protocol
- partially contain the calendar name
- are printed in different formats

The manual addition of context information like name and protocol
makes the code unnecessarily verbose.

The to be attached patch adds the generic calendar logging methods.

Comment 1

[Stefan Fleiter (:sfleiter)]

Attachment: generic calendar logging methods which automatically include calendar name and protocol

Comment 2

[Stefan Fleiter (:sfleiter)]

Still unaddressed log statements of calendar providers:

grep -r -l -c "cal\.\(LOG\|WARN\|ERROR\)" --include=*.js* calendar/providers/ 
calendar/providers/wcap/calWcapCalendarModule.js:1
calendar/providers/gdata/components/calGoogleCalendar.js:37
calendar/providers/gdata/components/calGoogleSession.js:15
calendar/providers/gdata/components/calGoogleUtils.js:6
calendar/providers/gdata/components/calGoogleRequest.js:4
calendar/providers/storage/calStorageHelpers.jsm:1
calendar/providers/storage/calStorageCalendar.js:5
calendar/providers/storage/calStorageUpgrade.jsm:13
calendar/providers/ics/calICSCalendar.js:18

Comment 3

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Comment on attachment 586823 [details] [diff] [review]
generic calendar logging methods which automatically include calendar name and protocol

>+    LOG: function cPB_LOG(aString) {
>+        cal.LOG(this.type + ": " + this.name + ": " + aString);
I'd prefer changing the format to:

("[" + this.type + "-provider] " + this.name + ": " + aString);



You could even go a step further and add a LOGverbose method (here and in calUtils) to allow easily logging messages with calendar.debug.log.verbose. This would also simplify the caldav provider as it has a lot of if(this.verboseLogging()) { cal.LOG(...); } constructs.

Another thing you can look into (but doesn't need to be fixed with this bug) is log4moz. This is a logger framework like log4j that I believe is included in Thunderbird. It has modules and extra prefs per module. The downside is that it might not be included in other supported apps like Seamonkey (and possibly Postbox).

Anyway, r=philipp with the LOGverbose method added.

Comment 4

[Stefan Sitter [:ssitter]]

See Bug 460075 for calendar logging too. I think log4moz is waiting on Toolkit Bug 451283. Thunderbird seems to use it already, see Thunderbird Bug 450631 Comment 2.

Comment 5

[Stefan Fleiter (:sfleiter)]

I am used to the log4*-API and like it, too.
Bug 451283 does not look like it will be fixed anytime soon, though.

For that reason I will continue with this as described in comment 3.

Comment 6

[Stefan Fleiter (:sfleiter)]

With the replacement of the verboseLogging() checks in calendar code even more
strings get concatenated in logging statements only to be thrown away afterwards.
Since most of our users have calendar.debug.log* disabled we are only wasting energy here.

The issue is described here (from a java perspective):
http://www.slf4j.org/faq.html#logging_performance

After a discussion between Philipp and me in IRC it was decided to avoid that.
At first slf4j Syntax with {} as placeholder in the format string
was favored, afterwards %1, %2, ... was found as possible placeholder.
clokep proposed simply joining the log arguments so no format string would be
needed at all.

In the following I try to show practical differences of the approaches
while trying to find out how they can be used for consistent logging while
avoiding unnecessary work in the case where logging is not activated:

Example log statement:
    this.log("itemUri.spec = " + itemUri.spec)
 
Logging calls that would have to be written for that in calendar provider code:
%1: this.log("itemUri.spec = %1", itemUri.spec)
{}: this.log("itemUri.spec = {}", itemUri.spec)
 ,: this.log("itemUri.spec = ", itemUri.spec)

The final log statements have to be prefixed by the equivalent of "[$type-provider] $name: "
and sent to the real logging method which should decide whether to log before creating the final log string.
Resulting log statements would be:

%1: this.log("[ %1-provider] %2: itemUri.spec = %3", this.type, this.name, itemUri.spec)
{}: this.log("[ {}-provider] {}: itemUri.spec = {}", this.type, this.name, itemUri.spec)
 ,: this.log("[ ", this.type, "-provider] ", this.name, ": ", "itemUri.spec = ", itemUri.spec)

The following modifications would be needed to the written log statement
to prefix the generic calendar information:

%1: format string has not only to be prefixed, but even the insertion markers have to be changed(!), 
    calendar specific arguments have to be inserted at start of log parameters
{}: format string and log parameters have to be prefixed
 ,: only arguments have to be prefixed, this could be done in calUtils.js after it was decided logging should be done

For that reason I would propose to go with simply joining log parts by ,.

If there are no objections I will work on this as time permits.

Comment 7

[Martin Schröder [:mschroeder]]

Stefan, any progress update?

Comment 8

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Now there is a cool new thing: template strings. I hope/assume they are performance optimized so that the expression is only evaluated when the string is displayed.

https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/template_strings

Comment 9

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

I never really liked the LOG("foo", thingy, "bar") format, but do accept that the current method is fairly slow. I asked in #jsapi and template strings are not helpful because as with normal strings the expressions are evaluated immediately.

I did however check if its faster to use closures:

http://jsperf.com/string-concat-vs-closure

It looks like this format is 11% slower with logging enabled, but at least 30% faster with logging disabled:

LOG(() => "I have " + myobj.expensiveGetter + " hopes"))

Stefan, if you are still around, interested into picking up work on this bug again?

Comment 10

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

We could even do this incrementally by changing the LOG methods to accept a function as the first parameter and in that case execute it, but if its something else then just log it normally. This way we don't have to fix everything at once.