Hanging at SSL connection

[robinmayol]

Hello! Thank you for your time developing this library which I actually have been using unknowingly for a while via this project: https://github.com/greenorca/nextcloud_calcli. I decided to take it back one step and make my own script, and search engines led me here. Anyway, to the issue...

Failure mode: Blinking cursor forever (at least 30mn) when I run python calendar_fetch.py.

`calendar_fetch.py

import sys
from datetime import date
from datetime import datetime

sys.path.insert(0, "..")
sys.path.insert(0, ".")

import caldav

caldav_url = "https://posteo.de:8443"
username = "[email protected]"
password = "x"

with caldav.DAVClient(url=caldav_url, username=username, password=password) as client:
my_principal = client.principal()

calendars = my_principal.calendars()

events_fetched = my_new_calendar.search(
start=datetime(2021, 1, 1), end=datetime(2024, 1, 1),event=True, expand=True)

print(events_fetched)

`
I know I probably can't print the events like this but I was going to figure that part out once I got an output (I'm a sunday afternoon script kiddie).

This shows up if I press Ctrl+C

Traceback (most recent call last): File "/home/mrfry/dev_python/caldav/calendar_fetch.py", line 16, in <module> my_principal = client.principal() File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 412, in principal self._principal = Principal(client=self, *largs, **kwargs) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/objects.py", line 478, in __init__ cup = self.get_property(dav.CurrentUserPrincipal()) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/objects.py", line 210, in get_property foo = self.get_properties([prop], **passthrough) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/objects.py", line 235, in get_properties response = self._query_properties(props, depth) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/objects.py", line 171, in _query_properties return self._query(root, depth) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/objects.py", line 196, in _query ret = getattr(self.client, query_method)(url, body, depth) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 460, in propfind return self.request(url or self.url, "PROPFIND", props, {"Depth": str(depth)}) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 630, in request return self.request(url, method, body, headers) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 655, in request return self.request(url, method, body, headers) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 655, in request return self.request(url, method, body, headers) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 655, in request return self.request(url, method, body, headers) [Previous line repeated 28 more times] File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 583, in request r = self.session.request( File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/requests/sessions.py", line 587, in request resp = self.send(prep, **send_kwargs) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/requests/sessions.py", line 701, in send r = adapter.send(request, **kwargs) File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/requests/adapters.py", line 489, in send resp = conn.urlopen( File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/urllib3/connectionpool.py", line 703, in urlopen httplib_response = self._make_request( File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/urllib3/connectionpool.py", line 449, in _make_request six.raise_from(e, None) File "<string>", line 3, in raise_from File "/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/urllib3/connectionpool.py", line 444, in _make_request httplib_response = conn.getresponse() File "/usr/lib/python3.10/http/client.py", line 1374, in getresponse response.begin() File "/usr/lib/python3.10/http/client.py", line 318, in begin version, status, reason = self._read_status() File "/usr/lib/python3.10/http/client.py", line 279, in _read_status line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1") File "/usr/lib/python3.10/socket.py", line 705, in readinto return self._sock.recv_into(b) File "/usr/lib/python3.10/ssl.py", line 1274, in recv_into return self.read(nbytes, buffer) File "/usr/lib/python3.10/ssl.py", line 1130, in read return self._sslobj.read(len, buffer) KeyboardInterrupt
I also ran the whole thing with strace and I see reads and writes (the output updates about once a second) with some sort of hierarchy of numbers like "/37/2/406/..." and call to a library file that has to do with ssl certificates I imagine: certifi/cacert.pem. Not posted here in case it's sensitive information.

I'm not sure what to do!

[tobixen]

First ...

events_fetched = my_new_calendar.search(
start=datetime(2021, 1, 1), end=datetime(2024, 1, 1),event=True, expand=True)

Have you tried specifying a shorter time range, or tried to disable expand? It could be that the server is struggling to give an answer, perhaps there are too many recurring events?

The traceback doesn't say me much - if there is communication going on, it could be that the server is simply slow giving answers. Though, 30 minutes is a lot.

[robinmayol]

Cheers. I just tried from 2021/12/1 to 22/01/01 and expand=false and the same thing is happening. Did I specify the port number in the proper way in the url variable?

[tobixen]

I believe that it should work when specified like that, and it seems like I have test code covering it ...

     self.server_params = {"url": "http://%s:%i/" % (xandikos_host, xandikos_port)}

When it just hangs, it could be a firewall issue ... but then it's a bit strange to see reads and writes through strace.

Have you tried to access the URL using curl or wget?

Can you check with tcpdump that there is actually network traffic going both ways?

Do you see any activity in server logs?

Python debugger is probably more suitable than strace. According to the traceback, line 583 in /home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py is the last point from the caldav library. You may try to throw in import pdb; pdb.set_trace() before that line. Press "n" to execute one and one code line (or "s" to dive deeper). The useful information here would be if the very first web request hangs forever, or if there is any traffic forth and back. (checking now, I see that it fails already in the first communication with the calendar server, so it never gets to the point where the search request is sent - my previous suggestion to reduce the search span was hence pretty moot).

[robinmayol]

Hey Tobi,

I did turn off my firewall and my VPN in case they were the reason but without luck.

I ran tcpdump and used the debugger and I have pinpointed the hang to
> /usr/lib/python3.10/ssl.py(1343)do_handshake() -> self._sslobj.do_handshake()
(I proceeded by pressing next until it hanged then starting again, pressing s at the point where I got the hang before. I moved the debugger call to the hanging line in the appropriate file to not have to start from scratch everytime. Hope that's how it's supposed to be done.)

Here is the entire tcpdump. I made sure I had not other programs using the network while I did it.

tcpdump: verbose output suppressed, use -v[v]... for full protocol decode listening on wlo1, link-type EN10MB (Ethernet), snapshot length 262144 bytes 19:28:40.706045 IP blade.37898 > homerouter.cpe.domain: 60487+ [1au] AAAA? poste.de. (37) 19:28:40.706283 IP blade.36354 > done.poste.de.pcsync-https: Flags [S], seq 128509526, win 64240, options [mss 1460,sackOK,TS val 858849907 ecr 0,nop,wscale 7], length 0 19:28:40.762813 IP blade.50560 > homerouter.cpe.domain: 22255+ [1au] PTR? 1.8.168.192.in-addr.arpa. (53) 19:28:40.766193 IP done.poste.de.pcsync-https > blade.36354: Flags [S.], seq 3450094259, ack 128509527, win 29832, options [mss 1356,nop,wscale 8,nop,nop,sackOK], length 0 19:28:40.766234 IP blade.36354 > done.poste.de.pcsync-https: Flags [.], ack 1, win 502, length 0 19:28:40.766253 IP homerouter.cpe.domain > blade.37898: 60487 0/1/1 (107) 19:28:40.769521 IP homerouter.cpe.domain > blade.50560: 22255- 1/0/0 OPT UDPsize=1472 (81) 19:28:40.769745 IP blade.50560 > homerouter.cpe.domain: 55630+ PTR? 1.8.168.192.in-addr.arpa. (42) 19:28:40.779538 IP homerouter.cpe.domain > blade.50560: 55630- 1/0/0 PTR homerouter.cpe. (70) 19:28:40.779991 IP blade.41205 > homerouter.cpe.domain: 45598+ PTR? 170.8.168.192.in-addr.arpa. (44) 19:28:40.789551 IP homerouter.cpe.domain > blade.41205: 45598- 1/0/0 PTR blade. (63) 19:28:40.790221 IP blade.44186 > homerouter.cpe.domain: 47272+ [1au] PTR? 65.184.201.138.in-addr.arpa. (56) 19:28:40.790242 IP blade.40640 > homerouter.cpe.domain: 12275+ PTR? 65.184.201.138.in-addr.arpa. (45) 19:28:40.858713 IP homerouter.cpe.domain > blade.44186: 47272 1/0/1 PTR done.poste.de. (83) 19:28:40.858716 IP homerouter.cpe.domain > blade.40640: 12275 1/0/1 PTR done.poste.de. (83) 19:28:45.829143 ARP, Request who-has blade tell homerouter.cpe, length 28 19:28:45.829159 ARP, Reply blade is-at 5c:e4:2a:49:9b:20 (oui Unknown), length 28 19:29:02.044834 IP blade.36354 > done.poste.de.pcsync-https: Flags [P.], seq 1:518, ack 1, win 502, length 517 19:29:02.315756 IP done.poste.de.pcsync-https > blade.36354: Flags [.], ack 518, win 16395, length 0 19:29:04.055937 IP6 fe80::ee4:a0ff:fe22:abda > ff02::1:ff6b:57b: ICMP6, neighbor solicitation, who has fe80::14be:d525:4f6b:57b, length 32 19:29:04.122385 IP blade.46780 > homerouter.cpe.domain: 3800+ [1au] PTR? b.7.5.0.b.6.f.f.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.2.0.f.f.ip6.arpa. (101) 19:29:04.122682 IP blade.39154 > homerouter.cpe.domain: 33204+ PTR? b.7.5.0.b.6.f.f.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.2.0.f.f.ip6.arpa. (90) 19:29:04.772773 IP homerouter.cpe.domain > blade.39154: 33204 NXDomain 0/1/1 (165) 19:29:04.772773 IP homerouter.cpe.domain > blade.46780: 3800 NXDomain 0/1/1 (165) 19:29:04.772998 IP blade.46780 > homerouter.cpe.domain: 3800+ PTR? b.7.5.0.b.6.f.f.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.2.0.f.f.ip6.arpa. (90) 19:29:04.840276 IP homerouter.cpe.domain > blade.46780: 3800 NXDomain 0/1/0 (154)

The man page for openssl says

If the underlying BIO is blocking, SSL_do_handshake() will only return once the handshake has been finished or an error occurred.

So I'm trying to investigate this and figure out how to print the error if one occured.

Thanks again for your help and guidance with this. It's a good learning experience for me.

Edit: Formatting

[tobixen]

I ran tcpdump and used the debugger and I have pinpointed the hang to > /usr/lib/python3.10/ssl.py(1343)do_handshake() -> self._sslobj.do_handshake() (I proceeded by pressing next until it hanged then starting again, pressing s at the point where I got the hang before. I moved the debugger call to the hanging line in the appropriate file to not have to start from scratch everytime. Hope that's how it's supposed to be done.)

No idea how things are "supposed to be done", but I would have done the same :-)

