search

Kozea / Radicale

A simple CalDAV (calendar) and CardDAV (contact) server.
https://radicale.org
GNU General Public License v3.0
3.33k stars 430 forks source link

Error 500 not appearing in debug output #709

Closed corsac-s closed 5 days ago

corsac-s commented 7 years ago

Hi, I'm using radicale server 1.1.1+20160115-4 (from Debian stretch) and an evolution client (3.26.0 from Debian sid).

Following the evolution upgrade, I can successfully read calendars and address books, but I can't write to them. When trying that, evolution reports an error 500 from the server. I assume there's something fishy on the client side, but trying to debug on the radicale side, I find no trace of the error.

Example debug log on the client side:

> Soup-Debug-Timestamp: 1505819079
> Soup-Debug: EWebDAVSession 1 (0x7ff0600054d0), SoupMessage 5 (0x7ff07800eab0), SoupSocket 6 (0x7ff078008b30)
> Host: XXXX
> User-Agent: Evolution/3.26.0
> Connection: close
> Cache-Control: no-cache
> Pragma: no-cache
> Accept-Language: en-us, en;q=0.9
> Authorization: Basic [user:********]

< HTTP/1.0 404 Not Found
< Soup-Debug-Timestamp: 1505819079
< Soup-Debug: SoupMessage 5 (0x7ff07800eab0)
< Date: Tue, 19 Sep 2017 11:04:39 GMT
< Server: WSGIServer/0.1 Python/2.7.13
< Content-Length: 0
< 

> GET /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2 HTTP/1.1
> Soup-Debug-Timestamp: 1505819079
> Soup-Debug: EWebDAVSession 1 (0x7ff0600054d0), SoupMessage 6 (0x7ff07800e8d0), SoupSocket 7 (0x7ff078008a60)
> Host: xxxx
> User-Agent: Evolution/3.26.0
> Connection: close
> Cache-Control: no-cache
> Pragma: no-cache
> Accept-Language: en-us, en;q=0.9
> Authorization: Basic [user:********]

< HTTP/1.0 404 Not Found
< Soup-Debug-Timestamp: 1505819080
< Soup-Debug: SoupMessage 6 (0x7ff07800e8d0)
< Date: Tue, 19 Sep 2017 11:04:40 GMT
< Server: WSGIServer/0.1 Python/2.7.13
< Content-Length: 0
< 

> PUT /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics HTTP/1.1
> Soup-Debug-Timestamp: 1505819080
> Soup-Debug: EWebDAVSession 1 (0x7ff0600054d0), SoupMessage 7 (0x7ff07800e8d0), SoupSocket 8 (0x7ff0780088c0)
> Host: xxxx
> User-Agent: Evolution/3.26.0
> Connection: close
> Cache-Control: no-cache
> Pragma: no-cache
> If-None-Match: *
> Content-Type: text/calendar; charset="utf-8"
> Transfer-Encoding: chunked
> Accept-Language: en-us, en;q=0.9
> Authorization: Basic [user:********]

BEGIN:VCALENDAR
CALSCALE:GREGORIAN
PRODID:-//Ximian//NONSGML Evolution Calendar//EN
VERSION:2.0
BEGIN:VTIMEZONE
TZID:/freeassociation.sourceforge.net/Europe/Paris
X-LIC-LOCATION:Europe/Paris
BEGIN:STANDARD
TZNAME:CET
DTSTART:19701029T030000
RRULE:FREQ=YEARLY;BYDAY=-1SU;BYMONTH=10
TZOFFSETFROM:+0200
TZOFFSETTO:+0100
END:STANDARD
BEGIN:DAYLIGHT
TZNAME:CEST
DTSTART:19700326T020000
RRULE:FREQ=YEARLY;BYDAY=-1SU;BYMONTH=3
TZOFFSETFROM:+0100
TZOFFSETTO:+0200
END:DAYLIGHT
END:VTIMEZONE
BEGIN:VEVENT
UID:e108dce5f2a11134735e3aeef1b21943d5b667c2
DTSTAMP:20170919T095041Z
DTSTART;TZID=/freeassociation.sourceforge.net/Europe/Paris:
 20171024T090000
