URLError: <urlopen error ('_ssl.c:710: The handshake operation timed out',)>

[dagwieers]

Describe the bug

I just got this error while testing the MNM stream

2019-05-06 16:52:02.405 T:1732186992   ERROR: EXCEPTION Thrown (PythonToCppException) : -->Python callback/script returned the following error<--
                                             - NOTE: IGNORING THIS CAN LEAD TO MEMORY LEAKS!
                                            Error Type: <class 'urllib2.URLError'>
                                            Error Contents: <urlopen error ('_ssl.c:710: The handshake operation timed out',)>
                                            Traceback (most recent call last):
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/addon.py", line 62, in <module>
                                                router(sys.argv[2][1:])
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/addon.py", line 56, in router
                                                vrt_player.play(params)
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/vrtplayer.py", line 184, in play
                                                stream = stream_service.get_stream(params)
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/streamservice.py", line 193, in get_stream
                                                video_json = self._get_video_json(api_data)
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/streamservice.py", line 141, in _get_video_json
                                                playertoken = self.token_resolver.get_live_playertoken(token_url, api_data.xvrttoken)
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/tokenresolver.py", line 58, in get_live_playertoken
                                                token = self._get_new_playertoken(token_path, token_url, headers)
                                              File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/tokenresolver.py", line 79, in _get_new_playertoken
                                                playertoken = json.loads(urlopen(req).read())
                                              File "/usr/lib/python2.7/urllib2.py", line 154, in urlopen
                                              File "/usr/lib/python2.7/urllib2.py", line 429, in open
                                              File "/usr/lib/python2.7/urllib2.py", line 447, in _open
                                              File "/usr/lib/python2.7/urllib2.py", line 407, in _call_chain
                                              File "/usr/lib/python2.7/urllib2.py", line 1241, in https_open
                                              File "/usr/lib/python2.7/urllib2.py", line 1198, in do_open
                                            URLError: <urlopen error ('_ssl.c:710: The handshake operation timed out',)>
                                            -->End of Python script error report<--

[dagwieers]

I would expect that requests would retry in some of the failure scenarios.

[mediaminister]

That's right, but in the previous version requests got also timeouts. We can't fix bad internet.

[dagwieers]

It happened again today a few times, and I have never seen this before myself that I can remember.
This time it happened in succession.

[mediaminister]

I can't reproduce this issue. Does this only occur with _get_new_playertoken function?
I made a tryfix where I changed the way the POST request is defined, maybe this fixes it.

[dagwieers]

The problem is that this is not easily reproduced. I haven't been collecting all the occurrences as I assumed it happened everywhere, but I should have some in my logs. Only one of my systems has not been rebooted since.

This one happened once:

  File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/tokenresolver.py", line 58, in get_live_playertoken
    token = self._get_new_playertoken(token_path, token_url, headers)
  File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/tokenresolver.py", line 79, in _get_new_playertoken
    playertoken = json.loads(urlopen(req).read())

This one 4 times in quick succession (I remember trying a few times):

  File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/streamservice.py", line 95, in _get_api_data
    api_data = self._webscrape_api_data(video_url) or apidata.ApiData(self._CLIENT, self._VUALTO_API_URL, video_id, '', None, True)
  File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/streamservice.py", line 101, in _webscrape_api_data
    html_page = urlopen(video_url).read()

I am almost certain that in the second case the problem was related to the service, and not a local network issue.

[dagwieers]

Now the first time I have seen this: SSLError: ('The read operation timed out',)

  File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/tokenresolver.py", l
ine 67, in get_xvrttoken
    token = self._get_new_xvrttoken(token_path, get_roaming_token)
  File "/storage/.kodi/addons/plugin.video.vrt.nu/resources/lib/vrtplayer/tokenresolver.py", l
ine 116, in _get_new_xvrttoken
    logon_json = json.loads(urlopen(req).read())

Happened a few times when trying to play a stream.

[dagwieers]

I have not seen any incidents anymore myself, but let's keep this issue open a bit longer.
Since v1.9.0 has not been released to the Kodi repository not a lot of people had a chance to test this out.

