Skip to content

Exponential backoff of mdns service resolution retries #268

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
balloob merged 3 commits into from
Feb 15, 2019
Merged

Exponential backoff of mdns service resolution retries #268

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
35ae388
Exponentional backoff of mdns retries
emontnemery Feb 15, 2019
05f9a32
Improve debug prints
emontnemery Feb 15, 2019
8ca26f1
lint
emontnemery Feb 15, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 3 additions & 4 deletions pychromecast/dial.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@
import logging
import requests

from .discovery import get_info_from_service
from .discovery import get_info_from_service, get_host_from_service_info

XML_NS_UPNP_DEVICE = "{urn:schemas-upnp-org:device-1-0}"

Expand Down Expand Up @@ -52,8 +52,7 @@ def get_device_status(host, services=None, zconf=None):
if not host:
for service in services.copy():
service_info = get_info_from_service(service, zconf)
if service_info and service_info.server:
host = service_info.server.lower()
host, _ = get_host_from_service_info(service_info)
if host:
_LOGGER.debug("Resolved service %s to %s", service, host)
break
Expand Down Expand Up @@ -94,7 +93,7 @@ def get_device_status(host, services=None, zconf=None):
return DeviceStatus(friendly_name, model_name, manufacturer,
uuid, cast_type)

except (requests.exceptions.RequestException, ValueError):
except (requests.exceptions.RequestException, OSError, ValueError):
return None


Expand Down
14 changes: 14 additions & 0 deletions pychromecast/discovery.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -152,3 +152,17 @@ def get_info_from_service(service, zconf):
except IOError:
pass
return service_info


def get_host_from_service_info(service_info):
""" Get hostname or IP from service_info. """
host = None
port = None
if (service_info and service_info.port and
(service_info.server or service_info.address)):
if service_info.address:
host = socket.inet_ntoa(service_info.address)
else:
host = service_info.server.lower()
port = service_info.port
return (host, port)
99 changes: 67 additions & 32 deletions pychromecast/socket_client.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@
from .controllers import BaseController
from .controllers.media import MediaController
from .dial import CAST_TYPE_CHROMECAST, CAST_TYPE_AUDIO, CAST_TYPE_GROUP
from .discovery import get_info_from_service
from .discovery import get_info_from_service, get_host_from_service_info
from .error import (
ChromecastConnectionError,
UnsupportedNamespace,
Expand Down Expand Up @@ -174,6 +174,7 @@ def __init__(self, host, port=None, cast_type=CAST_TYPE_CHROMECAST,
self._force_recon = False

self.cast_type = cast_type
self.fn = None # pylint:disable=invalid-name
self.tries = tries
self.timeout = timeout or TIMEOUT_TIME
self.retry_wait = retry_wait or RETRY_TIME
Expand Down Expand Up @@ -219,7 +220,7 @@ def __init__(self, host, port=None, cast_type=CAST_TYPE_CHROMECAST,
NetworkAddress(self.host, self.port)))
raise

def initialize_connection(self): # pylint:disable=too-many-statements
def initialize_connection(self): # noqa: E501 pylint:disable=too-many-statements, too-many-branches
"""Initialize a socket to a Chromecast, retrying as necessary."""
tries = self.tries

Expand All @@ -241,8 +242,18 @@ def initialize_connection(self): # pylint:disable=too-many-statements
self.connecting = True
retry_log_fun = self.logger.error

while not self.stop.is_set() and (tries is None or tries > 0):
# Dict keeping track of individual retry delay for each named service
retries = {}

while not self.stop.is_set() and (tries is None or tries > 0): # noqa: E501 pylint:disable=too-many-nested-blocks
# Prune retries dict
retries = {key: retries[key] for key in self.services if (
key is not None and key in retries)}

for service in self.services.copy():
now = time.time()
retry = retries.get(
service, {'delay': self.retry_wait, 'next_retry': now})
try:
self.socket = new_socket()
self.socket.settimeout(self.timeout)
Expand All @@ -252,35 +263,40 @@ def initialize_connection(self): # pylint:disable=too-many-statements
# Resolve the service name. If service is None, we're
# connecting directly to a host name or IP-address
if service:
if now < retry['next_retry']:
Copy link
Copy Markdown
Contributor

@balloob balloob Feb 15, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why check this here instead of before creating a new socket and outside of the try?

Copy link
Copy Markdown
Collaborator Author

@emontnemery emontnemery Feb 15, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, you're right.. Will fix.

continue
host = None
port = None
service_info = get_info_from_service(service,
self.zconf)
if (service_info and service_info.server and
service_info.port):
host = service_info.server.lower()
port = service_info.port
host, port = get_host_from_service_info(service_info)
if host and port:
try:
self.fn = service_info.properties[b'fn']\
.decode('utf-8')
except (AttributeError, KeyError, UnicodeError):
pass
self.logger.debug(
"[%s:%s] Resolved service %s to %s:%s",
self.host, self.port, service, self.host,
self.port)
self.fn or self.host, self.port, service, host,
port)
self.host = host
self.port = port
else:
self.logger.debug(
"[%s:%s] failed to resolve service %s",
self.host, self.port, service)
self.fn or self.host, self.port, service)
self._report_connection_status(
ConnectionStatus(
CONNECTION_STATUS_FAILED_RESOLVE,
NetworkAddress(service, None)))
# If zeroconf fails to receive the necessary data,
# try next
# try next service
continue

