704012 - Fail to retrieve calendar from mod_caldav based calendar

Status: RESOLVED INVALID

(Calendar :: Provider: CalDAV, defect)

Description

[Jaco Kroon]

Attachment: debug_output.txt

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:7.0.1) Gecko/20100101 Firefox/7.0.1
Build ID: 20111103080250

Steps to reproduce:

Created a new calendar link to an existing caldav calendar (with caching enabled).  Or refresh a calendar after an another client made modifications.


Actual results:

In the case of a new calendar no events will be loaded, an error gets output:

Warning: CalDAV: Fatal Error doing multiget for JKroon

I'm also attaching the full debug output, as well as a tcpdump captured http stream.


Expected results:

The calendar should have loaded properly, with all existing events loaded into the lightning plugin, and any new events added by other clients should be linked in too.

Comment 1

[Jaco Kroon]

Attachment: actual on-the wire tcp stream

Comment 2

[Jaco Kroon]

Should perhaps add I'm using Thunderbird 7.0.1.

Comment 3

[Stefan Sitter [:ssitter]]

Does this mean it works if Cache is disabled?
The Cache feature was changed heavily in Lightning 1.0 to support offline editing.
I suggest to retest using Thunderbird 8 + Lightning 1.0.

Comment 4

[Jaco Kroon]

Hi,

No, with caching disabled it still does the same thing.  In fact, it just means I don't have to delete/re-add the calendar, a simple restart of thunderbird is sufficient to trigger it.  Note that a refresh also fails with:

CalDAV: ctag matches, no need to fetch data for calendar JKroon

I suspect that is being addresses by bug 641665 though.

I will see what I can do about testing with Thunderbird 8 and Lightning 1.0 (these massive version number jumps are strange to me).

Comment 5

[Jaco Kroon]

Hi,

No change going to Thunderbird 8.0 with lightning 1.0, debug output for multiget remains exactly the same:

CalDAV: send(http://atlantis.local.uls.co.za/caldav/jkroon/): <calendar-multiget xmlns:D="DAV:" xmlns="urn:ietf:params:xml:ns:caldav">
  <D:prop>
    <D:getetag/>
    <calendar-data/>
  </D:prop>
  <D:href>/caldav/jkroon/40be90c4-61a0-4d5e-8d0d-51bf8abc2475.ics</D:href>
  <D:href>/caldav/jkroon/ec830e0b-7278-470d-9db6-72c559c32fdf.ics</D:href>
  <D:href>/caldav/jkroon/85898106-631c-45d7-b0c8-dd891df25640.ics</D:href>
  <D:href>/caldav/jkroon/5c6aa038-7412-4c02-b531-773e2a86134a.ics</D:href>
  <D:href>/caldav/jkroon/09a76041-c6de-4a59-8014-bf2803e832ed.ics</D:href>
  <D:href>/caldav/jkroon/386b89d3-4de3-4050-9391-eb357e43255c.ics</D:href>
  <D:href>/caldav/jkroon/bf233bf1-7b1e-4ec9-98da-56186ec965b1.ics</D:href>
</calendar-multiget>
Warning: CalDAV: Fatal Error doing multiget for JKroon
CalDAV: recv: 
<D:multistatus>
<D:response>
<D:href>/caldav/jkroon/40be90c4-61a0-4d5e-8d0d-51bf8abc2475.ics</D:href>
<D:propstat>
<D:prop>
<lp1:getetag>"4b22d78467b00"</lp1:getetag>
<lp3:calendar-data>BEGIN:VCALENDAR
PRODID:-//K Desktop Environment//NONSGML libkcal 4.3//EN
VERSION:2.0
BEGIN:VEVENT
CREATED:20111120T165835Z
X-ALT-DESC;FMTTYPE=text/html:
 
aChangeLogListener=null
calendarURI=http://atlantis.local.uls.co.za/caldav/jkroon/ 
iscached=false
this.mQueuedQueries.length=13

However, I did notice this additionally in the error console:

Error: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsISAXXMLReader.onDataAvailable]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: resource://calendar/modules/calUtils.jsm -> file:///usr/lib64/thunderbird/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/calendar-js/calDavRequestHandlers.js :: mg_onDataAvailable :: line 815"  data: no]
Source File: resource://calendar/modules/calUtils.jsm -> file:///usr/lib64/thunderbird/extensions/%7Be2fda1a4-762b-4020-b5ad-a41df1933103%7D/calendar-js/calDavRequestHandlers.js
Line: 815