Here is the entire tcpdump. I made sure I had not other programs using the network while I did it.

Traffic is flowing both ways, so probably not a firewall issue.

What happens if you visit https://posteo.de:8443/ in your browser? (If I do it, I get a login prompt - so whatever is there, it communicates https ... and it apparently runs some variant of sabredav, could be that it's nextcloud ...)

[tobixen]

I tried to register an account, but they want 12 EUR for that. Not a lot of money, but I'm not going to pay that just to test their caldav compliance :-)

[robinmayol]

No idea how things are "supposed to be done", but I would have done the same :-)
Hahaha! Comforting!

If I go to https://posteo.de:8443/ and fill the login prompt I actually get

<d:error> <s:exception>Sabre_DAV_Exception_NotImplemented</s:exception> <s:message>GET is only implemented on File objects</s:message> </d:error>
But I'm pretty sure that's normal. Thunderbird syncs successfully.

Yeah 12 euros will get you a year membership. It's basically a paying email service with green credentials. It's part of my degoogelisation masterplan :)

[robinmayol]

So when you mentioned Nextcloud I though, I do have my own Nextcloud instance, I should see if the same issue arises, then I can troubleshoot from the server side!
Sadly it works on my Nextcloud :) I'm happy just migrating even if I am very curious as to what is going on... I'll contact Posteo and see if they have any idea of what might be happening.