DTEND;TZID=/freeassociation.sourceforge.net/Europe/Paris:20171024T093000
SEQUENCE:2
SUMMARY:test
TRANSP:OPAQUE
CLASS:PUBLIC
CREATED:20170919T110440Z
LAST-MODIFIED:20170919T110440Z
END:VEVENT
END:VCALENDAR
< HTTP/1.0 500 Internal Server Error
< Soup-Debug-Timestamp: 1505819080
< Soup-Debug: SoupMessage 7 (0x7ff07800e8d0)
< Date: Tue, 19 Sep 2017 11:04:40 GMT
< Server: WSGIServer/0.1 Python/2.7.13
< Content-Type: text/plain
< Content-Length: 59
< 

A server error occurred.  Please contact the administrator.

On the server side, I get:

2017-09-19 13:04:39,693 - INFO: GET request at /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics received
2017-09-19 13:04:39,704 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/plain',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT_LANGUAGE': 'en-us, en;q=0.9',
 'HTTP_AUTHORIZATION': 'Basic XXXX',
 'HTTP_CACHE_CONTROL': 'no-cache',
 'HTTP_CONNECTION': 'close',
 'HTTP_HOST': 'xxxx',
 'HTTP_PRAGMA': 'no-cache',
 'HTTP_USER_AGENT': 'Evolution/3.26.0',
 'PATH_INFO': '/user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics',
 'QUERY_STRING': '',
 'REMOTE_ADDR': 'xxx.xxx.xxx.xxx',
 'REMOTE_HOST': '',
 'REQUEST_METHOD': 'GET',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'xxxx',
 'SERVER_PORT': 'xxxx',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.13',
 'wsgi.errors': <open file '<stderr>', mode 'w' at 0x7f52b024c1e0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x7f52ae4d7bb0>,
 'wsgi.input': <socket._fileobject object at 0x7f52ae455ed0>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2017-09-19 13:04:39,705 - DEBUG: Sanitized path: /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics
2017-09-19 13:04:39,706 - DEBUG: Reading rights from file /srv/sync/.config/radicale/rights
2017-09-19 13:04:39,706 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^shared(/.*)?$' from section 'shared'
2017-09-19 13:04:39,707 - DEBUG: Section 'shared' does not match
2017-09-19 13:04:39,707 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^user(/.*)?$' from section 'rw'
2017-09-19 13:04:39,707 - DEBUG: Section 'rw' matches
2017-09-19 13:04:39,707 - DEBUG: user has read access to collection user/calendar.ics/
2017-09-19 13:04:39,708 - DEBUG: Reading rights from file /srv/sync/.config/radicale/rights
2017-09-19 13:04:39,709 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^shared(/.*)?$' from section 'shared'
2017-09-19 13:04:39,709 - DEBUG: Section 'shared' does not match
2017-09-19 13:04:39,709 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^user(/.*)?$' from section 'rw'
2017-09-19 13:04:39,710 - DEBUG: Section 'rw' matches
2017-09-19 13:04:39,710 - DEBUG: user has write access to collection user/calendar.ics/
2017-09-19 13:04:39,965 - DEBUG: Answer status: 404 Not Found
2017-09-19 13:04:40,005 - INFO: GET request at /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2 received
2017-09-19 13:04:40,015 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/plain',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT_LANGUAGE': 'en-us, en;q=0.9',
 'HTTP_AUTHORIZATION': 'Basic XXXX',
 'HTTP_CACHE_CONTROL': 'no-cache',
 'HTTP_CONNECTION': 'close',
 'HTTP_HOST': 'xxxx',
 'HTTP_PRAGMA': 'no-cache',
 'HTTP_USER_AGENT': 'Evolution/3.26.0',
 'PATH_INFO': '/user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2',
 'QUERY_STRING': '',
 'REMOTE_ADDR': 'XXX.XXX.XXX.XXX',
 'REMOTE_HOST': '',
 'REQUEST_METHOD': 'GET',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'xxxx',
 'SERVER_PORT': 'xxxx',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.13',
 'wsgi.errors': <open file '<stderr>', mode 'w' at 0x7f52b024c1e0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x7f52ae4d7bb0>,
 'wsgi.input': <socket._fileobject object at 0x7f52ae455ed0>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2017-09-19 13:04:40,016 - DEBUG: Sanitized path: /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2
