gdata-provider [needs debugging help] Issues with idle time and lost synchronization

Hello, To synchronize my agenda with google agenda I need to reboot Thunderbird 102.1.2 (64 bits) under windows Is it normal?

LOG ERRORS

Successfully loaded OpenPGP library rnp.dll version 0.16+git20220124.f06439f7.MZLA from C:\Program Files (x86)\Mozilla Thunderbird\rnp.dll [RNPLib.jsm:100:15](chrome://openpgp/content/modules/RNPLib.jsm)
Found 0 public keys and 0 secret keys (0 protected, 0 unprotected) [RNPLib.jsm:301:15](chrome://openpgp/content/modules/RNPLib.jsm)
Trying to load C:\Program Files (x86)\Mozilla Thunderbird\libotr.dll [OTRLib.jsm:64:11](resource:///modules/OTRLib.jsm)
Successfully loaded OTR library C:\Program Files (x86)\Mozilla Thunderbird\libotr.dll [OTRLib.jsm:72:13](resource:///modules/OTRLib.jsm)
services.settings: Failed to load last_modified.json: TypeError: NetworkError when attempting to fetch resource. [Utils.jsm:330](resource://services-settings/Utils.jsm)
Cette page est en mode de compatibilité (quirks). La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
181 [calItemBase.js:431:30](resource:///components/calItemBase.js)
Cette page est en mode de compatibilité (quirks). La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
5 [calViewUtils.jsm:416:35](resource:///modules/calendar/utils/calViewUtils.jsm)
Cette page est en mode de compatibilité (quirks). La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
37 [calItemBase.js:431:30](resource:///components/calItemBase.js)
tb.account.size_on_disk - Trying to set an unsigned scalar to a negative number. 2
tb.account.size_on_disk - Truncating float/double number. 4
tb.account.size_on_disk - Trying to set an unsigned scalar to a negative number. 12
Une tentative visant à définir un en-tête interdit à été bloquée : Content-Length 2 [cardbookWebDAV.js:386:17](chrome://cardbook/content/cardbookWebDAV.js)
Cette page est en mode de compatibilité (quirks). La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
[blank](about:blank)
Cette page est en mode de compatibilité (quirks). La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
[background.js:59:41](moz-extension://background.js)
Cette page est en mode presque standard. La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
[](moz-nullprincipal:)
Cette page est en mode presque standard. La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
[blank](about:blank)
Cette page est en mode de compatibilité (quirks). La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
[fetch>UID>.INBOX>153770]
Cette page est en mode presque standard. La mise en page peut en être affectée. Pour le mode standard, utilisez « <!DOCTYPE html> ».
[cardbookMain.css:161:7](chrome://cardbook/content/skin/cardbookMain.css)
Erreur d’analyse de la valeur pour « align-items ».  Déclaration abandonnée. [cardbookMain.css:201:15](chrome://cardbook/content/skin/cardbookMain.css)

Sep 23 '22 05:09 multiprod

Is this still an issue with the latest version? I don't see anything suggesting a need for restart in the logs.

Nov 14 '22 21:11 kewisch

I can confirm that at least clicking "Synchronize" in the calendar tab (at the top left) does not seem to have an effect. I have to restart Thunderbird (102.5.0-1) to see changes. I'm on Manjaro Linux -- please let me know if/how I can help.

Nov 21 '22 16:11 hakanyi

No synchro problem since updating last versions Thunderbird 102.5.0 64bits and addon 102.0.0

Nov 23 '22 10:11 multiprod

Just checked, still an issue for me, unfortunately :/

Nov 23 '22 16:11 hakanyi

Still have sync problems. It's been a few months since some of my Google Calendars don't synchronize correctly. I cannot trust Thunderbird calendar anymore :/

Especially, events created by other people in shared google calendars don't appear in TB without the application restart. My own private calendars and my own events in shared calendars seem to synchronize. But I'm not sure if it's always the case.

I'm on Windows 11, TB 102.5.0, Google provider 102.0.3

Nov 29 '22 16:11 jachoo

Can you try re-subscribing to the calendar? If that doesn't work, I will need a few more logs, e.g. these steps logged

re-subscribe the calendar and make sure it is synchronized (I don't need the full logs here, just maybe the sync token)
create event in google calendar
click synchronize

Nov 30 '22 09:11 kewisch

Hello @kewisch , I can try to help. This thread seems similar to #529 that I started. But I don't know much about Thunderbird. For logs, do you want the error console output?
Or a log created ala https://wiki.mozilla.org/MailNews:Logging#Mac_OS_X ? or some other log source?

Will a Macos Thunderbird client even be helpful? I don't have the resources to try this on Windows or some variety *nix.

I also don't know much about git / github. Should I merge 529 into 498 and if so, what is an education references on how to do that.

fwiw, n00mad

Dec 06 '22 14:12 n00mad

Can you try re-subscribing to the calendar? If that doesn't work, I will need a few more logs, e.g. these steps logged 1. re-subscribe the calendar and make sure it is synchronized (I don't need the full logs here, just maybe the sync token) 2. create event in google calendar 3. click synchronize

I cannot reproduce the problem this way. After re-subscribing (or restarting TB) synchronization mostly works (as far as I can see). But after some time (hours, days?) calendars stop synchronizing from Google to TB.

Probably it's important to say that I subscribe to 16 google calendars (some are my private, some are shared, and some are public).

It's difficult for me to reproduce the issue, as it seems to happen after a few days. The first thing that seems to break is when an event is deleted on Google's side (then it still exists in TB). But after some time the synchronization stops entirely, or almost entirely. When I click "synchronize", in the status bar I see synchronization messages, but in reality, the calendars are not synced from Google to TB. The other way (from TB to Google) sync is still OK.

There are no messages in the developer console, so I cannot tell you more. Is there an option to enable better logging or something that can help us diagnose the issue? I had to stop using TB as my primary calendar because it's completely unreliable now :(

UPDATE:

I see two strange things in the logs, but they seem to be NOT correlated to sync problems (they happen just after re-subscribing, when the sync still works correctly, I think):

Sometimes the status bar message doesn't disappear after the sync ('synchronizing calendar XXX`)
There are a few error messages in the console:

Assert failed: Calendar manager initialised calendars before loadCalendarComponent ran on the first 3pane window. This should not happen. [calUtils.jsm:109](resource:///modules/calendar/calUtils.jsm)
Calendar: [calICSService] Error in parser worker: [object Object] [calICSService.js:588](resource:///components/calICSService.js)
Calendar: Error Parsing ICS: 2147500037 [CalIcsParser.jsm:146](resource:///modules/CalIcsParser.jsm)

Dec 20 '22 14:12 jachoo

@kewisch, any updates on the issue? Can I help you somehow?

Jan 02 '23 13:01 jachoo

Hello,

For the moment, I have another problem.

Could you please explain me how to delete the rigth column (Général vCard) on my CardBook ?

Michel Schatz

MosAiles 51 rue de la gare 57330 Zoufftgen

Tél : 00 33 (0)6 61 202 203 @.***

visitez notre sitehttps://www.mosailes.com visitez notre sitehttps://shop.mosailes.com

Je pense environnement: ai-je vraiment besoin d’imprimer ce message ? Save the Planet: Do I really need to print this email ?

Le 02/01/2023 à 14:42, jachoo a écrit :

Can you try re-subscribing to the calendar? If that doesn't work,
I will need a few more logs, e.g. these steps logged
1. re-subscribe the calendar and make sure it is synchronized (I
don't need the full logs here, just maybe the sync token)
2. create event in google calendar
3. click synchronize
@kewisch https://github.com/kewisch, any updates on the issue? Can I help you somehow?

— Reply to this email directly, view it on GitHub https://github.com/kewisch/gdata-provider/issues/498#issuecomment-1368957954, or unsubscribe https://github.com/notifications/unsubscribe-auth/AGITWWKNMSVVP3Z4XTL3Y6DWQLLOBANCNFSM6AAAAAAQTVJURA. You are receiving this because you authored the thread.Message ID: @.***>

Jan 03 '23 07:01 multiprod

Same problem here: hours/days after restarting TB or disabling-enabling the add-on sync stops.

Jan 04 '23 15:01 carlosabalde

This also happens to me on current stable release (both Windows and Linux). Are the debug steps from https://github.com/kewisch/gdata-provider/issues/498#issuecomment-1331857281 still up-to-date? I'll try to collect them when it happens again.

Feb 03 '23 08:02 peci1

I've trying to understand the issue and I found a tiny modification of the add-on that -so far- has fixed the issue for me. Details in https://github.com/kewisch/gdata-provider/discussions/497#discussioncomment-5188907 just in case somebody here wants to help testing it.

Mar 03 '23 10:03 carlosabalde

I've managed to workaround the bug without rebuilding or reinstalling. Just run in the console (Tools -> Developer Tools -> Debug Addons -> Provide for Google Calendar -> Console) following line:

> await messenger.storage.local.set({"settings.idleTime": 0})

After executing this line, one must restart Thunderbird. From now, the calendar sync should work correctly.

Mar 06 '23 17:03 jachoo

The side effect is the same, because that way maxIdleTime != 0 && idleTime > maxIdleTime will never be true. In any case, one way or another, it seems obvious that a bugfix release will be needed to avoid hacky workarounds.

Mar 06 '23 17:03 carlosabalde

await messenger.storage.local.set({"settings.idleTime": 0})

This doesn't sound like a good idea. It might have severe performance implications.

Mar 06 '23 17:03 peci1

await messenger.storage.local.set({"settings.idleTime": 0}) This doesn't sound like a good idea. It might have severe performance implications.

I don't agree. According to documentation (quoted below), idle time is a time when there is no keyboard/mouse activity. So if I'm using actively the computer, this command doesn't change anything in TB. But correctly workarounds the issue.

This interface lets you monitor how long the user has been 'idle', i.e. not used their mouse or keyboard. You can get the idle time directly, but in most cases you will want to register an observer for a predefined interval. The observer will get an 'idle' notification when the user is idle for that interval (or longer), and receive an 'active' notification when the user starts using their computer again.

Mar 08 '23 14:03 jachoo

You'll be able to get more logs by setting calendar.debug.log and calendar.debug.log.verbose in the advanced config editor in Thunderbird. This will also let you see if you get the message [calGoogleCalendar] Skipping refresh since user is idle while not actually idle. Can someone provide logs on that?

The logic is simply there to reduce API calls and avoid hitting the API limit. Setting idleTime to 0 has no other negative effects.

I'm curious if the idle time is a red herring though. In theory if you are using Thunderbird you should notice no difference. It should only start skipping syncs if you haven't used Thunderbird for 5 minutes. As soon as you hit sync, it should be up to date again.

Jul 09 '23 19:07 kewisch

It happened again today. A colleague sent added me to an event. I clicked "Synchronize" in TB, but the event was not there (it was normally present in online GCal webpage). There's nothing interesting in the log. Not even Skipping refresh since user is idle.

When I restarted TB, the event appeared in the startup log:

14:33:02.322 Calendar: [calGoogleCalendar] Request GET [https://www.googleapis.com/calendar/v3/calendars/***%40…eleted=true&syncToken=***](https://www.googleapis.com/calendar/v3/calendars/***/events?maxResults=1000&showDeleted=true&syncToken=***) responded with HTTP 200 [gdataRequest.jsm:390](resource://gdata-provider/legacy/modules/gdataRequest.jsm)
14:33:02.322 Calendar: [calGoogleCalendar] Timezone for *** is Europe/Prague [gdataUtils.jsm:1099](resource://gdata-provider/legacy/modules/gdataUtils.jsm)
14:33:02.322 Calendar: [calGoogleCalendar] Parsing 1 received events [gdataUtils.jsm:1107](resource://gdata-provider/legacy/modules/gdataUtils.jsm)
14:33:02.322 Calendar: [calGoogleCalendar] Parsing entry:
{
 "kind": "calendar#event",
 "etag": "\"3377984525032000\"",
 "id": "05kgvj3po8le0hcsjn86fv4onr",
 "status": "confirmed",
 "htmlLink": "https://www.google.com/calendar/event?eid=MDVrZ3ZqM3BvOGxlMGhjc2puODZmdjRvbnIgcGVja2FtYTJAZmVsLmN2dXQuY3o",
 "created": "2023-07-10T12:26:36.000Z",
 "updated": "2023-07-10T12:31:02.516Z",
 "summary": "***",
 "creator": {
  "email": "***"
 },
 "organizer": {
  "email": "***"
 },
 "start": {
  "dateTime": "2023-07-11T15:00:00+02:00",
  "timeZone": "Europe/Berlin"
 },
 "end": {
  "dateTime": "2023-07-11T16:00:00+02:00",
  "timeZone": "Europe/Berlin"
 },
 "iCalUID": "***",
 "sequence": 0,
 "attendees": [
  {
   "email": "***",
   "displayName": "***",
   "self": true,
   "responseStatus": "accepted"
  },
  {
   "email": "***",
   "responseStatus": "needsAction"
  },
  {
   "email": "***",
   "organizer": true,
   "responseStatus": "accepted"
  }
 ],
 "hangoutLink": "***",
 "conferenceData": {
  "entryPoints": [
   {
    "entryPointType": "video",
    "uri": "***",
    "label": "[***](chrome://devtools/content/webconsole/meet.google.com/***)"
   }
  ],
  "conferenceSolution": {
   "key": {
    "type": "hangoutsMeet"
   },
   "name": "Google Meet",
   "iconUri": "https://fonts.gstatic.com/s/i/productlogos/meet_2020q4/v6/web-512dp/logo_meet_2020q4_color_2x_web_512dp.png"
  },
  "conferenceId": "***"
 },
 "reminders": {
  "useDefault": true
 },
 "eventType": "default"
}
[gdataLogging.jsm:17](resource://gdata-provider/legacy/modules/gdataLogging.jsm)
14:33:02.328 Calendar: [calGoogleCalendar] Logging calIEvent:
	id:[email protected]
	created:2023-07-10T12:26:36Z
	updated:2023-07-10T12:31:02Z
	title:***
	description:null
	transparency:null
	status:CONFIRMED
	startTime:2023-07-11T15:00:00
	endTime:2023-07-11T16:00:00
	location:null
	privacy:null
	sequence:0
	alarmLastAck:null
	snoozeTime:null
	isOccurrence: false
	Organizer: 
		ID: mailto:***
			Name: undefined
			Rsvp: null
			Is Organizer: yes
			Role: null
			Status: NEEDS-ACTION
	Attendees: 

		ID: mailto:***
			Name: ***
			Rsvp: null
			Is Organizer: no
			Role: REQ-PARTICIPANT
			Status: ACCEPTED

		ID: mailto:***
			Name: undefined
			Rsvp: null
			Is Organizer: no
			Role: REQ-PARTICIPANT
			Status: NEEDS-ACTION

		ID: mailto:***
			Name: undefined
			Rsvp: null
			Is Organizer: no
			Role: REQ-PARTICIPANT
			Status: ACCEPTED
	recurrence: no
	alarms: yes: 
		
		Action: DISPLAY
		Offset: -PT10M
		alarmDate: null
		related: 1
		repeat: 0
		repeatOffset: null
		repeatDate: null
		description: null
		summary: null
		properties: yes:
			X-DEFAULT-ALARM:TRUE

Jul 10 '23 12:07 peci1

I'm curious if the idle time is a red herring though. In theory if you are using Thunderbird you should notice no difference. It should only start skipping syncs if you haven't used Thunderbird for 5 minutes. As soon as you hit sync, it should be up to date again.

The implementation is (or was) buggy. More info here: https://github.com/kewisch/gdata-provider/discussions/497#discussioncomment-5194513

Jul 10 '23 12:07 jachoo

After updating to 115.0.1 (and dropping the fix described in https://github.com/kewisch/gdata-provider/discussions/497#discussioncomment-5164776: i.e. removing this branch), the issue is back. Some time after I stopped using the computer, these are the last logged messages:

19:48:39.539 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:39.554 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:39.572 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:39.636 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:40.163 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:40.208 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:40.218 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758

After that, clicks on 'Calendars > Synchronize' are silently ignored and events are not synchronized.

Jul 10 '23 18:07 carlosabalde

There's a couple things I noticed that might be worthwhile. First off:

#593 is very likely to be a duplicate of this issue
#604 is very likely to be a duplicate of this issue
#464 is also likely a duplicate, although it technically was filed earlier

Anyways, that aside, I don't have enough context to understand what the correct fix would be, but there seems to be a suggested workaround of pasting the following into the terminal:

await messenger.storage.local.set({"settings.idleTime": 0})

I just wanted to point out that this is unnecessarily complicated. Instead, go to Settings, search for "config editor" and you should see the following:

This is the same thing as about:config in Firefox. Anyways, you can set the idle time to zero there directly:

No console or restart of thunderbird required. In any case I hope that someone (maybe @kewisch or @nneul?) can look into providing a patch soon. This issue seems like it'd be straightforward enough given that the discussion around it suggests that it is only one branch condition causing the problem, but maybe I'm completely mistaken on that front.

Aug 01 '23 18:08 ThatGeoGuy

Note that the config editor and the add-on's local storage are two separate storages. I do have some migration code between the two somewhere, so by coincidence it might work. If you want a GUI editor, debug add-ons to open the add-on devtools, go to the storage tab, and change/add settings.

I won't have time in the near future to reproduce and work on this issue, but I'll try to squeeze it in. If others are able to debug further what causes the sync to return without action when returning I'd much appreciate!

Aug 03 '23 11:08 kewisch

After updating to 115.0.1 (and dropping the fix described in #497 (comment): i.e. removing this branch), the issue is back. Some time after I stopped using the computer, these are the last logged messages:

19:48:39.539 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:39.554 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:39.572 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:39.636 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:40.163 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:40.208 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758
19:48:40.218 Calendar: [calGoogleCalendar] Skipping refresh since user is idle gdataCalendar.jsm:758

After that, clicks on 'Calendars > Synchronize' are silently ignored and events are not synchronized.

@carlosabalde When you click synchronize, does it say [calGoogleCalendar] Skipping refresh since user is idle as well? Or are these all log messages from while you were indeed idle?

Oct 15 '23 19:10 kewisch

@kewisch the 'Skipping refresh' events are the last messages in the log, probably logged because I went idle. problem is once they are logged, clicks on 'Calendars > Synchronize' are silently ignored and nothing is logged (and events are not synchronized anymore).

Oct 15 '23 20:10 carlosabalde

Would you be up for some debugging? The idle time check is the very first thing that is done, so if that doesn't provide a message then the idle time is probably a red herring.

If you set the debugger to break here: https://github.com/kewisch/gdata-provider/blob/1b494e010928b5a61401b27e7ec866b8e37c4a54/src/legacy/modules/gdataCalendar.jsm#L750

then you should be able to find out at what point it bails out. You can access the debugger with Tools> Developer Tools > Developer Toolbox

Oct 15 '23 20:10 kewisch

For the last months I've using the await messenger.storage.local.set({"settings.idleTime": 0}) workaround. Yesterday I executed await messenger.storage.local.set({"settings.idleTime": 60}) and the issue reappeared after some idle time (Thunderbird 115.3.1 + Provider for Google Calendar 115.0.2). However, I'd need some help to add the breakpoint. Using the debugger and inspectingthe add-on, the only file I can see to add breakpoints is background.js.

screenshot-2023 10 16-08 45 16

Oct 16 '23 06:10 carlosabalde

There is a more elaborate debugger if you follow the menu structure I posted above, that should allow you to debug all of Thunderbird (including legacy add-ons like this one). Can you try that?

Oct 16 '23 07:10 kewisch

@kewisch finally I managed to add the breakpoint you suggested, but all I can see is replayChangesOn(aListener) is never called once the issue appears. If I restart Thunderbird to 'fix' the issue, then the breakpoint works as expected.

Oct 16 '23 11:10 carlosabalde

The issue is already diagnosed in the following threads: https://github.com/kewisch/gdata-provider/discussions/497#discussioncomment-5194513 and https://github.com/kewisch/gdata-provider/discussions/497#discussioncomment-5164776

Probably there's no need to investigate this problem further. You can try to fix this if you have enough knowledge. I don't :(

Oct 20 '23 16:10 jachoo

gdata-provider gdata-provider copied to clipboard

[needs debugging help] Issues with idle time and lost synchronization

LOG ERRORS

gdata-provider
gdata-provider copied to clipboard