1396897 - GData provider creates duplicate events when recurring events are edited, saved and synchronized

Status: RESOLVED FIXED

(Calendar :: Provider: GData, defect, P1)

Description

[Tobias (:Tobbi) Markus]

I have the following setup:
Thunderbird (latest nightly): 57.0a1 (2017-08-28) (64-bit)
Lightning (latest nightly) - 5.9a1 
GData Provider (latest nightly) - 3.8a1

Steps to reproduce:
1. Create a Google calendar event (for me it was a recurring event, not sure whether that's relevant), click OK, let it synchronize.
2. Open the event again, make changes, click OK, let it synchronize.

The event (and maybe others) get duplicated upon synching. The event shows even more numerously in the Google Calendar web view than in Thunderbird.

Comment 1

[WaltS48 [:walts48]]

I can confirm using Daily 57.0a1 with Lightning 5.9a1 and GData Provider 3.8a1 on Ubuntu 16.04 LTS Linux.

Can not duplicate using the Ubuntu supplied Thunderbird 52.2.1 with Lightning 5.4.2.1 and GData Provider 3.3

Also can not duplicate using TB 56.0b3 Mozilla/5.0 (X11; Linux x86_64; rv:56.0) Gecko/20100101 Thunderbird/56.0 ID:20170819123318 CSet: 7cc1d5c9ddb50c41b5c393f9292ddee797eac916 with Lightning 5.8b1 and Provider for Google Calendar 3.7b2

Comment 2

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

I can also confirm this with Daily 57.0a1 / Lighting 5.9a1 / Provider 3.9a1.
Does not reproduce in Thunderbird 56.0b3 / Lightning 5.8b1 / Provider 3.9a1.

So it must be an issue with Lightning, which is even more concerning for me. I'll see what I can do, I might need some support. MakeMyDay, do you have time to take a look by chance?

For those testing Provider 3.9a1 in earlier versions, you need to revert bug 1386916 or provide a backwards compatible mechanism e.g. (aUri.pathQueryRef || aUri.path). I'll file a bug to make this backwards compatible for a while.

Comment 3

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

Another interesting detail: it seems the offline cache queue is not cleared. Every time I synchronize, I get about 10 of the same addItem calls that luckily don't create new items, I guess since the id already exists.

Comment 4

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

And to make matters worse, I couldn't identify anything in calendar/ in the changes between latest-comm-central and beta that would cause this to happen.

Comment 5

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

If anyone experiencing this has some time, could you try to find a closer regression range, e.g. which nightly build this started happening in?

Comment 6

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

Attachment: gdata-provider.xpi

Here is the version of the gdata provider I am using that works both on beta and central. This will help finding the regression range.

Comment 7

[Jorg K (CEST = GMT+2)]

Alice, could you assist us here? You'd need to install the add-on and then edit an event which is synchronised with a Google calendar. When editing that event and synchronising again, you get multiple undesired copies. As per comment #2, the regression range is not large, works in TB 56 beta, doesn't work in Daily. Many thanks in advance.

Comment 8

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

(In reply to Jorg K (GMT+2) from comment #7)
> Alice, could you assist us here? You'd need to install the add-on and then
> edit an event which is synchronised with a Google calendar.

Note the event needs to be a recurring event. I've edited the title after selecting "edit all occurrences". Thanks for the help!

Comment 9

[WaltS48 [:walts48]]

Attachment: Test results and Error log

I am sorry to report that it didn't work for me in my production or a test profile.

I have attached a test report and error log.

Comment 10

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

(In reply to [e-mail] from comment #9)
> I am sorry to report that it didn't work for me in my production or a test
> profile.
There may have been a misunderstanding. The attached xpi does not contain a fix, just a change that allows it to be installed both into beta and daily, due to an API incompatibilities. What I am looking for is the nightly that this started appearing in, you can find them at http://ftp.mozilla.org/pub/thunderbird/nightly/2017/

Comment 11

[Tobias (:Tobbi) Markus]

I hope this is correct because looking at the push log I couldn't find any commits that on first glance would be responsible for the bug.

Last good nightly: 2017-08-24
First bad nightly: 2017-08-25

Pushlog:
https://hg.mozilla.org/comm-central/pushloghtml?startdate=2017-08-24&enddate=2017-08-25

Comment 12

[Jorg K (CEST = GMT+2)]

You can obtain the correct range by looking at revision numbers:

2017-08-24:
C-C 56c3a9e0cbda
M-C d1c70c20e7b52f7295411343e4dc5db8ee

2017-08-25:
C-C 5a4764a25a0e
M-C 2306e153fba9ca55726ffcce889eaca7a4

That gives:
https://hg.mozilla.org/comm-central/pushloghtml?fromchange=56c3a9e0cbda&tochange=5a4764a25a0e
Nothing suspicious.

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d1c70c20e7b52f7295411343e4dc5db8ee&tochange=2306e153fba9ca55726ffcce889eaca7a4
Finding something in there will be hard.

Are you 100% about the 24th and 25th?

Comment 13

[Tobias (:Tobbi) Markus]

(In reply to Jorg K (GMT+2) from comment #12)
> You can obtain the correct range by looking at revision numbers:
> 
> 2017-08-24:
> C-C 56c3a9e0cbda
> M-C d1c70c20e7b52f7295411343e4dc5db8ee
> 
> 2017-08-25:
> C-C 5a4764a25a0e
> M-C 2306e153fba9ca55726ffcce889eaca7a4
> 
> That gives:
> https://hg.mozilla.org/comm-central/
> pushloghtml?fromchange=56c3a9e0cbda&tochange=5a4764a25a0e
> Nothing suspicious.
> 
> https://hg.mozilla.org/mozilla-central/
> pushloghtml?fromchange=d1c70c20e7b52f7295411343e4dc5db8ee&tochange=2306e153fb
> a9ca55726ffcce889eaca7a4
> Finding something in there will be hard.
> 
> Are you 100% about the 24th and 25th?

Yes, I am certain it's that range. I tried it over and over again and the build from the 24th doesn't exhibit any problematic behaviour from what I can tell. Feel free to re-test.

The exact range taken from about:buildconfig is the one you already mentioned:
https://hg.mozilla.org/comm-central/pushloghtml?fromchange=56c3a9e0cbdacd2620f060dea62abefb5ca359cf&tochange=5a4764a25a0e22561012b96cc0fbd58c5e35794c

Comment 14

[WaltS48 [:walts48]]

I get the same results as Tobbi.

Mozilla/5.0 (X11; Linux x86_64; rv:57.0) Gecko/20100101 Thunderbird/57.0a1 BuildID:20170824030204 https://hg.mozilla.org/comm-central/rev/56c3a9e0cbdacd2620f060dea62abefb5ca359cf with Lightning 5.9a1. - Passed

Mozilla/5.0 (X11; Linux x86_64; rv:57.0) Gecko/20100101 Thunderbird/57.0a1 BuildID:20170825030205 https://hg.mozilla.org/comm-central/rev/5a4764a25a0e22561012b96cc0fbd58c5e35794c with Lightning 5.9a1 - Failed

Comment 15

[Jorg K (CEST = GMT+2)]

There is nothing in the C-C range that could have caused this, so it must be in M-C:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d1c70c20e7b52f7295411343e4dc5db8ee&tochange=2306e153fba9ca55726ffcce889eaca7a4
Maybe some JS/promise change.

Are there no errors in the error console? Tools > Developer Tools > Error Console?

Comment 16

[Tobias (:Tobbi) Markus]

(In reply to Jorg K (GMT+2) from comment #15)
> There is nothing in the C-C range that could have caused this, so it must be
> in M-C:
> https://hg.mozilla.org/mozilla-central/
> pushloghtml?fromchange=d1c70c20e7b52f7295411343e4dc5db8ee&tochange=2306e153fb
> a9ca55726ffcce889eaca7a4
> Maybe some JS/promise change.
> 
> Are there no errors in the error console? Tools > Developer Tools > Error
> Console?

Not from what I can see. I enabled lightning verbose debug output to no avail.

Comment 17

[WaltS48 [:walts48]]

Attachment: error_log

This was with calendar.debug.log set to true.

I can do one with calendar.debug.log also set to true if it would help.

Comment 18

[Jorg K (CEST = GMT+2)]

Actually, this started failing the same day that bug 1393704 appeared, on 2017-08-25. Tooru took the pain to trace that back to bug 1392554, https://hg.mozilla.org/mozilla-central/rev/df5b4f5fe775, which is in the regression range.

So Philipp, you have all the information you can possibly get, now some Calendar person needs to analyse the test failure and fixing that will most likely also fix the bug.

BTW, the test fails in a spot that is about recurrence, that's what I disabled:
https://hg.mozilla.org/comm-central/rev/bfb0e8a1e5a2#l1.16

I guess we should pay attention to test failures.

Comment 19

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

Thank you all for the elaborate hunting! Async changes to the database do seem like a viable reason. I'll check this out ASAP, if MakeMyDay happens to have time that would also be marvelous. I suspect something changed in the order of async calls in the cached calendar.

Might be worth testing if the same happens with a cached caldav calendar, vs an uncached one.

Comment 20

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

Attachment: Fix - v1

Here is a patch that fixes the issue. I've also filed a bug to fix the m-c part, but it may turn out to be WONTFIX. The patch on this bug works around anyway.

Comment 21

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

Attachment: Lightning with patch applied - v1

Here is a lightning xpi with the patch applied for testing. It works with Daily 57.0a1, please give it a test run.


Also, here is a try run, fingers crossed that everything works.

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=e43534bdc968fafa958f18d60d577a9cd1924034

I tried to re-enable bug 1393704, but that did not work. Needs further investigation, trying to find time.

Comment 22

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

Attachment: Fix - v1

Corrected author, sorry about that!

Comment 23

[[:MakeMyDay]]

Comment on attachment 8916063 [details] [diff] [review]
Fix - v1

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

Just some style nits.

The test is on the list of disabled tests but passes locally for me, so probably you should enable it and kick off another try run.

::: calendar/base/modules/calAsyncUtils.jsm
@@ +37,5 @@
> +            case "modifyOfflineItem":
> +            case "deleteOfflineItem":
> +            case "getOfflineItemFlag":
> +            case "resetItemOfflineFlag":
> +                return (...args) => this.promiseOperation(target.QueryInterface(Components.interfaces.calIOfflineStorage), name, args);

Can you move the qi part to a separate variale and use that here you cut the length of the line a little bit?

::: calendar/providers/memory/calMemoryCalendar.js
@@ +432,5 @@
> +        } else if ((aItemFilter & calICalendar.ITEM_FILTER_OFFLINE_MODIFIED) != 0) {
> +          requestedFlag = cICL.OFFLINE_FLAG_MODIFIED_RECORD;
> +        } else if ((aItemFilter & calICalendar.ITEM_FILTER_OFFLINE_DELETED) != 0) {
> +          requestedFlag = cICL.OFFLINE_FLAG_DELETED_RECORD;
> +        }

Too little indentations here.

@@ +434,5 @@
> +        } else if ((aItemFilter & calICalendar.ITEM_FILTER_OFFLINE_DELETED) != 0) {
> +          requestedFlag = cICL.OFFLINE_FLAG_DELETED_RECORD;
> +        }
> +
> +        function matchOffline(itemFlag, requestedFlag) {

Please move this definition to the top or assign the function to a variable to avoid a strict warning here.

@@ +444,5 @@
> +                    (!itemFlag ||
> +                    /* OR   offline_journal != ${cICL.OFFLINE_FLAG_DELETED_RECORD})) */
> +                     itemFlag != cICL.OFFLINE_FLAG_DELETED_RECORD)) ||
> +                    /*  OR (offline_journal == :offline_journal)) */
> +                   itemFlag == requestedFlag

Indentation looks odd here, too.

@@ +451,2 @@
>          cal.forEach(this.mItems, ([id, item]) => {
>              let isEvent_ = cal.isEvent(item);

Don't we use to use the underscrore at the beginning instead of the end of the var name?

@@ +463,4 @@
>  
>              // If the offline flag doesn't match, skip the item
> +            if (!matchOffline(itemFlag, requestedFlag)) {
> +              return cal.forEach.CONTINUE;

Indentation

Comment 24

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

Attachment: Fix - v2

(In reply to Philipp Kewisch [:Fallen] from comment #21)
> I tried to re-enable bug 1393704, but that did not work. Needs further
> investigation, trying to find time.
I take that back, enabling the test works for me now! I've also changed do_check_eq() to equal().

Here is a new try run with correct syntax and the updated patch. Thanks Tom for the hint with --buildbot.

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=de7720e00951e621bf07397a21f9f113ab1d4912

Comment 26

[Jorg K (CEST = GMT+2)]

(In reply to Philipp Kewisch [:Fallen] from comment #24)
> https://treeherder.mozilla.org/#/jobs?repo=try-comm-
> central&revision=de7720e00951e621bf07397a21f9f113ab1d4912
Are you at C-C tip, that didn't compile when it should.

Comment 27

[Jorg K (CEST = GMT+2)]

Repeated that for you:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=a2494ba223eeeef1ae91e70a4936ab22f3ec916a

Comment 28

[Jorg K (CEST = GMT+2)]

Try successful (on Linux so far), remaining failures due to bug 1404577.

Comment 29

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

(In reply to [:MakeMyDay] from comment #23)
> > +                return (...args) => this.promiseOperation(target.QueryInterface(Components.interfaces.calIOfflineStorage), name, args);
> 
> Can you move the qi part to a separate variale and use that here you cut the
> length of the line a little bit?
This will introduce the ugly block within case due to variable scoping, but line length is more important here indeed.



> 
> @@ +444,5 @@
> > +                    (!itemFlag ||
> > +                    /* OR   offline_journal != ${cICL.OFFLINE_FLAG_DELETED_RECORD})) */
> > +                     itemFlag != cICL.OFFLINE_FLAG_DELETED_RECORD)) ||
> > +                    /*  OR (offline_journal == :offline_journal)) */
> > +                   itemFlag == requestedFlag
> 
> Indentation looks odd here, too.
I think this is in part due to the sql mixed in. I've split it out separately and improved the comments.

> 
> @@ +451,2 @@
> >          cal.forEach(this.mItems, ([id, item]) => {
> >              let isEvent_ = cal.isEvent(item);
> 
> Don't we use to use the underscrore at the beginning instead of the end of
> the var name?
We do, I suspect this is from times where isEvent was loaded from calUtils.js without the cal scope, and using let isEvent = ... would shadow the isEvent function on scope. Not going to fix this now otherwise I will rage rewrite the file :D

Comment 30

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

Attachment: Fix - v3

I'm going to assume you meant to r+. Here are the nits fixed. I didn't test this patch again because I am getting too tired today. Jörg, your call if you want to risk pushing this without testing, otherwise I can check in the next day or two.

Comment 31

[Jorg K (CEST = GMT+2)]

I'll take care of it from here. I'll give it another try. So far everything came out red tonight :-(

Comment 32

[Jorg K (CEST = GMT+2)]

I've run
mozilla/mach xpcshell-test calendar/test/unit/test_gdata_provider.js
mozilla/mach xpcshell-test calendar/test/unit/test_providers.js
manually and they both pass, so this is good to go.

As discussed with Philipp on IRC, this also fixes bug 1400253.

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/91eec4d4f89b
Don't use query parameters getter in sql related code. r=MakeMyDay

Comment 34

[Jorg K (CEST = GMT+2)]

This needs beta 57 uplift since it broke when bug 1392554 landed on mozilla57. We also need to re-enable test from bug 1400253 on beta.

Comment 35

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

Comment on attachment 8916175 [details] [diff] [review]
Fix - v3

Definitely want this on beta! I'm glad we didn't do a 57 beta yet.

Comment 36

[Tobias (:Tobbi) Markus]

I verified that everything works (after spending a long time deleting the excess events) with

Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:58.0) Gecko/20100101 Thunderbird/58.0a1 (2017-10-07) (64-bit)
Lightning 6.0a1 (2017-10-08)
GCal Provider 3.9a1 (2017-10-08)

Comment 37

[Jorg K (CEST = GMT+2)]

Beta (Calendar 5.9, TB 57):
https://hg.mozilla.org/releases/comm-beta/rev/8e53e2f0abefd6b835ba2f769e43c52249563325