2017-09-19 13:04:40,017 - DEBUG: Reading rights from file /srv/sync/.config/radicale/rights
2017-09-19 13:04:40,017 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^shared(/.*)?$' from section 'shared'
2017-09-19 13:04:40,017 - DEBUG: Section 'shared' does not match
2017-09-19 13:04:40,018 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^user(/.*)?$' from section 'rw'
2017-09-19 13:04:40,018 - DEBUG: Section 'rw' matches
2017-09-19 13:04:40,018 - DEBUG: user has read access to collection user/calendar.ics/
2017-09-19 13:04:40,018 - DEBUG: Reading rights from file /srv/sync/.config/radicale/rights
2017-09-19 13:04:40,019 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^shared(/.*)?$' from section 'shared'
2017-09-19 13:04:40,019 - DEBUG: Section 'shared' does not match
2017-09-19 13:04:40,020 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^user(/.*)?$' from section 'rw'
2017-09-19 13:04:40,020 - DEBUG: Section 'rw' matches
2017-09-19 13:04:40,020 - DEBUG: user has write access to collection user/calendar.ics/
2017-09-19 13:04:40,293 - DEBUG: Answer status: 404 Not Found
2017-09-19 13:04:40,340 - INFO: PUT request at /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics received
2017-09-19 13:04:40,349 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/calendar; charset="utf-8"',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT_LANGUAGE': 'en-us, en;q=0.9',
 'HTTP_AUTHORIZATION': 'Basic XXXXXX',
 'HTTP_CACHE_CONTROL': 'no-cache',
 'HTTP_CONNECTION': 'close',
 'HTTP_HOST': 'xxxx',
 'HTTP_IF_NONE_MATCH': '*',
 'HTTP_PRAGMA': 'no-cache',
 'HTTP_TRANSFER_ENCODING': 'chunked',
 'HTTP_USER_AGENT': 'Evolution/3.26.0',
 'PATH_INFO': '/user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics',
 'QUERY_STRING': '',
 'REMOTE_ADDR': 'XXX.XXX.XXX.XXX',
 'REMOTE_HOST': '',
 'REQUEST_METHOD': 'PUT',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'xxxx',
 'SERVER_PORT': 'xxxx',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.13',
 'wsgi.errors': <open file '<stderr>', mode 'w' at 0x7f52b024c1e0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x7f52ae4d7bb0>,
 'wsgi.input': <socket._fileobject object at 0x7f52ae455ed0>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2017-09-19 13:04:40,350 - DEBUG: Sanitized path: /user/calendar.ics/e108dce5f2a11134735e3aeef1b21943d5b667c2.ics
2017-09-19 13:04:40,350 - DEBUG: Reading rights from file /srv/sync/.config/radicale/rights
2017-09-19 13:04:40,351 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^shared(/.*)?$' from section 'shared'
2017-09-19 13:04:40,352 - DEBUG: Section 'shared' does not match
2017-09-19 13:04:40,352 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^user(/.*)?$' from section 'rw'
2017-09-19 13:04:40,352 - DEBUG: Section 'rw' matches
2017-09-19 13:04:40,352 - DEBUG: user has read access to collection user/calendar.ics/
2017-09-19 13:04:40,353 - DEBUG: Reading rights from file /srv/sync/.config/radicale/rights
2017-09-19 13:04:40,354 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^shared(/.*)?$' from section 'shared'
2017-09-19 13:04:40,354 - DEBUG: Section 'shared' does not match
2017-09-19 13:04:40,354 - DEBUG: Test if 'user:user/calendar.ics' matches against '.+:^user(/.*)?$' from section 'rw'
2017-09-19 13:04:40,354 - DEBUG: Section 'rw' matches
2017-09-19 13:04:40,355 - DEBUG: user has write access to collection user/calendar.ics/

And nothing after the last line. I can't spot anything wrong there so I'm unsure where the error 500 comes from, which would really help in debugging the client part.

Unrud commented 7 years ago

I'm unsure where the error 500 comes

Logging in Radicale 1.x.x was unreliable. It probably wrote the error message to stderr. Try to update to version 2.x.x.

corsac-s commented 7 years ago

Upgrading is not really an option here. I tried to run radicale using: radicale -f -D

but nothing happens on stdout/stderr. Is there something more I need to do?

Unrud commented 7 years ago

Is there something more I need to do?

No, that should be enough. Did A server error occurred. Please contact the administrator. appear in the client log, again?

detrout commented 7 years ago

I just had this problem of evolution not being able to change a calendar entry on Debian as well

