search

jobisoft / DAV-4-TbSync

Mozilla Public License 2.0
161 stars 26 forks source link

'Parser Error. Could not find 'VCALENDAR' component.' when using with SOGo #269

Closed Frederick888 closed 2 years ago

Frederick888 commented 3 years ago

Your environment

TbSync version: 2.22 DAV-4-TbSync version: 1.24 Thunderbird version: 78.13.0

Expected behavior

Calendar events show up in Lightning.

Actual behavior

Events are pulled from SOGo, but causes Parser Error. Could not find 'VCALENDAR' component. and nothing shows up in Lightning.

Steps to reproduce

  1. Add SOGo account
  2. Select a calendar to synchronise

Thunderbird logs:

[calBackendLoader] Using Thunderbird's libical backend
console.debug: "Successfully loaded OpenPGP library librnp.so version 0.14+git20210121.7c8492b4.MZLA from /usr/lib/thunderbird/librnp.so"
Extension error: Error while loading 'jar:file:///usr/lib/thunderbird/omni.ja!/chrome/messenger/search-extensions/twitter/manifest.json' (NS_ERROR_FILE_NOT_FOUND) resource://gre/modules/Extension.jsm:570 :: readJSON/</<@resource://gre/modules/Extension.jsm:570:20
onStopRequest@resource://gre/modules/NetUtil.jsm:128:18

console.debug: "Found 12 public keys and 0 secret keys (0 protected, 0 unprotected)"
console.debug: "Successfully loaded optional OpenPGP library libgpgme.so from system's standard library locations"
console.debug: "gpgme version: 1.16.0"
console.debug: "Trying to load /usr/lib/thunderbird/libotr.so.5"
console.debug: "Trying to load libotr.so.5 from system's standard library locations"
console.debug: "Trying to load libotr.so from system's standard library locations"
console.log: (new Error("Cannot load required OTR library", "resource:///modules/OTRLib.jsm", 91))
console.log: "Creating sandbox for <10000@https://sogo.tsundere.moe>"
console.log: "Passing provided credentials for user <frederick888@tsundere.moe> to nsIHttpChannel."
console.log: "Passing provided credentials for user <frederick888@tsundere.moe> to nsIHttpChannel."
console.log: "Creating sandbox for <10001@https://sogo.tsundere.moe>"
console.log: "Passing provided credentials for user <frederick888@tsundere.moe> to nsIHttpChannel."
console.error: Lightning: 
  Parser Error. Could not find 'VCALENDAR' component.
BEGIN:XROOT
BEGIN:VTIMEZONE
TZID:Australia/Melbourne
LAST-MODIFIED:20210303T135712Z
X-LIC-LOCATION:Australia/Melbourne
BEGIN:STANDARD
TZNAME:AEST
TZOFFSETFROM:+1100
TZOFFSETTO:+1000
DTSTART:19700405T030000
RRULE:FREQ=YEARLY;BYDAY=1SU;BYMONTH=4
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:AEDT
TZOFFSETFROM:+1000
TZOFFSETTO:+1100
DTSTART:19701004T020000
RRULE:FREQ=YEARLY;BYDAY=1SU;BYMONTH=10
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:5F-6130B700-7-50B19F00
SUMMARY:Test
CLASS:PRIVATE
TRANSP:OPAQUE
DTSTART;TZID=Australia/Melbourne:20210904T213000
DTEND;TZID=Australia/Melbourne:20210904T223000
CREATED:20210902T113624Z
DTSTAMP:20210902T113624Z
LAST-MODIFIED:20210902T113624Z
END:VEVENT
END:XROOT