Not sure if that helps.

Comment 6

[Jaco Kroon]

Hi,

Further info, in calendar-js/calDavRequestHandlers.js, in the function mg_fatalError the this.unhandledErrors variables should be incremented so that mg_onStopRequest will be able to figure out that there was an error and not end up calling this.calendar.finalizeUpdatedItems, resulting in the incorrect CTAG being assigned.  This together with the patch I submitted to bug 641665 allows the calendar to figure out something went wrong.  This has two side effects that I can see:

1.  The calendar now creates a visible exclamation mark next to the calendar indicating an error (which is what I'd expect); and
2.  A further "Reload Remote Calendars" doesn't silently fail, as the mCtag value for the "local" calendar will now be null, resulting in a reload attempt.

This does not fix the underlying problem, but at least visibly exposes it to prevent silent errors, it does have one further side effect, I now also get this in my logs:

Warning: CalDAV: Get failed: multiget error
Warning: There has been an error reading data for calendar: JKroon.  However, this error is believed to be minor, so the program will attempt to continue. Error code: 0x80004005. Description: multiget error
Warning: There has been an error reading data for calendar: JKroon.  However, this error is believed to be minor, so the program will attempt to continue. Error code: READ_FAILED. Description: 

I will probably be able to investigate further again, but perhaps someone with more experience regarding the code can pick up on this so long and perhaps spot what's wrong much quicker than what I can.

Comment 7

[Felix Möller]

Hi Jaco,

I think it would be great if you could post your mod_caldav version and the configuration. I have seen lightning against DAViCal and Apple Calendar Server. Not sure if anybody here uses a mod_caldav share currently...

Comment 8

[Jaco Kroon]

Attachment: mod_dav_acl + mod_caldav configuration extract.

You don't NEED to use mod_auth_mysql (this is just what I use).  I managed to get this with file-based basic and digest auth too.  Bunch of placeholders in there.  The attachment goes in the vhost portion of the config, globally there is also this:

        AclOwnerFullRights on
        AclLockFile        /var/tmp/davacl.lock
        AclSharedMemFile   /var/tmp/davacl.shm
        AclSharedMemSize   65000

Comment 9

[Stefan Sitter [:ssitter]]

Does "Acl" in "AclOwnerFullRights on" refers to the "access control list (ACL)" feature that is in development in Bug 586276? If yes: Try to turn it off because Lightning doesn't support it yet.

Comment 10

[Felix Möller]

Jaco are you running http://sourceforge.net/projects/modcaldav/ ? Is there any version control for that??

Comment 11

[Jaco Kroon]

Yes, it's sourceforge.net/projects/modcaldav/ - I don't know about VCS, I just grabbed the latest source archive (mod_caldav-0.1.10) and used that, along with mod_dav_acl-0.1.6 (moddavacl on sourceforge).

Setting AclOwnerFullRights off has no effect.  From the README file for mod_dav_acl:

-the owner (if exists) has full rights to the resource if not any acl is set.

That probably applies to the principal only though, with mod_caldav doing it's own handling in case of no ACL being present.  I suspect the ACL code from bug 586276 should only really affect client-side handling, the SERVER side has to support dav_acl as it uses it for internal handling of access control, the client-side code could potentially allow for:

* Preventing a user from locally performing actions (s)he's not allowed to on the server, eg, adding new entries unless (s)he is allowed to.
* Potentially managing ACLs for a user's calendar, eg, I might want to grant free-busy access to most of my staff, full read to some senior staff, and write access to my PA.

I don't have any acl set (yet), so without that disabled I should actually (probably, from what I understand, unless it only applies to the principal as per explanation above) get access denied, however, there is no change.  I do seem to be getting short reponses in my captures though with the connection being reset from the Thunderbird side (not a clean FIN/ACK but a simple RST).  I'm guessing there is something in this response that is not liked, and early on (probably in the headers already, only posting the headers, a full sample in the attachments):

REPORT /caldav/jkroon/ HTTP/1.1

Host: atlantis.local.uls.co.za

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:8.0) Gecko/20111121 Thunderbird/8.0 Lightning/1.0

Accept: text/xml

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Accept-Charset: utf-8,*;q=0.1

Connection: keep-alive

Content-Length: 793

Content-Type: text/xml; charset=utf-8

Depth: 1

Authorization: Basic XXXXXXXXXXX=
Pragma: no-cache

Cache-Control: no-cache



