search

Kozea / Radicale

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

CardDAV-Sync communicate with Radicale too slow #82

Closed yuq closed 11 years ago

yuq commented 11 years ago

I tried to use CardDAV-Sync with Radicale, it works but very slow. I see the DEBUG log that Radicale print out and find two request from client are always delayed by 5 seconds.

And I also use Wireshark to monitor the same communication, it seems the Radicale side will delay 15 seconds to respond client for a request.

So I'm wondering what happened in Radicale and how can I drop the delay to make the sync not so painful.

2013-11-18 13:50:25,970 - INFO: Starting Radicale hahaha
2013-11-18 13:50:25,970 - DEBUG: Authentication type is htpasswd
2013-11-18 13:50:25,971 - DEBUG: Rights type is owner_only
2013-11-18 13:50:25,973 - DEBUG: Base URL prefix: /
2013-11-18 13:50:25,973 - DEBUG: Listening to yuq-Vostro-270 port 5232
2013-11-18 13:50:25,974 - DEBUG: Radicale server ready
2013-11-18 13:50:51,747 - INFO: PROPFIND request at /admin/address.vcf/ received
2013-11-18 13:50:51,749 - DEBUG: Request headers:
{'CONTENT_LENGTH': '123',
 'CONTENT_TYPE': 'application/xml; charset="utf-8"',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT_ENCODING': 'gzip',
 'HTTP_CACHE_CONTROL': 'no-cache',
 'HTTP_CONNECTION': 'Keep-Alive',
 'HTTP_DEPTH': '0',
 'HTTP_HOST': '192.168.1.123:5232',
 'HTTP_PRAGMA': 'no-cache',
 'HTTP_USER_AGENT': 'CardDAV-Sync (Android) (like iOS/5.0.1 (9A405) dataaccessd/1.0) gzip',
 'PATH_INFO': '/admin/address.vcf/',
 'QUERY_STRING': '',
 'REMOTE_ADDR': '192.168.1.118',
 'REMOTE_HOST': '',
 'REQUEST_METHOD': 'PROPFIND',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'yuq-Vostro-270',
 'SERVER_PORT': '5232',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.3',
 'wsgi.errors': <open file '/dev/null', mode 'w' at 0x9820bd0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x9768ddc>,
 'wsgi.input': <socket._fileobject object at 0x988102c>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2013-11-18 13:50:51,749 - DEBUG: Sanitized path: /admin/address.vcf/
2013-11-18 13:50:51,749 - DEBUG: Request content:
<?xml version="1.0" encoding="utf-8" ?><A:propfind xmlns:A="DAV:"><A:prop><A:current-user-principal/></A:prop></A:propfind>
2013-11-18 13:50:51,750 - INFO: Anonymous user refused
2013-11-18 13:50:51,750 - DEBUG: Answer status: 401 Unauthorized
2013-11-18 13:50:56,889 - INFO: PROPFIND request at /admin/address.vcf/ received
2013-11-18 13:50:56,891 - DEBUG: Request headers:
{'CONTENT_LENGTH': '123',
 'CONTENT_TYPE': 'application/xml; charset="utf-8"',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT_ENCODING': 'gzip',
 'HTTP_AUTHORIZATION': 'Basic YWRtaW46YWRtaW4=',
 'HTTP_CACHE_CONTROL': 'no-cache',
 'HTTP_CONNECTION': 'Keep-Alive',
 'HTTP_DEPTH': '0',
 'HTTP_HOST': '192.168.1.123:5232',
 'HTTP_PRAGMA': 'no-cache',
 'HTTP_USER_AGENT': 'CardDAV-Sync (Android) (like iOS/5.0.1 (9A405) dataaccessd/1.0) gzip',
 'PATH_INFO': '/admin/address.vcf/',
 'QUERY_STRING': '',
 'REMOTE_ADDR': '192.168.1.118',
 'REMOTE_HOST': '',
 'REQUEST_METHOD': 'PROPFIND',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'yuq-Vostro-270',
 'SERVER_PORT': '5232',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.3',
 'wsgi.errors': <open file '/dev/null', mode 'w' at 0x9820bd0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x9768ddc>,
 'wsgi.input': <socket._fileobject object at 0x988102c>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2013-11-18 13:50:56,891 - DEBUG: Sanitized path: /admin/address.vcf/
2013-11-18 13:50:56,891 - DEBUG: Request content:
<?xml version="1.0" encoding="utf-8" ?><A:propfind xmlns:A="DAV:"><A:prop><A:current-user-principal/></A:prop></A:propfind>
2013-11-18 13:50:56,892 - DEBUG: admin has read access to collection admin/address.vcf/
2013-11-18 13:50:56,892 - DEBUG: admin has write access to collection admin/address.vcf/
2013-11-18 13:50:56,894 - DEBUG: Response content:
<?xml version="1.0"?>
<multistatus xmlns="DAV:">
  <response>
    <href>/admin/address.vcf/</href>
    <propstat>
      <prop>
        <current-user-principal>
          <href>/admin/</href>
        </current-user-principal>
      </prop>
      <status>HTTP/1.1 200 OK</status>
    </propstat>
  </response>
</multistatus>

2013-11-18 13:50:56,894 - DEBUG: Answer status: 207 Unknown

screenshot from 2013-11-18 15 00 51

liZe commented 11 years ago

That's strange. Do you have the same delay with a simple browser or wget when you try to access to http://192.168.1.123:5232/ ?

yuq commented 11 years ago

No, seem not. here is the log for a browser to access it, the 3 sec delay is for me to enter username and password.

2013-11-18 15:34:26,363 - INFO: GET request at / received
2013-11-18 15:34:26,365 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/plain',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT': 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
 'HTTP_ACCEPT_ENCODING': 'gzip, deflate',
 'HTTP_ACCEPT_LANGUAGE': 'zh-cn,zh;q=0.8,en-us;q=0.5,en;q=0.3',
 'HTTP_CONNECTION': 'keep-alive',
 'HTTP_HOST': 'localhost:5232',
 'HTTP_USER_AGENT': 'Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0',
 'PATH_INFO': '/',
 'QUERY_STRING': '',
 'REMOTE_ADDR': '127.0.0.1',
 'REMOTE_HOST': 'localhost',
 'REQUEST_METHOD': 'GET',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'yuq-Vostro-270',
 'SERVER_PORT': '5232',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.3',
 'wsgi.errors': <open file '/dev/null', mode 'w' at 0x9820bd0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x9768ddc>,
 'wsgi.input': <socket._fileobject object at 0x988102c>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2013-11-18 15:34:26,365 - DEBUG: Sanitized path: /
2013-11-18 15:34:26,365 - INFO: Anonymous user refused
2013-11-18 15:34:26,365 - DEBUG: Answer status: 401 Unauthorized
2013-11-18 15:34:29,527 - INFO: GET request at / received
2013-11-18 15:34:29,528 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/plain',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT': 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
 'HTTP_ACCEPT_ENCODING': 'gzip, deflate',
 'HTTP_ACCEPT_LANGUAGE': 'zh-cn,zh;q=0.8,en-us;q=0.5,en;q=0.3',
 'HTTP_AUTHORIZATION': 'Basic YWRtaW46YWRtaW4=',
 'HTTP_CONNECTION': 'keep-alive',
 'HTTP_HOST': 'localhost:5232',
 'HTTP_USER_AGENT': 'Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0',
 'PATH_INFO': '/',
 'QUERY_STRING': '',
 'REMOTE_ADDR': '127.0.0.1',
 'REMOTE_HOST': 'localhost',
 'REQUEST_METHOD': 'GET',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'yuq-Vostro-270',
 'SERVER_PORT': '5232',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.3',
 'wsgi.errors': <open file '/dev/null', mode 'w' at 0x9820bd0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x9768ddc>,
 'wsgi.input': <socket._fileobject object at 0x988102c>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2013-11-18 15:34:29,528 - DEBUG: Sanitized path: /
2013-11-18 15:34:29,528 - DEBUG: admin has NO read access to collection /
2013-11-18 15:34:29,528 - DEBUG: admin has NO write access to collection /
2013-11-18 15:34:29,528 - DEBUG: Answer status: 403 Forbidden
2013-11-18 15:34:29,757 - INFO: GET request at /favicon.ico received
2013-11-18 15:34:29,758 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/plain',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT': 'image/png,image/*;q=0.8,*/*;q=0.5',
 'HTTP_ACCEPT_ENCODING': 'gzip, deflate',
 'HTTP_ACCEPT_LANGUAGE': 'zh-cn,zh;q=0.8,en-us;q=0.5,en;q=0.3',
 'HTTP_AUTHORIZATION': 'Basic YWRtaW46YWRtaW4=',
 'HTTP_CONNECTION': 'keep-alive',
 'HTTP_HOST': 'localhost:5232',
 'HTTP_USER_AGENT': 'Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0',
 'PATH_INFO': '/favicon.ico',
 'QUERY_STRING': '',
 'REMOTE_ADDR': '127.0.0.1',
 'REMOTE_HOST': 'localhost',
 'REQUEST_METHOD': 'GET',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'yuq-Vostro-270',
 'SERVER_PORT': '5232',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.3',
 'wsgi.errors': <open file '/dev/null', mode 'w' at 0x9820bd0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x9768ddc>,
 'wsgi.input': <socket._fileobject object at 0x988102c>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2013-11-18 15:34:29,759 - DEBUG: Sanitized path: /favicon.ico
2013-11-18 15:34:29,759 - DEBUG: admin has NO read access to collection /
2013-11-18 15:34:29,759 - DEBUG: admin has NO write access to collection /
2013-11-18 15:34:29,759 - DEBUG: Answer status: 403 Forbidden
2013-11-18 15:34:29,787 - INFO: GET request at /favicon.ico received
2013-11-18 15:34:29,788 - DEBUG: Request headers:
{'CONTENT_LENGTH': '',
 'CONTENT_TYPE': 'text/plain',
 'GATEWAY_INTERFACE': 'CGI/1.1',
 'HTTP_ACCEPT': 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8',
 'HTTP_ACCEPT_ENCODING': 'gzip, deflate',
 'HTTP_ACCEPT_LANGUAGE': 'zh-cn,zh;q=0.8,en-us;q=0.5,en;q=0.3',
 'HTTP_AUTHORIZATION': 'Basic YWRtaW46YWRtaW4=',
 'HTTP_CONNECTION': 'keep-alive',
 'HTTP_HOST': 'localhost:5232',
 'HTTP_USER_AGENT': 'Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0',
 'PATH_INFO': '/favicon.ico',
 'QUERY_STRING': '',
 'REMOTE_ADDR': '127.0.0.1',
 'REMOTE_HOST': 'localhost',
 'REQUEST_METHOD': 'GET',
 'SCRIPT_NAME': '',
 'SERVER_NAME': 'yuq-Vostro-270',
 'SERVER_PORT': '5232',
 'SERVER_PROTOCOL': 'HTTP/1.1',
 'SERVER_SOFTWARE': 'WSGIServer/0.1 Python/2.7.3',
 'wsgi.errors': <open file '/dev/null', mode 'w' at 0x9820bd0>,
 'wsgi.file_wrapper': <class wsgiref.util.FileWrapper at 0x9768ddc>,
 'wsgi.input': <socket._fileobject object at 0x988102c>,
 'wsgi.multiprocess': False,
 'wsgi.multithread': True,
 'wsgi.run_once': False,
 'wsgi.url_scheme': 'http',
 'wsgi.version': (1, 0)}
2013-11-18 15:34:29,788 - DEBUG: Sanitized path: /favicon.ico
2013-11-18 15:34:29,788 - DEBUG: admin has NO read access to collection /
2013-11-18 15:34:29,788 - DEBUG: admin has NO write access to collection /
2013-11-18 15:34:29,788 - DEBUG: Answer status: 403 Forbidden
yuq commented 11 years ago

It only happens for CardDAV-Sync. I have tested libcarddav, it's OK.

yuq commented 11 years ago

But, from wireshark, it's Radicale who hold the communication process for a while (response for 5 sec delay). Here is the Wireshark result.

screenshot from 2013-11-18 16 10 22

liZe commented 11 years ago

Can you check the CPU to find if Radicale is actually doing something during these 5 seconds?

yuq commented 11 years ago

I have checked the Radicale process CPU usage, almost 0% when the CardDAV-Sync is communicating with Radicale. The total CPU usage is also very low.

liZe commented 11 years ago

OK, so that's probably a problem related to the network. As Radicale is using the default Python HTTP server, and as the problem only happens with CalDAV-Sync, I'm pretty sure that the problem comes from CalDAV-Sync.

If the 5s delay is always the same, there's probably a timeout in the server or in the client. It may be caused by a request with a bad content-length header, or something similar. I've met other network-related problems causing strange delays (IPv6 or DNS resolution for example), but they're related to the computer configuration and are not directly caused by the software.

I close the bug for now, feel free to re-open it if you have any clues about something wrong in Radicale.

yuq commented 11 years ago

Do you think if the HTTP headers (like keep alive) will cause this problem?

christophdb commented 9 years ago

Hi, I had the same issue and tried everything: Firewall, other port, other radicale version... In the end I only had to change in the /etc/radicale/config the value "DNS_LOOKUP=False". Please try that. Best regards Christoph