Closed Bug 1667962 Opened 4 years ago Closed 3 years ago

comm/calendar/test/unit/test_bug485571.js: InternalError: too much recursion" {file:"resource:///modules/calendar/Ical.jsm" line: 5788 (or 5596)}]

Categories

(Calendar :: General, defect)

Product:
Calendar
Component:
General
Platform:
x86_64
Linux
Type:
defect

Tracking

(thunderbird_esr91 wontfix)

Status:
RESOLVED FIXED
Milestone:
95 Branch
Tracking Flags:
Tracking Status
thunderbird_esr91 --- wontfix

People

(Reporter: ishikawa, Assigned: darktrojan)

References

Details

Attachments

(1 file)

Bug 1667962 - Avoid comparing calendar objects in a way that causes them to be printed to a log. r=mkmelin
48 bytes, text/x-phabricator-request
Details | Review

During local xpcshell-test run with FULL DEBUG version of TB, I noticed the following errors.
(I run tests under Debian GNU/linux, but I suspect the bug appears on all the platform.)

These error were not visible in June. So they are relatively new.
(I have not had a chance to test xpcshell test for a while due to some issues
related to runtime error caused by OS version string issue which has
been fixed lately.)

These errors are only visible when you add --verbose flag to |mach xpcshell-test| command because the error is SILENTLY IGNORED BY XPCSHELL-TEST HARNESS and IS NOT REPORTED to unsuspecting tryserver submitters. (and better still with --sequential so that the test results won't get mixed with parallel execution of subtests.)

There were a few tests that triggered the error and the line number
seems to be different.

The errors are reported in the following tests:

egrep "(TEST_START|TEST_END|Leaving test|Entering test|Ical.jsm.*Internal)" /FF-NEW/log1252-xpctest.txt
 0:00.53 TEST_START: xpcshell-icaljs.ini:comm/calendar/test/unit/test_alarm.js
 0:06.98 pid:783895 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 0:12.79 pid:783895 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 0:13.69 TEST_END: Test PASS. Subtests passed 90/90. Unexpected 0
 ...
 0:25.49 TEST_START: xpcshell-icaljs.ini:comm/calendar/test/unit/test_alarmutils.js
 0:31.69 pid:783944 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 0:37.29 pid:783944 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 0:47.14 TEST_END: Test PASS. Subtests passed 69/69. Unexpected 0
...
 0:54.47 TEST_START: xpcshell-icaljs.ini:comm/calendar/test/unit/test_bug485571.js
 1:00.59 pid:784168 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 1:00.98 TEST_END: Test PASS. Subtests passed 21/21. Unexpected 0
...
 1:15.09 TEST_START: xpcshell-icaljs.ini:comm/calendar/test/unit/test_caldav_requests.js
 1:31.13 pid:784338 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 1:37.09 pid:784338 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 1:41.69 TEST_END: Test PASS. Subtests passed 122/122. Unexpected 0
...

line 5788 case:

 1:37.12 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5788}]
setTimeAttr@resource:///modules/calendar/Ical.jsm:5788:1
fromData@resource:///modules/calendar/Ical.jsm:5016:13
icaltime@resource:///modules/calendar/Ical.jsm:4878:10
clone@resource:///modules/calendar/Ical.jsm:4928:14
startOfWeek@resource:///modules/calendar/Ical.jsm:5104:25
get startOfWeek@resource:///components/calDateTime.js:164:45
getMessage@resource://testing-common/Assert.jsm:87:21
Assert.AssertionError@resource://testing-common/Assert.jsm:127:18
proto.report@resource://testing-common/Assert.jsm:220:13
strictEqual@resource://testing-common/Assert.jsm:354:8
test_freebusy_request@/NEW-SSD/moz-obj-dir/objdir-tb3/_tests/xpcshell/comm/calendar/test/unit/test_caldav_requests.js:901:14
_do_main@/NEW-SSD/NREF-COMM-CENTRAL/mozilla/testing/xpcshell/head.js:248:6
_execute_test@/NEW-SSD/NREF-COMM-CENTRAL/mozilla/testing/xpcshell/head.js:577:5
@-e:1:1