<?xml version="1.0" encoding="UTF-8"?>
<calendar-multiget xmlns:D="DAV:" xmlns="urn:ietf:params:xml:ns:caldav">
  <D:prop>
    <D:getetag/>
    <calendar-data/>
  </D:prop>
  <D:href>/caldav/jkroon/40be90c4-61a0-4d5e-8d0d-51bf8abc2475.ics</D:href>
  <D:href>/caldav/jkroon/71b88b1d-bd7b-4913-b3dd-48cbc21f2ee7.ics</D:href>
  <D:href>/caldav/jkroon/ec830e0b-7278-470d-9db6-72c559c32fdf.ics</D:href>
  <D:href>/caldav/jkroon/85898106-631c-45d7-b0c8-dd891df25640.ics</D:href>
  <D:href>/caldav/jkroon/5c6aa038-7412-4c02-b531-773e2a86134a.ics</D:href>
  <D:href>/caldav/jkroon/09a76041-c6de-4a59-8014-bf2803e832ed.ics</D:href>
  <D:href>/caldav/jkroon/386b89d3-4de3-4050-9391-eb357e43255c.ics</D:href>
  <D:href>/caldav/jkroon/bf233bf1-7b1e-4ec9-98da-56186ec965b1.ics</D:href>
</calendar-multiget>

And the response (This looks OK to me, but could the lack of Transfer-Encoding _AND_ Content-Length headers be causing an issue - it would most certainly kill Connection: keep-alive):

HTTP/1.0 207 Unknown

Date: Tue, 22 Nov 2011 20:18:22 GMT

Server: Apache

Content-Type: application/xml; charset="utf-8"

X-Cache: MISS from atlantis.local.uls.co.za

X-Cache-Lookup: MISS from atlantis.local.uls.co.za:3128

X-Cache: MISS from armadillo.local

X-Cache-Lookup: MISS from armadillo.local:3128

Via: 1.1 atlantis.local.uls.co.za:3128 (squid/2.7.STABLE9), 1.0 armadillo.local:3128 (squid/2.7.STABLE9)

Connection: close



The other responses have Content-Length headers, and Connection: keep-alive, but this response has Connection: close and no Content-Length header.

Comment 12

[Simon Vaillancourt]

I think your problem is that the server is not encoding XML properly, ie: if you look at the X-ALT-DESC value in one of your meeting, you will see that it contains html elements. A quick fix on the server side could be to enclose all calendar-data values in <![CDATA[ ]]> sections.

Comment 13

[Jaco Kroon]

Simon,

Looks like you're right.  Had a single .ics file in a DAV folder, as per the following, placed there by my a Nokia N9:

BEGIN:VCALENDAR
PRODID:-//K Desktop Environment//NONSGML libkcal 4.3//EN
VERSION:2.0
BEGIN:VEVENT
CREATED:20120102T195213Z
X-ALT-DESC;FMTTYPE=text/html:
 <!DOCTYPE=20HTML=20PUBLIC=20"-//W3C//DTD=20HTML=204.0//EN"=20"http:
 //www.w3.org/TR/REC-html40/strict.dtd">=0A<html><head><meta=20name=3D"qric
 htext"=20content=3D"1"=20/><meta=20http-equiv=3D"Content-Type"=20content=3
 D"text/html;
 =20charset=3Dutf-8"=20/><style=20type=3D"text/css">=0Ap,=20li=20{=20white-
 space:=20pre-wrap;=20}=0A</style></head><body=20style=3D"=20font-family:
 'Nokia=20Pure=20Text=20Light';=20font-weight:400;=20font-style:normal;
 ">=0A<p=20style=3D"-qt-paragraph-type:empty;=20margin-top:0px;
 =20margin-bottom:0px;=20margin-left:0px;=20margin-right:0px;
 =20-qt-block-indent:0;=20text-indent:0px;"><br=20/></p></body></html>
DTSTAMP:20120102T195102Z
UID:2318185c-56e7-4937-b10d-920a4deee244
LAST-MODIFIED:20120102T195102Z
SUMMARY:Work starts
LOCATION:Uls
STATUS:CONFIRMED
DTSTART;VALUE=DATE:20120109
DTEND;VALUE=DATE:20120110
TRANSP:OPAQUE
BEGIN:VALARM
ACTION:AUDIO
TRIGGER;VALUE=DURATION:-PT12H
REPEAT:5
DURATION:PT5M
X-KDE-KCALCORE-ENABLED:TRUE
END:VALARM
END:VEVENT
END:VCALENDAR