[tobixen]

Now I get 401 as I'm supposed to.

"/home/mrfry/dev_python/caldav/calendar_fetch/lib/python3.10/site-packages/caldav/davclient.py", line 655, in request return self.request(url, method, body, headers) [Previous line repeated 28 more times] File

Seems to be a recursion problem.

Could you try with some earlier versions of caldav, like v0.9.2?

[tobixen]

This logic was last changed in afdea80

[tobixen]

It doesn't make sense to me ... current code looks like this ...

    def request(...):
      (...)
        elif (
            r.status_code == 401
            and "WWW-Authenticate" in r.headers
            and self.password
            and self.username
            and self.auth
        ):
            (...)
            self.username = None
            self.password = None
            return self.request(url, method, body, headers)

... and your traceback hits the requests line on the bottom there repeatedly (it's probably a red herring that the problem stems from the SSL library ... it's probably rate-limits on the posteo-side that finally causes this to stop up).

However, since self.username and self.password is set to None there, that elif branch is not supposed to strike again.

The code is some explicit exception for sabre (nextcloud) when username and/or password contains UTF8-characters. Could you try to change your password to something containing only ascii?

[tobixen]

I think it's important to figure out of this ... and I have promised to make a new caldav release during the upcoming week.

There seems to be possible to create an account at posteo, choose a non-instant payment scheme, and then they do allow me to start using the account. It just feels wrong and dishonest ... but perhaps I should do that :-)

[tobixen]

I have registered an account with posteo now. Tests run fine (with some exceptions), I don't have any problems with connecting to the server ... but I choose a very plain password, will try to change it (though, the password policy forbids "umlauts" ... hm)

[robinmayol]

Hey Tobi, I just gave it another shot as well and it works on my side as well. I have no idea what happened, sorry for the trouble!

[tobixen]

It seems like this problem may be triggered by entering the wrong username and password. Will follow up in #295.