line 5596 case:

 0:54.47 TEST_START: xpcshell-icaljs.ini:comm/calendar/test/unit/test_bug485571.js
 ...

 1:00.59 pid:784168 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 1:00.59 PASS check_absolute - [check_absolute : 97] [object Object] != null
 1:00.59 PASS check_absolute - [check_absolute : 98] null == null
 1:00.59 INFO (xpcshell/head.js) | test MAIN run_test finished (1)
 1:00.59 INFO exiting test
 1:00.59 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5596}]
icaltime_adjust@resource:///modules/calendar/Ical.jsm:5596:1
setTimeAttr@resource:///modules/calendar/Ical.jsm:5793:18
fromData@resource:///modules/calendar/Ical.jsm:5016:13
icaltime@resource:///modules/calendar/Ical.jsm:4878:10
clone@resource:///modules/calendar/Ical.jsm:4928:14
startOfWeek@resource:///modules/calendar/Ical.jsm:5104:25
get startOfWeek@resource:///components/calDateTime.js:164:45
getMessage@resource://testing-common/Assert.jsm:82:19
Assert.AssertionError@resource://testing-common/Assert.jsm:127:18
proto.report@resource://testing-common/Assert.jsm:220:13
notEqual@resource://testing-common/Assert.jsm:290:8
check_absolute@/NEW-SSD/moz-obj-dir/objdir-tb3/_tests/xpcshell/comm/calendar/test/unit/test_bug485571.js:97:11
run_test@/NEW-SSD/moz-obj-dir/objdir-tb3/_tests/xpcshell/comm/calendar/test/unit/test_bug485571.js:76:17
_execute_test@/NEW-SSD/NREF-COMM-CENTRAL/mozilla/testing/xpcshell/head.js:571:7
@-e:1:1

What irks me is that tests SUCCEEDED.

The test harness/infrastructure SHOULD FAIL A TEST THAT PRODUCES JAVASCRIPT ERRORS OR INTERNALERRORS.

TIA

The test harness/infrastructure SHOULD FAIL A TEST THAT PRODUCES JAVASCRIPT ERRORS OR INTERNALERRORS.

In general, no. There are plenty of cases where the error is handled, but due to the way xpcom propagates errors they show up in the console.

Summary: C-C TB xpcshell test. InternalError: too much recursion" {file:"resource:///modules/calendar/Ical.jsm" line: 5788 (or 5596)}] → comm/calendar/test/unit/test_bug485571.js: InternalError: too much recursion" {file:"resource:///modules/calendar/Ical.jsm" line: 5788 (or 5596)}]