self.logger.debug("[%s:%s] Connecting to %s",
self.host, self.port, self.host)
self.logger.debug("[%s:%s] Connecting to %s:%s",
self.fn or self.host, self.port,
self.host, self.port)
self.socket.connect((self.host, self.port))
self.socket = ssl.wrap_socket(self.socket)
self.connecting = False
Expand All @@ -293,34 +309,51 @@ def initialize_connection(self): # pylint:disable=too-many-statements
self.heartbeat_controller.reset()

self.logger.debug("[%s:%s] Connected!",
self.host, self.port)
self.fn or self.host, self.port)
return
except OSError as err:
self.connecting = True
if self.stop.is_set():
self.logger.error(
"[%s:%s] Failed to connect: %s. "
"aborting due to stop signal.",
self.host, self.port, err)
self.fn or self.host, self.port, err)
raise ChromecastConnectionError("Failed to connect")

self._report_connection_status(
ConnectionStatus(CONNECTION_STATUS_FAILED,
NetworkAddress(self.host, self.port)))
if service is not None:
# Exponentional backoff for service name mdns lookups
now = time.time()
retry['next_retry'] = now + retry['delay']
retry_log_fun(
"[%s:%s] Failed to connect to service %s"
", retrying in %.1fs",
self.fn or self.host, self.port,
service, retry['delay'])
retry['delay'] = min(retry['delay']*2, 300)
retries[service] = retry
else:
retry_log_fun(
"[%s:%s] Failed to connect, retrying in %.1fs",
self.fn or self.host, self.port, self.retry_wait)
retry_log_fun = self.logger.debug

# Only sleep if we have another retry remaining
if tries is None or tries > 1:
retry_log_fun("[%s:%s] Failed to connect, retrying in %.1fs",
self.host, self.port, self.retry_wait)
retry_log_fun = self.logger.debug
self.logger.debug(
"[%s:%s] Not connected, sleeping for %.1fs. Services: %s",
self.fn or self.host, self.port,
self.retry_wait, self.services)
time.sleep(self.retry_wait)

if tries:
tries -= 1

self.stop.set()
self.logger.error("[%s:%s] Failed to connect. No retries.",
self.host, self.port)
self.fn or self.host, self.port)
raise ChromecastConnectionError("Failed to connect")

