On Thursday 24 Jun 2010 00:23:56 Andrew McMillan wrote:
> On Wed, 2010-06-23 at 18:57 +0100, Jim Hague wrote:
> > The admin is at http://<mydomain>/calendar/index.php. So I've tried
> > accessing the calendar I created at
> > http://<mydomain>/calendar/caldav.php/<principal>/home. This seems to
> > work fine in Evolution, but Sunbird - actually Iceowl, Debian Testing
> > (1.0b1) - is not happy. [...]
>
> It's odd that it refers just to <myprincipal> unless that's perhaps the
> name you've given the calendar locally. A status 400 is 'Bad Request'
> for which you may find something logged in DAViCal (the PHP log is
> usually the Apache error log).
>
> Make sure you don't have Apache mod_dav also running on your server
> since this will conflict with DAViCal. Probably this isn't the case,
> since Evolution is working fine, but the two clients take different
> approaches (and Apple iCal does it another way) so it is possible to
> have things work for one and not the other
I did have mod_dav loaded, though only enabled for a different path. To make
sure, I've repeated the setup on my home server, which does not have mod_dav
loaded. I get an identical error. I've also tried the regular Windows Sunbird
client, with the same results. To recap, the server setup is with Apache 2 on
Debian Lenny, following the instructions on the wiki, with a fresh install of
Postgres 8.3. Postgres and Davical both installed via apt-get, and the system
is otherwise fully up to date with Lenny main, security and volatile.
So, concentrating on the my home test setup, I have a single principal called
'test'. Here's the Sunbird/Iceowl log, this time completely unedited:
CalDAV: send(
http://web/calendar/caldav.php/test/home/): <?xml version="1.0"
encoding="UTF-8"?>
<D:propfind xmlns:D="DAV:">
<D:prop>
<D:getcontenttype/>
<D:resourcetype/>
<D:getetag/>
</D:prop>
</D:propfind>
CalDAV: recv:
<multistatus>
<response>
<href>/calendar/caldav.php/test/home/</href>
<propstat>
<prop>
<getcontenttype>httpd/unix-directory</getcontenttype>
<resourcetype>
<collection></collection>
<C:calendar></C:calendar>
</resourcetype>
</prop>
<status>HTTP/1.1 200 OK</status>
</propstat>
<propstat>
<prop>
<getetag></getetag>
</prop>
<status>HTTP/1.1 404 Not Found</status>
</propstat>
</response>
<response>
<href>/calendar/caldav.php/test/home/aeafbdff-
ddc1-4ef8-936c-1cd762cbe848.ics</href>
<propstat>
<prop>
<getcontenttype>text/calendar</getcontenttype>
<resourcetype></resourcetype>
<getetag>"ae40dfe99ebb6ed226663e3b48ea90b0"</getetag>
</prop>
<status>HTTP/1.1 200 OK</status>
</propstat>
</response>
</multistatus>
CalDAV: send(
http://web/calendar/caldav.php/test/home/): <?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>/calendar/caldav.php/test/home/aeafbdff-
ddc1-4ef8-936c-1cd762cbe848.ics</D:href>
</calendar-multiget>
CalDAV: Status 400 fetching calendar-data for calendar Test
CalDAV: Error: got status 400 fetching calendar data for Testnull
Warning: There has been an error reading data for calendar: Test. However,
this error is believed to be minor, so the program will attempt to continue.
Error code: 0x80004005. Description: CalDAV: Error: got status 400 fetching
calendar data for Testnull
Warning: There has been an error reading data for calendar: Test. However,
this error is believed to be minor, so the program will attempt to continue.
Error code: READ_FAILED. Description:
Here's a Wireshark capture of the TCP stream for the failing PROPFIND:
PROPFIND /calendar/caldav.php/test/home/ HTTP/1.1
Host: web
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1.5) Gecko/20100411
Calendar/1.0b1
Accept: text/xml
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: utf-8,*;q=0.1
Keep-Alive: 300
Connection: keep-alive
Content-Length: 166
Content-Type: text/xml; charset=utf-8
Depth: 1
Authorization: Basic dGVzdDp0ZXN0
Pragma: no-cache
Cache-Control: no-cache
<?xml version="1.0" encoding="UTF-8"?>
<D:propfind xmlns:D="DAV:">
<D:prop>
<D:getcontenttype/>
<D:resourcetype/>
<D:getetag/>
</D:prop>
</D:propfind>HTTP/1.1 207 Multi-Status
Date: Thu, 24 Jun 2010 16:38:56 GMT
Server: Apache/2.2.9 (Debian) mod_jk/1.2.26 PHP/5.2.6-1+lenny8 with Suhosin-
Patch mod_ssl/2.2.9 OpenSSL/0.9.8g mod_wsgi/2.5 Python/2.5.2
X-Powered-By: PHP/5.2.6-1+lenny8
DAV: 1, 2, access-control, calendar-access, calendar-schedule, extended-mkcol,
calendar-proxy, bind, calendar-auto-schedule
ETag: "97cdcec41aa2e6ad2b037470938a2cd7"
X-DAViCal-Version: DAViCal/0.9.9; DB/1.2.8
Content-Length: 844
Connection: close
Content-Type: text/xml; charset="utf-8"
<?xml version="1.0" encoding="utf-8" ?>
<multistatus xmlns="DAV:" xmlns:C="urn:ietf:params:xml:ns:caldav">
<response>
<href>/calendar/caldav.php/test/home/</href>
<propstat>
<prop>
<getcontenttype>httpd/unix-directory</getcontenttype>
<resourcetype>
<collection/>
<C:calendar/>
</resourcetype>
</prop>
<status>HTTP/1.1 200 OK</status>
</propstat>
<propstat>
<prop>
<getetag/>
</prop>
<status>HTTP/1.1 404 Not Found</status>
</propstat>
</response>
<response>
<href>/calendar/caldav.php/test/home/aeafbdff-
ddc1-4ef8-936c-1cd762cbe848.ics</href>
<propstat>
<prop>
<getcontenttype>text/calendar</getcontenttype>
<resourcetype/>
<getetag>"ae40dfe99ebb6ed226663e3b48ea90b0"</getetag>
</prop>
<status>HTTP/1.1 200 OK</status>
</propstat>
</response>
</multistatus>
I've run this with "$c->dbg['ALL'] = 1", looking for signs of strife. Omitting
the request and response logs (since they just duplicate the above), this
seems to be the processing bit of the request. I've highlighted a line that
looks possibly suspect to me.
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--><?xml version="1.0" encoding="UTF-8"?>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--><D:propfind xmlns:D="DAV:">
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--> <D:prop>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--> <D:getcontenttype/>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--> <D:resourcetype/>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--> <D:getetag/>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--> </D:prop>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
request:--></D:propfind>
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
caldav: Query: DBGQ: SELECT * FROM collection WHERE dav_name = :exact_name
ORDER BY LENGTH(dav_name) DESC LIMIT 1
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
caldav: Query: DBGQ: ":exact_name" => "/test/home/"
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
caldav: Query: DBGQ: Took: 0.005299 to find 1 rows.
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: ALL:
caldav: Collection '/test/home/' is 3, type calendar
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:Finding Principal from path: "/test/home/", options.allow_by_email:
""
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:Path split into at least /// test /// home ///
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
always: Query: DBGQ: SELECT *, to_char(updated at time zone 'GMT','Dy, DD Mon
IYYY HH24:MI:SS "GMT"') AS modified, principal.*,
pprivs(:session_principal::int8,principal.principal_id,:scan_depth::int) AS
privileges FROM usr LEFT JOIN principal USING(user_no) WH
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
always: Query: DBGQ: ERE lower(username) = lower(:param)
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
always: Query: DBGQ: ":session_principal" => "2"
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
always: Query: DBGQ: ":scan_depth" => "2"
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
always: Query: DBGQ: ":param" => "test"
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
always: Query: DBGQ: Took: 0.021887 to find 1 rows.
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: SELECT usr.username FROM group_member JOIN
principal ON (principal_id=group_id) JOIN usr USING(user_no) WHERE member_id =
:member_id UNION SELECT usr.username FROM group_member LEFT JOIN grants ON
(to_principal=group_id) JOIN principal ON (
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: principal_id=by_principal) JOIN usr
USING(user_no) WHERE member_id = :member_id and by_principal != member_id
ORDER BY 1
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: ":member_id" => "2"
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: Took: 0.011187 to find 0 rows.
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: ALL:
caldav:Full permissions for user accessing their own hierarchy
[Thu Jun 24 23:46:05 2010] [error] [client 192.168.129.128] bearcave: ALL:
caldav: Parsed incoming XML request body.
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
PROPFIND:method handler
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::FetchCollection: Looking for collection for "/test/home/".
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
DAVResource: Query: DBGQ: SELECT collection.*,
path_privs(:session_principal::int8, collection.dav_name,:scan_depth::int),
p.principal_id, p.type_id AS principal_type_id, p.displayname AS
principal_displayname, p.default_privileges AS principal_default_privileges, t
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
DAVResource: Query: DBGQ: ime_zone.tz_spec FROM collection LEFT JOIN principal
p USING (user_no) LEFT JOIN time_zone ON (collection.timezone=time_zone.tz_id)
WHERE collection.dav_name = :raw_path ORDER BY LENGTH(collection.dav_name)
DESC LIMIT 1
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
DAVResource: Query: DBGQ: ":raw_path" => "/test/home/"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
DAVResource: Query: DBGQ: ":session_principal" => "2"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
DAVResource: Query: DBGQ: ":scan_depth" => "2"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
DAVResource: Query: DBGQ: Took: 0.013778 to find 1 rows.
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::FetchCollection: Found collection named "/test/home/" of type
"calendar".
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::FromPath: Path "/test/home/" is
<DAV::collection/><urn:ietf:params:xml:ns:caldav:calendar/> a collection.
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource:Privileges of "111111111111111111111111" for user "test" accessing
"/test/home/"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource:Testing privileges of "DAV::read" (1) against allowed
"111111111111111111111111" => "1" (1)
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
PROPFIND:Getting collection contents: Depth 1, Path: /test/home/
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::RenderAsXML: Resource "/test/home/" exists(1)
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::GetPropStat: propstat for href "/test/home/"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
XMLDocument:auto-assigning prefix of 'C' for ns of
'urn:ietf:params:xml:ns:caldav'
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:Finding Principal from path: "/test/home/", options.allow_by_email:
""
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:Path split into at least /// test /// home ///
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: SELECT usr.username FROM group_member JOIN
principal ON (principal_id=group_id) JOIN usr USING(user_no) WHERE member_id =
:member_id UNION SELECT usr.username FROM group_member LEFT JOIN grants ON
(to_principal=group_id) JOIN principal ON (
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: principal_id=by_principal) JOIN usr
USING(user_no) WHERE member_id = :member_id and by_principal != member_id
ORDER BY 1
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: ":member_id" => "2"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
CalDAVPrincipal: Query: DBGQ: Took: 0.006638 to find 0 rows.
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
principal:: RenderAsXML: Principal Property "DAV::getetag"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
PROPFIND:Getting collection contents: Depth 0, Path: /test/home/, Bound from:
/test/home/
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource:Testing privileges of "DAV::read" (1) against allowed
"111111111111111111111111" => "1" (1)
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
PROPFIND:Getting collection items: Depth 0, Path: /test/home/
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource:Testing privileges of "all" (111111111111111111111111) against
allowed "111111111111111111111111" => "16777215" (111111111111111111111111)
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
PROPFIND: Query: DBGQ: SELECT collection.*, principal.*, calendar_item.*,
caldav_data.*, to_char(coalesce(calendar_item.created, caldav_data.created) at
time zone 'GMT','Dy, DD Mon IYYY HH24:MI:SS "GMT"') AS created,
to_char(last_modified at time zone 'GMT','Dy,
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
PROPFIND: Query: DBGQ: DD Mon IYYY HH24:MI:SS "GMT"') AS modified, summary AS
dav_displayname FROM caldav_data LEFT JOIN calendar_item USING( dav_id,
user_no, dav_name, collection_id) LEFT JOIN collection
USING(collection_id,user_no) LEFT JOIN principal USING(use
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
PROPFIND: Query: DBGQ: r_no) WHERE collection.dav_name = :collection_dav_name
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
PROPFIND: Query: DBGQ: ":collection_dav_name" => "/test/home/"
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: LOG:
PROPFIND: Query: DBGQ: Took: 0.012933 to find 1 rows.
** Is this expected?
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::FromRow: Named "/test/home/aeafbdff-
ddc1-4ef8-936c-1cd762cbe848.ics" is not a collection.
**
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::RenderAsXML: Resource "/test/home/aeafbdff-
ddc1-4ef8-936c-1cd762cbe848.ics" exists(1)
[Thu Jun 24 23:46:06 2010] [error] [client 192.168.129.128] bearcave: ALL:
DAVResource::GetPropStat: propstat for href "/test/home/aeafbdff-
ddc1-4ef8-936c-1cd762cbe848.ics"
--
Jim Hague - jim.hague at acm.org Never trust a computer you can't lift.