(In reply to Magnus Melin [:mkmelin] from comment #1)

The test harness/infrastructure SHOULD FAIL A TEST THAT PRODUCES JAVASCRIPT ERRORS OR INTERNALERRORS.

In general, no. There are plenty of cases where the error is handled, but due to the way xpcom propagates errors they show up in the console.

I agree in principle. There ARE tests that deal with incorrect input and the way TB handles such error sometime is throwing an error and during the error processing, the log related to the error handling is printed. In that sense, as long as the error is handled correctly, those error messages can be safely ignored.

HOWEVER, THEN there ought to be a mechanism to TELL the
test framework that the next errors that pop up should be ignored (say, we are handling a test case where such errors are handled intelligently).
The errors not covered by such preceding permission can be reported as errors clearly.
Such a mechanism can be a crude but simple, "Ignore a following error that will pop up during this test" based on a simple string match.
This will probably cover 95% of such errors that we do not want to be reported.
And actually, such instruction to the test framework, if printed in the log, clarifies what a person analyzing should take a look at, etc.
(I recall that Portable C Compiler distribution of many years ago has such a message, "Please ignore the following error from the execution of yacc, The shift-reduce conflict or such were expected.", blah, blah for then C grammar specification. So we can safely ignore that while building it.

If XPCOM cannot be fixed easily, then the user-supplied strings to suppress the error reporting one way or the other and the error reporting that takes advantage of such user-supplied instruction should be build to make logs useful at all IMHO.

Such a print of a message would GO A LONG WAY to relieve us to look at frivoulous errors and help us to focus on really unwanted errors.

BTW, there seems to be a mechanism meant for an operation in that direction. Well actually, there does seem to be a usage of such functions in a few tests I saw. I can't recall where I saw it now. But it was declarative and I am not sure how test framework did anything about it at all.
We solely need to have either such a mechanism or the printing of a user-supplied "Ignore the following error" in a standard format from the test program itself if it is known to cause an JavaScript error and the error is known to be safe.

Someone need to add some debuginng and check what goes wrong at
https://searchfox.org/comm-central/rev/e3363365eed24f91277ac9946d8e61d357d8547d/calendar/base/modules/Ical.jsm#5788 when ./mach xpcshell-test comm/calendar/test/unit/test_bug485571.js is run

Weird.

I inserted the following dump.

diff --git a/calendar/base/modules/Ical.jsm b/calendar/base/modules/Ical.jsm
--- a/calendar/base/modules/Ical.jsm
+++ b/calendar/base/modules/Ical.jsm
@@ -5784,17 +5784,20 @@ ICAL.TimezoneService = (function() {
           }
 
           return this._time[attr];
         },
         set: function setTimeAttr(val) {
           // Check if isDate will be set and if was not set to normalize date.
           // This avoids losing days when seconds, minutes and hours are zeroed
           // what normalize will do when time is a date.
+          console.log("(debug) setTimeAttr: attr=" + attr
+                        + ", val = " + val + ", this._time.isDate = " + this._time.isDate + "\n" );
           if (attr === "isDate" && val && !this._time.isDate) {
+            console.log("(debug) setTimeAttr: this.adjust is being called \n");
             this.adjust(0, 0, 0, 0);
           }
           this._cachedUnixTime = null;
           this._pendingNormalization = true;
           this._time[attr] = val;
 
           return val;
         }

Then I got a very strange error in different place.
I can't easily explain what is going on
Maybe the JS stack is exhausted and we get garbage result???

 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=isDate, val = true, this._time.isDate = false\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: this.adjust is being called \n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=isDate, val = true, this._time.isDate = true\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=day, val = 26, this._time.isDate = true\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=isDate, val = true, this._time.isDate = true\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=hour, val = 0, this._time.isDate = true\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=minute, val = 0, this._time.isDate = true\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=second, val = 0, this._time.isDate = true\n"
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=year, val = 2009, this._time.isDate = false\n"
 0:43.05 pid:792745 JavaScript error: resource://gre/modules/ConsoleAPIStorage.jsm, line 109: InternalError: too much recursion
 0:43.05 pid:792745 [792745, Main Thread] WARNING: Failed to record a console event.: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/console/Console.cpp:1564
 0:43.05 pid:792745 console.log: "(debug) setTimeAttr: attr=month, val = 4, this._time.isDate = false\n"
 0:43.09 pid:792745 JavaScript error: resource:/gre/modules/ConsolbeAPIStorage.jsm, line 109: InternalError: too much recursion
 0:43.09 pid:792745 [792745, Main Thread] WARNING: Failed to record a console event.: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/console/Console.cpp:1564
 0:43.09 pid:792745 console.log: "(debug) setTimeAttr: attr=day, val = 26, this._time.isDate = false\n"
 0:43.09 pid:792745 JavaScript error: resource://gre/modules/ConsoleAPIStorage.jsm, line 109: InternalError: too much recursion
 0:43.09 pid:792745 [792745, Main Thread] WARNING: Failed to record a console event.: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/console/Console.cpp:1564
 0:43.09 pid:792745 console.log: "(debug) setTimeAttr: attr=hour, val = 0, this._time.isDate = false\n"
 0:43.09 pid:792745 JavaScript error: resource://gre/modules/ConsoleAPIStorage.jsm, line 109: InternalError: too much recursion
 0:43.09 pid:792745 [792745, Main Thread] WARNING: Failed to record a console event.: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/console/Console.cpp:1564

Or is it possible that

  • JS compiler used to take care of tail recursion and turn it into a repetition, but somehow now
    it fails to do so in some cases, and we hit such a case?
    A simple repetition of events that are recorded causing stack overflow is hard to understand. Hmm.

It seems that the error regarding console event is that there may be simply too many (?) calls to this routine that flooded the communication buffer for console.log()?
In my local mochitest log

  •        console.log("(debug) setTimeAttr: this.adjust is being called \n");

This line was printed WHOPPING 2523489 times. Yes, 2.5 million times.
We may want to check the logic of Calendar to figure out why it needs to call this function so many times.
(This may be one reason why calendar test feels so slow in contrast to other tests in mochitests.)

I still get these errors.

Please recall that you have to specify "--sequential --verbose" to see these unreported errors from xpcshell test framework.

 0:13.50 pid:687958 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 0:24.23 pid:687958 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 0:24.53 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5596}]
 0:24.54 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5596}]
 0:42.03 pid:688009 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 0:50.62 pid:688009 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 0:50.66 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5788}]
 0:50.67 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5788}]
 1:11.33 pid:688243 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5788: InternalError: too much recursion
 1:11.35 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5788}]
 1:30.30 pid:688402 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 1:41.27 pid:688402 JavaScript error: resource:///modules/calendar/Ical.jsm, line 5596: InternalError: too much recursion
 1:41.28 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5596}]
 1:41.30 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5596}]