def disconnect(self):
Expand Down Expand Up @@ -413,12 +446,12 @@ def run_once(self):
self.logger.info(
"[%s:%s] Stopped while reading message, "
"disconnecting.",
self.host, self.port)
self.fn or self.host, self.port)
else:
self.logger.error(
"[%s:%s] Interruption caught without being stopped: "
"%s",
self.host, self.port, exc)
self.fn or self.host, self.port, exc)
return 1
except ssl.SSLError as exc:
if exc.errno == ssl.SSL_ERROR_EOF:
Expand All @@ -428,7 +461,7 @@ def run_once(self):
except socket.error:
self._force_recon = True
self.logger.error('[%s:%s] Error reading from socket.',
self.host, self.port)
self.fn or self.host, self.port)
else:
data = _json_from_message(message)
if not message:
Expand Down Expand Up @@ -474,13 +507,13 @@ def _check_connection(self):
self.logger.warning(
"[%s:%s] Error communicating with socket, resetting "
"connection",
self.host, self.port)
self.fn or self.host, self.port)
reset = True

elif self.heartbeat_controller.is_expired():
self.logger.warning(
"[%s:%s] Heartbeat timeout, resetting connection",
self.host, self.port)
self.fn or self.host, self.port)
reset = True

if reset:
Expand All @@ -502,7 +535,7 @@ def _route_message(self, message, data):
# debug messages
if message.namespace != NS_HEARTBEAT:
self.logger.debug(
"[%s:%s] Received: %s", self.host, self.port,
"[%s:%s] Received: %s", self.fn or self.host, self.port,
_message_to_string(message, data))

# message handlers
Expand All @@ -515,18 +548,19 @@ def _route_message(self, message, data):
if data.get(REQUEST_ID) not in self._request_callbacks:
self.logger.debug(
"[%s:%s] Message unhandled: %s",
self.host, self.port,
self.fn or self.host, self.port,
_message_to_string(message, data))
except Exception: # pylint: disable=broad-except
self.logger.exception(
("[%s:%s] Exception caught while sending message to "
"controller %s: %s"), self.host, self.port,
"controller %s: %s"), self.fn or self.host, self.port,
type(self._handlers[message.namespace]).__name__,
_message_to_string(message, data))

else:
self.logger.debug(
"[%s:%s] Received unknown namespace: %s", self.host, self.port,
"[%s:%s] Received unknown namespace: %s",
self.fn or self.host, self.port,
_message_to_string(message, data))

def _cleanup(self):
Expand All @@ -547,7 +581,7 @@ def _cleanup(self):
self.socket.close()
except Exception: # pylint: disable=broad-except
self.logger.exception(
"[%s:%s] _cleanup", self.host, self.port)
"[%s:%s] _cleanup", self.fn or self.host, self.port)
self._report_connection_status(
ConnectionStatus(CONNECTION_STATUS_DISCONNECTED,
NetworkAddress(self.host, self.port)))
Expand All @@ -558,7 +592,7 @@ def _report_connection_status(self, status):
for listener in self._connection_listeners:
try:
self.logger.debug("[%s:%s] connection listener: %x (%s)",
self.host, self.port,
self.fn or self.host, self.port,
id(listener), type(listener).__name__)
listener.new_connection_status(status)
except Exception: # pylint: disable=broad-except
Expand Down Expand Up @@ -638,7 +672,8 @@ def send_message(self, destination_id, namespace, data,

# Log all messages except heartbeat
if msg.namespace != NS_HEARTBEAT:
self.logger.debug("[%s:%s] Sending: %s", self.host, self.port,
self.logger.debug("[%s:%s] Sending: %s",
self.fn or self.host, self.port,
_message_to_string(msg, data))

if not force and self.stop.is_set():
Expand All @@ -656,7 +691,7 @@ def send_message(self, destination_id, namespace, data,
self._request_callbacks.pop(request_id, None)
self._force_recon = True
self.logger.info('[%s:%s] Error writing to socket.',
self.host, self.port)
self.fn or self.host, self.port)
else:
raise NotConnected("Chromecast " + self.host + ":" + self.port +
" is connecting...")
Expand Down