1: [resource:///modules/CalIcsParser.jsm:41] processIcalComponent
2: [resource:///modules/CalIcsParser.jsm:153] parseString
3: [resource:///modules/CalDavCalendar.jsm:897] addTargetCalendarItem
4: [resource:///modules/caldav/CalDavRequestHandlers.jsm:984] endElement
5: [resource:///modules/caldav/CalDavRequestHandlers.jsm:883] onDataAvailable

console.warn: Lightning: Failed to parse item: BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 5.1.0//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Australia/Melbourne
LAST-MODIFIED:20210303T135712Z
X-LIC-LOCATION:Australia/Melbourne
BEGIN:STANDARD
TZNAME:AEST
TZOFFSETFROM:+1100
TZOFFSETTO:+1000
DTSTART:19700405T030000
RRULE:FREQ=YEARLY;BYMONTH=4;BYDAY=1SU
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:AEDT
TZOFFSETFROM:+1000
TZOFFSETTO:+1100
DTSTART:19701004T020000
RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=1SU
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:5F-6130B700-7-50B19F00
SUMMARY:Test
CLASS:PRIVATE
TRANSP:OPAQUE
DTSTART;TZID=Australia/Melbourne:20210904T213000
DTEND;TZID=Australia/Melbourne:20210904T223000
CREATED:20210902T113624Z
DTSTAMP:20210902T113624Z
LAST-MODIFIED:20210902T113624Z
END:VEVENT
END:VCALENDAR
console.log: WebExtensions: BootstrapLoader for dav4tbsync@jobisoft.de unloaded!
JavaScript error: , line 0: NS_ERROR_NOT_AVAILABLE
JavaScript error: , line 0: NS_ERROR_NOT_AVAILABLE

I'll send debug.log in a min.

Frederick888 commented 3 years ago

Just upgraded to Thunderbird 91.1.0 + TbSync 3.0.1 + DAV-4-TbSync 2.0.2, still the same issue.

jobisoft commented 3 years ago

Didn't sogo release its own add-on? Maybe that works?

Frederick888 commented 3 years ago

@jobisoft Their connector only supports Thunderbird up to 68.x unfortunately...

jobisoft commented 3 years ago

I am pretty sure they have one for TB91, as I actively supported them in upgrading.

Frederick888 commented 3 years ago

@jobisoft Yup, found their nightly builds at https://packages.inverse.ca/SOGo/thunderbird/nightly/. Updated extensions.rdf according to the doc and skimmed over some code to add the missing properties in Config Editor, then after a restart my default SOGo calendar was added automatically.

However, still there are no events showing up in Lightning and I'm seeing the same error messages.

Btw I also tried the (new?) native CalDAV support. The calendar name showed up correctly during configuration but later it was the same symptom.

I can see events using ICS URL though but not able to create/update due to https://www.sogo.nu/bugs/view.php?id=2451.

Is this actually a Lightning problem?

jobisoft commented 3 years ago

What you have looks like an invalid event entry. There is a "END:VCALENDAR" at the end, but no opening counterpart. Could you check the actual data on the server? Is this a one-off error in TB, throwing away the first line?

Edit: Please only use the native CalDAV implementation for now, to minimize issues caused by add-ons.

Frederick888 commented 3 years ago

@jobisoft I've created a public test calendar: https://sogo.tsundere.moe/SOGo/dav/public/frederick888@tsundere.moe/Calendar/60-6139EC80-3-50B31E80/, which can be used to reproduce this issue in Thunderbird.

Then using the good 'ol vdirsyncer with the following configuration:

[general]
status_path = "~/.local/share/vdirsyncer/status/"

[pair my_calendar]
a = "my_calendar_local"
b = "my_calendar_remote"
collections = ["from a", "from b"]

[storage my_calendar_local]
type = "filesystem"
path = "~/.local/share/vdirsyncer/calendar/"
fileext = ".ics"

[storage my_calendar_remote]
type = "caldav"
url = "https://sogo.tsundere.moe/SOGo/dav/public/frederick888@tsundere.moe/Calendar/60-6139EC80-3-50B31E80/"

1 event and 1 task can be downloaded from this calendar:

60-6139EC80-3-50B31E80/5E-6139EC80-1-76CE5580.ics

BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 5.2.0//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Australia/Melbourne
LAST-MODIFIED:20210303T135712Z
X-LIC-LOCATION:Australia/Melbourne
BEGIN:STANDARD
TZNAME:AEST
TZOFFSETFROM:+1100
TZOFFSETTO:+1000
DTSTART:19700405T030000
RRULE:FREQ=YEARLY;BYMONTH=4;BYDAY=1SU
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:AEDT
TZOFFSETFROM:+1000
TZOFFSETTO:+1100
DTSTART:19701004T020000
RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=1SU
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:5E-6139EC80-1-76CE5580
SUMMARY:Some Event
CLASS:PUBLIC
TRANSP:OPAQUE
DTSTART;TZID=Australia/Melbourne:20210930T101500
DTEND;TZID=Australia/Melbourne:20210930T111500
CREATED:20210909T111437Z
DTSTAMP:20210909T111437Z
LAST-MODIFIED:20210909T111437Z
END:VEVENT
END:VCALENDAR

60-6139EC80-3-50B31E80/5F-6139EC80-5-24A868C0.ics

BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 5.2.0//EN
VERSION:2.0
BEGIN:VTODO
UID:5F-6139EC80-5-24A868C0
SUMMARY:Some Task
CLASS:PUBLIC
CREATED:20210909T111458Z
DTSTAMP:20210909T111458Z
LAST-MODIFIED:20210909T111458Z
END:VTODO
END:VCALENDAR

So the log probably also printed the whole event directly?

console.warn: Lightning: Failed to parse item: BEGIN:VCALENDAR
                                               ^ server response actually started here
jobisoft commented 3 years ago

Is there some sort of conversion going on? In your previous comment, there is:

console.error: Lightning: 
  Parser Error. Could not find 'VCALENDAR' component.
BEGIN:XROOT
BEGIN:VTIMEZONE
TZID:Australia/Melbourne
LAST-MODIFIED:20210303T135712Z
X-LIC-LOCATION:Australia/Melbourne
BEGIN:STANDARD
TZNAME:AEST
TZOFFSETFROM:+1100
TZOFFSETTO:+1000
DTSTART:19700405T030000
RRULE:FREQ=YEARLY;BYDAY=1SU;BYMONTH=4
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:AEDT
TZOFFSETFROM:+1000
TZOFFSETTO:+1100
DTSTART:19701004T020000
RRULE:FREQ=YEARLY;BYDAY=1SU;BYMONTH=10
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:5F-6130B700-7-50B19F00
SUMMARY:Test
CLASS:PRIVATE
TRANSP:OPAQUE
DTSTART;TZID=Australia/Melbourne:20210904T213000
DTEND;TZID=Australia/Melbourne:20210904T223000
CREATED:20210902T113624Z
DTSTAMP:20210902T113624Z
LAST-MODIFIED:20210902T113624Z
END:VEVENT
END:XROOT

observe XROOT as outer tag. Do you still get that? Your previous comment later has

console.warn: Lightning: Failed to parse item: BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 5.1.0//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Australia/Melbourne
LAST-MODIFIED:20210303T135712Z
X-LIC-LOCATION:Australia/Melbourne
BEGIN:STANDARD
TZNAME:AEST
TZOFFSETFROM:+1100
TZOFFSETTO:+1000
DTSTART:19700405T030000
RRULE:FREQ=YEARLY;BYMONTH=4;BYDAY=1SU
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:AEDT
TZOFFSETFROM:+1000
TZOFFSETTO:+1100
DTSTART:19701004T020000
RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=1SU
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:5F-6130B700-7-50B19F00
SUMMARY:Test
CLASS:PRIVATE
TRANSP:OPAQUE
DTSTART;TZID=Australia/Melbourne:20210904T213000
DTEND;TZID=Australia/Melbourne:20210904T223000
CREATED:20210902T113624Z
DTSTAMP:20210902T113624Z
LAST-MODIFIED:20210902T113624Z
END:VEVENT
END:VCALENDAR

is that the same event, but with VCalendar instead of ROOT? Maybe TB did that, but its parsing function for some reason was thrown on the initial one and failed? I have no idea....

Frederick888 commented 3 years ago

The error in my issue description was from a different calendar, and the error logs probably don't look very pretty as they were copied from Error Console...

Using the public calendar link I just shared:

image image

CalDavCalendar seems to be the outer layer to handle the CalDAV events/tasks, and [resource:///modules/CalIcsParser.jsm:165] parseString probably did some magic here to convert them but later caused issue in [resource:///modules/CalIcsParser.jsm:48] processIcalComponent.

I'll file a ticket to Thunderbird when I've got time I think.

jobisoft commented 3 years ago

Out of curiosity: Could you check the raw data on the server, does it include the VCALENDAR outer tag? And does sogo have an option to fix that on the server side?

Frederick888 commented 3 years ago

@jobisoft Sure thing. Just checked database raw data for the test calendar, looked exactly the same as what I posted, so it's probably not SOGo's issue...

jobisoft commented 3 years ago

As you posted two different versions, could you be more specific? Does the raw data have the VCALENDER tag as its outer tag?

grafik

This is the culprit.

Frederick888 commented 3 years ago

@jobisoft Yes I can confirm. My raw query:

mysql> select * from sogoxxxxxx where c_content like '%Some%';
+----------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------+----------------+-----------+-----------+
| c_name                     | c_content

                                                | c_creationdate | c_lastmodified | c_version | c_deleted |
+----------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------+----------------+-----------+-----------+
| 5E-6139EC80-1-76CE5580.ics | BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 5.2.0//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Australia/Melbourne
LAST-MODIFIED:20210303T135712Z
X-LIC-LOCATION:Australia/Melbourne
BEGIN:STANDARD
TZNAME:AEST
TZOFFSETFROM:+1100
TZOFFSETTO:+1000
DTSTART:19700405T030000
RRULE:FREQ=YEARLY;BYMONTH=4;BYDAY=1SU
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:AEDT
TZOFFSETFROM:+1000
TZOFFSETTO:+1100
DTSTART:19701004T020000
RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=1SU
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:5E-6139EC80-1-76CE5580
SUMMARY:Some Event
CLASS:PUBLIC
TRANSP:OPAQUE
DTSTART;TZID=Australia/Melbourne:20210930T101500
DTEND;TZID=Australia/Melbourne:20210930T111500
CREATED:20210909T111437Z
DTSTAMP:20210909T111437Z
LAST-MODIFIED:20210909T111437Z
END:VEVENT
END:VCALENDAR |     1631186077 |     1631186077 |         0 |      NULL |
| 5F-6139EC80-3-24A868C0.ics | BEGIN:VCALENDAR
PRODID:-//Inverse inc./SOGo 5.2.0//EN
VERSION:2.0
BEGIN:VTODO
UID:5F-6139EC80-5-24A868C0
SUMMARY:Some Task
CLASS:PUBLIC
CREATED:20210909T111458Z
DTSTAMP:20210909T111458Z
LAST-MODIFIED:20210909T111458Z
END:VTODO
END:VCALENDAR
                                   |     1631186098 |     1631186098 |         0 |      NULL |
+----------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------+----------------+-----------+-----------+
2 rows in set (0.00 sec)
Frederick888 commented 3 years ago

FYI I filed https://bugzilla.mozilla.org/show_bug.cgi?id=1730121.

Frederick888 commented 2 years ago

It turned out to be an issue from GNUstep https://bugzilla.mozilla.org/show_bug.cgi?id=1737067#c6. I rebuilt my SOGo docker image as suggested and the issue was gone.

Thank you @jobisoft for the help :)