https://github.com/mozilla-comm/ical.js/issues/410

This is exactly the same bug, I think.

Are we supposed to report errors related to ical.js to this github repository?

I found a stackoverflow reference to JSON.stringify causing too much recursion:
https://stackoverflow.com/questions/3895399/too-much-recursion-error-when-calling-json-stringify-on-a-large-object-with-ci

So basically, it seems there is a circular list created by calendar, it seems.

In theory we just pull in the upstream ical.js, but we could potentially fix it locally and sync to upstream as well.

(In reply to Magnus Melin [:mkmelin] from comment #10)

In theory we just pull in the upstream ical.js, but we could potentially fix it locally and sync to upstream as well.

I see.　Finding what are causing the circular reference is not that easy, considering just trying to find it by printing would cause the infinite recursion.
OTOH, if the JSON.stringify is only called for dumping purposes, non-standard object method, toSource() could be used.
https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Object/toSource
But toSource() is only for Firefox.

toString() method is available, but probably again only useful for debugging purposes, maybe.
https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Object/toString

We need to figure out where the JSON.stringify() is used.
According to
https://github.com/mozilla-comm/ical.js/issues/410
the problem seems to happen in the test to print　the result of assert().
（https://searchfox.org/mozilla-central/source/testing/modules/Assert.jsm#82　and
https://searchfox.org/mozilla-central/source/testing/modules/Assert.jsm#87
refer to JSON.stringify() BTW.)

As of now, I have no idea what circular reference is created in calendar.
Following is what I have figured out today.

