kewisch/gdata-provider

Silently fails to save event to Calendar without error or message (data is lost) Adding item failed:2147500036:

Closed this issue · 13 comments

Describe the problem and steps to reproduce it:

I tried to convert an email to an event in a Google Calendar within Thunderbird. I have seen this error many many times in the last month and not always when converting emails to events, so I doubt the conversion is the issue.

What happened?

The event is not added to the Calendar and no error is given. Unless you go and check the calendar or the error console, you will not notice that the event is not there.

What did you expect to happen?

The event is saved or an error is given to signal that something went wrong.

Anything else we should know?

Restarting Thunderbird fixes it... for a little while then it happens again:

Thunderbird Version 91.5.0
Provider for Google Calendar extension 91.0.4

Error console prints (among other things that seem unrelated):

TypeError: this._idleService is undefined
[imCore.jsm:149:20](resource:///modules/imCore.jsm)
    _checkIdle resource:///modules/imCore.jsm:149
    observe resource:///modules/imCore.jsm:119
Calendar: [calStorageCalendar] Message: executeSyncItemStatement exception
Connection Ready: true
Last DB Error Number: 6
Last DB Error Message: database table is locked
Database File:XXX/calendar-data/cache.sqlite
Last DB Statement: [object StatementJSHelper]
Last Statement param [0]: undefined
Last Statement param [1]: undefined
Last Statement param [2]: undefined
Last Statement param [offline_journal]: undefined
Last Statement param [id]: undefined
Last Statement param [cal_id]: undefined
Last Statement param [length]: 3
Exception: [Exception... "Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep]"  nsresult: "0x8052000e (NS_ERROR_FILE_IS_LOCKED)"  location: "JS frame :: resource:///modules/CalStorageCalendar.jsm :: executeSyncItemStatement :: line 267"  data: no]
1: [resource:///modules/[CalStorageCalendar.jsm:2725](resource:///modules/CalStorageCalendar.jsm)] logError
2: [resource:///modules/CalStorageCalendar.jsm:269] executeSyncItemStatement
3: [resource:///modules/CalStorageCalendar.jsm:2612] setMetaData
4: [resource://gdata-provider/legacy/modules/gdataUtils.jsm:88] saveItemMetadata
5: [resource://gdata-provider/legacy/modules/gdataUtils.jsm:1234] commitItem
CalStorageCalendar.jsm:2725
Calendar: [calCachedCalendar] replay action failed: <unknown>, uri=googleapi://XXX@gmail.com/?tasks=XXXXXXX, result=Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep], operation=[object Object] [calCachedCalendar.js:346](resource:///components/calCachedCalendar.js)
NS_ERROR_FILE_IS_LOCKED: Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep] [CalStorageCalendar.jsm:267](resource:///modules/CalStorageCalendar.jsm)
NS_ERROR_NOT_AVAILABLE: [ActivityManager.jsm:129](resource:///modules/ActivityManager.jsm)
Calendar: [calCachedCalendar] replay action failed: <unknown>, uri=https://apidata.googleusercontent.com/caldav/v2/XXXXXX%40group.calendar.google.com/events/, result=2147746065, operation=[xpconnect wrapped calIOperation] [calCachedCalendar.js:346](resource:///components/calCachedCalendar.js)
Calendar: [calCachedCalendar] replay action failed: <unknown>, uri=googleapi://XXXXXX@gmail.com/?calendar=XXXXXXXXXX%40group.calendar.google.com, result=, operation=[object Object] [calCachedCalendar.js:346](resource:///components/calCachedCalendar.js)
Calendar: [calGoogleCalendar] Adding Item EVENT failed:2147500036: [gdataCalendar.jsm:457](resource://gdata-provider/legacy/modules/gdataCalendar.jsm)

I've heard about this issue, though it is an issue with Thunderbird. Please try stopping Thunderbird, moving XXX/calendar-data/cache.sqlite out of the way, and then starting again.

I've heard about this issue, though it is an issue with Thunderbird. Please try stopping Thunderbird, moving XXX/calendar-data/cache.sqlite out of the way, and then starting again.

Well, starting again always fixes it. But I will anyway do what you suggest and keep an eye if it happens again (it is hard to notice because it is silent).

I did that and now all events for all remove calendars are gone. I waited to see if it is just taking time to synchronize and no. The file has been regenerated but all events are gone in thunderbird (luckily they are still in the Google site, otherwise...well, I don't to even imagine that). This is what the error console says:

Unexpected event profile-after-change [URLQueryStrippingListService.jsm:224](resource://gre/modules/URLQueryStrippingListService.jsm)
    observe resource://gre/modules/URLQueryStrippingListService.jsm:224
Unknown Collection "thunderbird/query-stripping" [RemoteSettingsClient.jsm:160](resource://services-settings/RemoteSettingsClient.jsm)
    UnknownCollectionError resource://services-settings/RemoteSettingsClient.jsm:160
    sync resource://services-settings/RemoteSettingsClient.jsm:501
    InterpretGeneratorResume self-hosted:1482
    AsyncFunctionNext self-hosted:692
Assert failed: Calendar manager initialised calendars before loadCalendarComponent ran on the first 3pane window. This should not happen.
 [calUtils.jsm:121](resource:///modules/calendar/calUtils.jsm)
    ASSERT resource:///modules/calendar/calUtils.jsm:121
    loadCalendarComponent chrome://calendar/content/calendar-chrome-startup.js:44
    atStartupRestoreTabs chrome://messenger/content/msgMail3PaneWindow.js:1203
    loadStartFolder chrome://messenger/content/msgMail3PaneWindow.js:1304
    selectFirstFolder chrome://messenger/content/msgMail3PaneWindow.js:1007
[Exception... "Component returned failure code: 0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0x80520001 (NS_ERROR_FILE_UNRECOGNIZED_PATH)"  location: "JS frame :: resource://gre/modules/L10nRegistry.jsm :: L10nRegistry.loadSync :: line 692"  data: no] [L10nRegistry.jsm:692:19](resource://gre/modules/L10nRegistry.jsm)
    loadSync resource://gre/modules/L10nRegistry.jsm:692
    fetchFile resource://gre/modules/L10nRegistry.jsm:607
    generateResourceSetSync resource://gre/modules/L10nRegistry.jsm:512
    map self-hosted:221
    generateResourceSetSync resource://gre/modules/L10nRegistry.jsm:507
    generateResourceSetsForLocaleSync resource://gre/modules/L10nRegistry.jsm:449
    next self-hosted:1430
    generateBundlesSync resource://gre/modules/L10nRegistry.jsm:186
    InterpretGeneratorResume self-hosted:1482
    next self-hosted:1430
    touchNext resource://gre/modules/Localization.jsm:167
    generateBundles resource://gre/modules/Localization.jsm:473
    <anonymous> resource:///modules/OTRUI.jsm:16
    get resource://gre/modules/XPCOMUtils.jsm:62
    _str resource:///modules/OTRUI.jsm:20
    initStrings resource:///modules/OTRUI.jsm:38
    init resource:///modules/OTRUI.jsm:259
    InterpretGeneratorResume self-hosted:1482
    AsyncFunctionNext self-hosted:692

I tried disabling and enabling the calendars. I did not work. But I got new errors:

Calendar: [calStorageCalendar] Message: executeSyncItemStatement exception
Connection Ready: true
Last DB Error Number: 6
Last DB Error Message: database table is locked
Database File: XXXXXXXX/calendar-data/cache.sqlite
Last DB Statement: [object AsyncStatementJSHelper]
Exception: [Exception... "Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep]"  nsresult: "0x8052000e (NS_ERROR_FILE_IS_LOCKED)"  location: "JS frame :: resource:///modules/CalStorageCalendar.jsm :: executeSyncItemStatement :: line 267"  data: no]
1: [resource:///modules/[CalStorageCalendar.jsm:2725](resource:///modules/CalStorageCalendar.jsm)] logError
2: [resource:///modules/CalStorageCalendar.jsm:269] executeSyncItemStatement
3: [resource:///modules/CalStorageCalendar.jsm:2612] setMetaData
4: [resource:///modules/CalDavCalendar.jsm:230] saveCalendarProperties
5: [resource:///modules/caldav/CalDavRequestHandlers.jsm:554] endDocument
6: [resource:///modules/caldav/CalDavRequestHandlers.jsm:61] handleResponse
CalStorageCalendar.jsm:2725
NS_ERROR_FILE_IS_LOCKED: Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep] [CalStorageCalendar.jsm:267](resource:///modules/CalStorageCalendar.jsm)
    executeSyncItemStatement resource:///modules/CalStorageCalendar.jsm:267
    setMetaData resource:///modules/CalStorageCalendar.jsm:2612
    saveCalendarProperties resource:///modules/CalDavCalendar.jsm:230
    endDocument resource:///modules/caldav/CalDavRequestHandlers.jsm:554
    handleResponse resource:///modules/caldav/CalDavRequestHandlers.jsm:61
    InterpretGeneratorResume self-hosted:1482
    AsyncFunctionNext self-hosted:692
Calendar: [calStorageCalendar] Message: executeSyncItemStatement exception
Connection Ready: true
Last DB Error Number: 6
Last DB Error Message: database table is locked
Database File: XXXX/calendar-data/cache.sqlite
Last DB Statement: [object AsyncStatementJSHelper]
Exception: [Exception... "Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep]"  nsresult: "0x8052000e (NS_ERROR_FILE_IS_LOCKED)"  location: "JS frame :: resource:///modules/CalStorageCalendar.jsm :: executeSyncItemStatement :: line 267"  data: no]
1: [resource:///modules/[CalStorageCalendar.jsm:2725](resource:///modules/CalStorageCalendar.jsm)] logError
2: [resource:///modules/CalStorageCalendar.jsm:269] executeSyncItemStatement
3: [resource:///modules/CalStorageCalendar.jsm:2612] setMetaData
4: [resource:///modules/CalDavCalendar.jsm:230] saveCalendarProperties
5: [resource:///modules/caldav/CalDavRequestHandlers.jsm:554] endDocument
6: [resource:///modules/caldav/CalDavRequestHandlers.jsm:61] handleResponse
CalStorageCalendar.jsm:2725
NS_ERROR_FILE_IS_LOCKED: Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep] [CalStorageCalendar.jsm:267](resource:///modules/CalStorageCalendar.jsm)
    executeSyncItemStatement resource:///modules/CalStorageCalendar.jsm:267
    setMetaData resource:///modules/CalStorageCalendar.jsm:2612
    saveCalendarProperties resource:///modules/CalDavCalendar.jsm:230
    endDocument resource:///modules/caldav/CalDavRequestHandlers.jsm:554
    handleResponse resource:///modules/caldav/CalDavRequestHandlers.jsm:61
    InterpretGeneratorResume self-hosted:1482
    AsyncFunctionNext self-hosted:692
NS_ERROR_FILE_IS_LOCKED: Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [mozIStorageStatement.executeStep]

I've heard about this issue, though it is an issue with Thunderbird. Please try stopping Thunderbird, moving XXX/calendar-data/cache.sqlite out of the way, and then starting again.

This resulted in all events from all remote calendars disappearing. I was not able to fix it. I had to unsubscribe from all calendars, and add them back. For others out there, DO NOT DELETE calendar-data/cache.sqlite

By the way, after deleting calendar-data/cache.sqlite and re-adding the calendars, the problem has occurred again.

Another data point. If I save the event to a local calendar, then copy+paste it into the Google Calendar, it is saved, while saving directly it to the Google Calendar gives the error above until Thunderbird is restarted.

Do you have your profile on a network drive? Or a different filesystem? I'm sorry I haven't been replying, I'm unfortunately not sure what to recommend regarding the FILE_IS_LOCKED error. This shouldn't be happening, and since it is, it is in the lower level parts of Thunderbird that the provider can't easily influence. At the same time, the Thunderbird team will likely have trouble reproducing this.

If you have any other data points that might give hints on what is different on your system to mine and others I'd appreciate.

No, it is a normal ext4 partition. Do you know what is generating the message?

Calendar: [calGoogleCalendar] Adding Item EVENT failed:2147500036: gdataCalendar.jsm:457

Couldn't the addon catch that error and offer the user to retry or save in a different calendar?

The only possible difference is that my memory is really limited (only 8 GB and 1GB of swap) so thunderbird sometimes crashes when it goes crazy consuming memory. Perhaps it is trying to allocate a large chunk of memory and something gets killed?

I also have clamav running in the background. Perhaps it is trying to read the same file? But which file?

The file that is locked is indeed cache.sqlite, in othefr cases it may be local.sqlite. It could also be related to the WAL and SHM files for those databases. Can you try having clamav exclude the Thunderbird profile (or at least those files)?

This is still happening. I have excluded the whole calendar-data folder but it still happens. It is a very dangerous error.

I have spent all day today accepting invitations and creating meetings only to notice at the end of the day that none of them have been saved to the calendar. The fact that there is no error at all is really the worst aspect of this bug.

Is there no return value or signal that can be caught and give an error to the user? When it starts failing I simply have to close thunderbird and open it again and then it works. However, if I don't notice the problem, then it silently fails forever.

Not at the level that the Provider is functioning. This happens in the Thunderbird code somewhere, so I am not sure if I can catch it. Do you have any other software that is potentially watching the filesystem similar to how an anti virus might? Are you experiencing this issue with any other remote calendars in Thunderbird? You could try subscribing to the Google Calendar without the Provider via CalDAV, to see if that triggers the error as well.

It looks like we haven't heard back on this issue, therefore we are closing this issue. If this problem persists in the latest version of Thunderbird and the Provider for Google Calendar, please re-open this issue.