Evolution 3.26.0-1 Radicale: 1.1.1+20160115-4 (I'm guessing Debian backported some patches)

My apache error logs may have a useful error:

[client 131.215.54.62:49808] Received request requiring chunked transfer encoding, but optional support for chunked transfer encoding has not been enabled.: /var/lib/radicale/radicale.wsgi

I do see chunked mentioned in the logs above, and found some other web posts that chunked mode doesn't work well with WSGI.

corsac-s commented 7 years ago

I don't think I'm using WSGI, I'm using radicale directly so it handles everything HTTP related, afaict. But maybe the issue is still related to chunked encoding.

Unrud commented 7 years ago

I do see chunked mentioned in the logs above, and found some other web posts that chunked mode doesn't work well with WSGI.

I haven't noticed that. Radicale's built-in web server uses the WSGI reference implementation from Python's standard library. It only supports HTTP/1.0, Transfer-Encoding was introduced in HTTP/1.1. The client shouldn't use it, unless it made sure that the server supports HTTP/1.1.

You have to use another WSGI server, that supports HTTP/1.1.

corsac-s commented 7 years ago

Radicale's built-in web server uses the WSGI reference implementation from Python's standard library. It only supports HTTP/1.0, Transfer-Encoding was introduced in HTTP/1.1. The client shouldn't use it, unless it made sure that the server supports HTTP/1.1.

Well, I guess I can work with that and report that to evolution (actually I think it might be to glib-networking or libcurl, not sure).

detrout commented 7 years ago

I got some logging out of evolution and here's the put when I tried to update an event.

> PUT /user/calendar.ics/12345678-1234-1234-1234-1234567890ab.ics HTTP/1.1
> Soup-Debug-Timestamp: 1506551337
> Soup-Debug: EWebDAVSession 1 (0x56386cf95dd0), SoupMessage 4 (0x7f77947a14a0),
 SoupSocket 5 (0x7f77946bf370)
> Host: cal.example.com
> User-Agent: Evolution/3.26.0
> Connection: close
> Cache-Control: no-cache
> Pragma: no-cache
> If-Match: "4793972f593deb0487268e53f599ccc7"
> Content-Type: text/calendar; charset="utf-8"
> Transfer-Encoding: chunked
> Accept-Language: en-us, en;q=0.9
> Authorization: Basic [user:********]

<Then new vcard data>
< HTTP/1.1 411 Length Required
< Soup-Debug-Timestamp: 1506551337
< Soup-Debug: SoupMessage 4 (0x7f77947a14a0)
< Date: Wed, 27 Sep 2017 22:28:58 GMT
< Server: Apache/2.4.25 (Debian)
< Content-Length: 317
< Connection: close
< Content-Type: text/html; charset=iso-8859-1
< 

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>411 Length Required</title>
</head><body>
<h1>Length Required</h1>
<p>A request of the requested method PUT requires a valid Content-length.<br />
</p>
<hr>
<address>Apache/2.4.25 (Debian) Server at cal.example.com Port 443</address>
</body></html>

Technically Transfer-Encoding: chunked is part of the HTTP/1.1 spec.

WSGI (or its replacement) probably should be updated to support it. On the other hand evolution seems like it should know the content-length, so why isn't it setting it?

corsac-s commented 7 years ago

I'm not really fluent enough in HTTP protocol, but evolution (or libsoup) starts with OPTIONS /foo.ics HTTP/1.1 and radicale always reply with HTTP/1.0 200 OK so maybe at one point libsoup should understand that the server can't do HTTP/1.1 and fall back to 1.0

corsac-s commented 7 years ago

I dug a bit more and found https://bugzilla.gnome.org/show_bug.cgi?id=787656 which is now fixed in evolution-data-server git tree (85543d3993a24e41c8b7fdaac53799a9cca71fe2)

detrout commented 7 years ago

@corsac-s Hi, I forwarded the gnome bugzilla link to Debian, https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=877145 I'll see if I I can get a release incorporating it.

corsac-s commented 7 years ago

On Fri, 2017-09-29 at 15:15 +0000, Diane Trout wrote:

@corsac-s Hi, I forwarded the gnome bugzilla link to Debian, https://bugs.de bian.org/cgi-bin/bugreport.cgi?bug=877145 I'll see if I I can get a release incorporating it.

Thanks @detrout / Diane. I actually talked to Jeremy about that and e-d-s 3.26.1 release (including the fix) is expected next Monday, and he should be able to do an upload to Debian sid in the same timeframe.

Regards, -- Yves-Alexis

detrout commented 7 years ago

Awesome. Thank you.

pbiering commented 5 days ago

closed because of very old version