thunderbird (lightning) refused to sync.  After manually editing and removing the X-ALT-DESC flag it worked, then restored the original file and edited to wrap the X-ALT-DESC tag in <![CDATA[...]]>, that however silently failed, in fact duplicating the only other entry that I've had in the calendar (after a full unsubscribe resubscribe cycle).  At that point editing the file again and removing the X-ALT-DESC tag entirely managed to get the new entry (but kept the duplicated entry).

At this point a restart of thunderbird loaded the calendar correctly (I've disabled "caching" of the calendar entirely, so a restart as I understand it does a full reload in effect).  Instead of wrapping in the CDATA tag doing a search&replace for < => &lt; and > => &gt; does actually work - not sure if this means I added the <![CDATA[...]]> tag incorrectly perhaps (I'm not particularly knowledgeable on XML, so for reference:

BEGIN:VCALENDAR
PRODID:-//K Desktop Environment//NONSGML libkcal 4.3//EN
VERSION:2.0
BEGIN:VEVENT
CREATED:20120102T195213Z
X-ALT-DESC;FMTTYPE=text/html:
 <![CDATA[<!DOCTYPE=20HTML=20PUBLIC=20"-//W3C//DTD=20HTML=204.0//EN"=20"http:
 //www.w3.org/TR/REC-html40/strict.dtd">=0A<html><head><meta=20name=3D"qric
 htext"=20content=3D"1"=20/><meta=20http-equiv=3D"Content-Type"=20content=3
 D"text/html;
 =20charset=3Dutf-8"=20/><style=20type=3D"text/css">=0Ap,=20li=20{=20white-
 space:=20pre-wrap;=20}=0A</style></head><body=20style=3D"=20font-family:
 'Nokia=20Pure=20Text=20Light';=20font-weight:400;=20font-style:normal;
 ">=0A<p=20style=3D"-qt-paragraph-type:empty;=20margin-top:0px;
 =20margin-bottom:0px;=20margin-left:0px;=20margin-right:0px;
 =20-qt-block-indent:0;=20text-indent:0px;"><br=20/></p></body></html>]]>
DTSTAMP:20120102T195102Z
UID:2318185c-56e7-4937-b10d-920a4deee244
LAST-MODIFIED:20120102T195102Z
SUMMARY:Work starts
LOCATION:Uls
STATUS:CONFIRMED
DTSTART;VALUE=DATE:20120109
DTEND;VALUE=DATE:20120110
TRANSP:OPAQUE
BEGIN:VALARM
ACTION:AUDIO
TRIGGER;VALUE=DURATION:-PT12H
REPEAT:5
DURATION:PT5M
X-KDE-KCALCORE-ENABLED:TRUE
END:VALARM
END:VEVENT
END:VCALENDAR

but that works now ... so I must've made a typo on the first attempt.  Ok, the fact remains that if the second .ics entry is invalid the first gets duplicated, but that may be related to another bug.

I've filed a bug against mod_caldav, explaining the bug, however, if someone is familiar with libxml2 and is willing to help with writing a patch for mod_caldav, please put your hand in the air, I've looked at the code very briefly and am not sure where to add it.  I thought that maybe the easy hack would be to just wrap the entire iCal file content in <![CDATA[ ... ]] but that actually prevents mod_caldav itself from functioning so it'll have to be modified to properly escape the field data I think.

mod_caldav bug visible at:  https://sourceforge.net/tracker/?func=detail&aid=3468503&group_id=191888&atid=939185

IMHO this bug can be closed, albeit, during my testing now thunderbird (lightning) was rather unhappy a number of times.  Most likely due to messing with the data on the caldav side.  Will see if I can reproduce those (and file bugs) once I have mod_caldav sorted out.

Comment 14

[Jaco Kroon]

On second thought, I've just been messing around with the cli test tool included in mod_caldav to try and see if I can get a way to look at the actual raw streamed XML data and it seems there is a way to request the XML server to only give known fields (ie, ignore the X-ALT-DESC field and not even send it.

One of the standard REPORT tests that the tool run sends the following XML with the REPORT query:

<?xml version="1.0" encoding="utf-8" ?>
<C:calendar-query xmlns:D="DAV:"
                 xmlns:C="urn:ietf:params:xml:ns:caldav">
     <D:prop>
       <D:getetag/>
       <C:calendar-data>
         <C:comp name="VCALENDAR">
           <C:prop name="VERSION"/>
           <C:comp name="VEVENT">
             <C:prop name="SUMMARY"/>
             <C:prop name="UID"/>
             <C:prop name="DTSTART"/>
             <C:prop name="DTEND"/>
             <C:prop name="DURATION"/>
             <C:prop name="RRULE"/>
             <C:prop name="RDATE"/>
             <C:prop name="EXRULE"/>
             <C:prop name="EXDATE"/>
             <C:prop name="RECURRENCE-ID"/>
           </C:comp>
           <C:comp name="VTIMEZONE"/>
         </C:comp>
       </C:calendar-data>
     </D:prop>
     <C:filter>
       <C:comp-filter name="VCALENDAR">
         <C:comp-filter name="VEVENT">
           <C:time-range start="20060104T000000Z"
                         end="20060105T000000Z"/>
         </C:comp-filter>
       </C:comp-filter>
     </C:filter>
   </C:calendar-query>

I modified the C:time-range tag to be sane to match exactly the one event with the -X-ALT-DESC tag, and surprisingly (had to recreate a new one), only got this as response:

<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:">
<D:response xmlns:lp1="DAV:" xmlns:lp2="http://apache.org/dav/props/" xmlns:lp3="urn:ietf:params:xml:ns:caldav" xmlns:lp4="http://calendarserver.org/ns/">
<D:href>/caldav/jkroon/79e819b8-f65d-4cd2-b454-3275c8b77ed4.ics</D:href>
<D:propstat>
<D:prop>
<lp1:getetag>"4b59271af2900"</lp1:getetag>
<lp3:calendar-data>BEGIN:VCALENDAR
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Africa/Johannesburg
BEGIN:STANDARD
TZNAME:SAST
TZOFFSETFROM:+0130
TZOFFSETTO:+0200
DTSTART:19030301T223000
RDATE;VALUE=DATE-TIME:19030301T223000
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:SAST
TZOFFSETFROM:+0200
TZOFFSETTO:+0300
DTSTART:19420921T000000
RDATE;VALUE=DATE-TIME:19420921T000000
RDATE;VALUE=DATE-TIME:19430920T000000
END:DAYLIGHT
BEGIN:STANDARD
TZNAME:SAST
TZOFFSETFROM:+0300
TZOFFSETTO:+0200
DTSTART:19430321T230000
RDATE;VALUE=DATE-TIME:19430321T230000
RDATE;VALUE=DATE-TIME:19440319T230000
END:STANDARD
END:VTIMEZONE
BEGIN:VEVENT
UID:79e819b8-f65d-4cd2-b454-3275c8b77ed4
SUMMARY:Test
DTSTART;TZID=Africa/Johannesburg:20120110T082500
DTEND;TZID=Africa/Johannesburg:20120110T092500
END:VEVENT
END:VCALENDAR
</lp3:calendar-data>
</D:prop>
<D:status>HTTP/1.1 200 OK</D:status>
</D:propstat>
</D:response>
</D:multistatus>

Note that the X-ALT-DESC is NOT included.  I tried various modifications of this to get the X-ALT-TAG included, and the minimal change is to not request any <C:prop name="..."> inner tags on the <C:comp name="VEVENT">:

<?xml version="1.0" encoding="utf-8" ?>
<C:calendar-query xmlns:D="DAV:"
                 xmlns:C="urn:ietf:params:xml:ns:caldav">
     <D:prop>
       <D:getetag/>
       <C:calendar-data>
         <C:comp name="VCALENDAR">
           <C:prop name="VERSION"/>
           <C:comp name="VEVENT" />
           <C:comp name="VTIMEZONE"/>
         </C:comp>
       </C:calendar-data>
     </D:prop>
     <C:filter>
       <C:comp-filter name="VCALENDAR">
         <C:comp-filter name="VEVENT">
           <C:time-range start="20120104T000000Z"
                         end="20120130T000000Z"/>
         </C:comp-filter>
       </C:comp-filter>
     </C:filter>
   </C:calendar-query>

And this also seems to work quite nicely:

           <C:comp name="VEVENT">
             <C:prop name="all"/>
           </C:comp>

Not sure if this is a worthwhile adjustment on the thunderbird side, however, try as I might I could not get it right, and all the debug output for TB still showed the X-ALT-DESC line coming down, and dying immediately upon receipt thereof.

Comment 15

[Jaco Kroon]

Patch submitted to mod_caldav, after which TB works as expected.  Some of the error handling can probably improve on the TB side, but for now I'm happy.

Closing.