[mediaminister]

I never ever got such an error. I really think it's related to a bad internet connection.

[dagwieers]

@mediaminister What do we consider "a bad internet connection" ? IMO these were caused by issues at VRT infrastructure. I have also experienced a stream that stopped during playback, in one case the stream was unavailable for about 5 minutes before things worked again. Since I also do radio streaming continuously when I am working, I doubt I have an Internet connectivity issue.

In any case, I haven't seen this ever before we switched to urllib2, so IMO Requests is more mature in handling these issues (whatever the cause).

[mediaminister]

I consider failing requests caused by issues at IP level (client, ISP or server) as "bad internet".
Please provide a full debug log when this happens again.

[dagwieers]

Sure, the problem is that it is not quite reproducible, but if it happens again for a longer period I'll try to troubleshoot. Again, I doubt it's related to the stuff I control myself. That said, I plan to look into injecting intermittent faults in my network with the intent of looking how the plugin behaves. But even for this it may be hard to reproduce the exact same issues, let alone have it automated.

Version 1.9.0 has been released, we'll see if people report similar things.

[dagwieers]

Ok, I haven't seen this once since those incidents. Let's close it and I'll look into injecting intermittent failures to make our plugin survive them better.

[dagwieers]

And now I have seen this issue in TravisCI: https://travis-ci.org/pietje666/plugin.video.vrt.nu/jobs/535568744

======================================================================
ERROR: test_search_journaal_page2 (__main__.TestSearch)
Test for journaal
----------------------------------------------------------------------
Traceback (most recent call last):
  File "test/searchtests.py", line 36, in test_search_journaal_page2
    search_items, sort, ascending, content = self._apihelper.search('journaal', page=2)
  File "/home/travis/build/pietje666/plugin.video.vrt.nu/resources/lib/vrtplayer/vrtapihelper.py", line 386, in search
    api_json = json.load(urlopen(api_url))
  File "/opt/python/2.7.15/lib/python2.7/urllib2.py", line 154, in urlopen
    return opener.open(url, data, timeout)
  File "/opt/python/2.7.15/lib/python2.7/urllib2.py", line 429, in open
    response = self._open(req, data)
  File "/opt/python/2.7.15/lib/python2.7/urllib2.py", line 447, in _open
    '_open', req)
  File "/opt/python/2.7.15/lib/python2.7/urllib2.py", line 407, in _call_chain
    result = func(*args)
  File "/opt/python/2.7.15/lib/python2.7/urllib2.py", line 1241, in https_open
    context=self._context)
  File "/opt/python/2.7.15/lib/python2.7/urllib2.py", line 1198, in do_open
    raise URLError(err)
URLError: <urlopen error [SSL: SSLV3_ALERT_HANDSHAKE_FAILURE] sslv3 alert handshake failure (_ssl.c:726)>

[mediaminister]

All #817 builds passed in the TravisCI cloud, I don't find that ERROR there.
Maybe you got that error on your local machine?

[dagwieers]

No, I did a rebuild so the project shows the build is passing. It did fail in TravisCI.

[dagwieers]

Alright, no incidents, no progress. Closing this again...

[gustawdaniel]

This is problem of internet connection, no problem of this package. I have the same error in other tool:

$ speedtest
Retrieving speedtest.net configuration...
Cannot retrieve speedtest configuration
ERROR: <urlopen error _ssl.c:835: The handshake operation timed out>

If something can be done in code of this package this is handling of bad internet problems.

[dagwieers]

@gustawdaniel If you intend to build a reliable solution, there are two possible points of view:

• It is not our problem (e.g. we assume the Internet connection is always stable, service is always working flawlessly, network must work correctly at all times)
• Can we work around the effect? (e.g. can we retry or reconnect and continue without impacting the user?)

I reported it for the second reason, and because we had just moved from Requests to urllib2, and these issues were only seen after this move.

For better reporting to the user, see #385. Even if there is no way to work around the problem, we could still offer the end-user a clue to why they have this problem.