The first recursion error I see in local log is as follows.
(Please recall that I run xpcshell test with --verbose --sequential passed to |mach| command

 0:24.53 INFO "CONSOLE_MESSAGE: (error) [JavaScript Error: "InternalError: too much recursion" {file: "resource:///modules/calendar/Ical.jsm" line: 5596}]
icaltime_adjust@resource:///modules/calendar/Ical.jsm:5596:37
setTimeAttr@resource:///modules/calendar/Ical.jsm:5793:18
fromData@resource:///modules/calendar/Ical.jsm:5016:13
icaltime@resource:///modules/calendar/Ical.jsm:4878:10
clone@resource:///modules/calendar/Ical.jsm:4928:14
startOfWeek@resource:///modules/calendar/Ical.jsm:5104:25
get startOfWeek@resource:///components/calDateTime.js:164:45
getMessage@resource://testing-common/Assert.jsm:82:19
Assert.AssertionError@resource://testing-common/Assert.jsm:127:18
proto.report@resource://testing-common/Assert.jsm:220:13
equal@resource://testing-common/Assert.jsm:275:8
test_dates@/NEW-SSD/moz-obj-dir/objdir-tb3/_tests/xpcshell/comm/calendar/test/unit/test_alarm.js:387:8
run_test@/NEW-SSD/moz-obj-dir/objdir-tb3/_tests/xpcshell/comm/calendar/test/unit/test_alarm.js:27:3
_execute_test@/NEW-SSD/NREF-COMM-CENTRAL/mozilla/testing/xpcshell/head.js:592:7

Looking at near test_alarm.js:387, we find,

  // Set an absolute time and check it
  alarm.related = Ci.calIAlarm.ALARM_RELATED_ABSOLUTE;
  let alarmDate = createDate(2007, 0, 1, true, 2, 0, 0); <--- suspicious
  alarm.alarmDate = alarmDate;
  equal(alarm.alarmDate, alarmDate);  <--- line 387, This blosws up the stack.
  equal(alarm.offset, null);

|alarm.alarmDate| and |alarmDate| should be equal due to the assignment immediately above.

The above suggests that createDate() seems to create a circular reference.
The name suggests a simple function and it is a bit hard to understand why and how.

createDate() is defined at
https://searchfox.org/comm-central/source/calendar/test/unit/head_consts.js#17

function createDate(aYear, aMonth, aDay, aHasTime, aHour, aMinute, aSecond, aTimezone) {
  let date = Cc["@mozilla.org/calendar/datetime;1"].createInstance(Ci.calIDateTime);
  date.resetTo(
    aYear,
    aMonth,
    aDay,
    aHour || 0,
    aMinute || 0,
    aSecond || 0,
    aTimezone || cal.dtz.UTC
  );
  date.isDate = !aHasTime;
  return date;
}

I am not sure why |aHour| is passed |true|. Maybe it has a special meaning within calendar.
Anyway, if I understand this correctly,
date.resetTo(2007, 0, 1, true, 2, 0, 0) is called(?), and
|date| is returned.
|date| is actually

date = Cc["@mozilla.org/calendar/datetime;1"].createInstance(Ci.calIDateTime);

|resetTo|, I think, is
at https://searchfox.org/comm-central/source/calendar/base/backend/icaljs/calDateTime.js#95

 resetTo(year, month, day, hour, minute, second, timezone) {
    this.innerObject.fromData({
      year,
      month: month + 1,
      day,
      hour,
      minute,
      second,
    });
    this.timezone = timezone;
  },

For the call to this(i.e., |date|).innerObject.fromData(),
I am not entirely sure which version of fromData() defined in many places in Ical.jsm s exactly used

So all I can think of is JSON().stringify() may recur too much
when it tries to print one of the following data.

- |date| after a value is set through this.innerObject.fromData() call above, or
-  Cc["@mozilla.org/calendar/datetime;1"].createInstance(Ci.calIDateTime)  itself after creation,
- true,  or (<- this  is hard to believe) 
- cal.dtz.UTC  (whatever value it had when the too much recursion was encountered.)

That is all I can think of as of now. Beware I am a total calendar newbie.

Interesting find.

This too much recursion error is not reported when TB is run under valgrind during xpcshell test.

The timing difference may cause the recursion to be stopped before it gets too deep.
(That is before JS has time to recur very deep, some external event(?) may change the recursion termination condition and recursion is terminated?)

Yes, the error occurs when the test framework tries to print a variable to the log. There's not very much we can do about it, except not directly compare some types of value using equal, since using that function causes the arguments to be printed. Fortunately in most cases we can just compare the values for equality.

The log printer follows a cyclical reference until it dies of "too much recursion".

Assignee: nobody → geoff
Status: NEW → ASSIGNED

Pushed by geoff@darktrojan.net:
https://hg.mozilla.org/comm-central/rev/527a49709cf2
Avoid comparing calendar objects in a way that causes them to be printed to a log. r=mkmelin

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
status-thunderbird_esr91: --- → wontfix
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: