diff --git a/pychromecast/dial.py b/pychromecast/dial.py index fa7b2a870..2c7544d9d 100644 --- a/pychromecast/dial.py +++ b/pychromecast/dial.py @@ -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}" @@ -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 @@ -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 diff --git a/pychromecast/discovery.py b/pychromecast/discovery.py index d35e6c319..123448b4d 100644 --- a/pychromecast/discovery.py +++ b/pychromecast/discovery.py @@ -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) diff --git a/pychromecast/socket_client.py b/pychromecast/socket_client.py index cae6d4ddf..518cfe155 100644 --- a/pychromecast/socket_client.py +++ b/pychromecast/socket_client.py @@ -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, @@ -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 @@ -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 @@ -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) @@ -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']: + 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 @@ -293,7 +309,7 @@ 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 @@ -301,18 +317,35 @@ def initialize_connection(self): # pylint:disable=too-many-statements 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: @@ -320,7 +353,7 @@ def initialize_connection(self): # pylint:disable=too-many-statements 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): @@ -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: @@ -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: @@ -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: @@ -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 @@ -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): @@ -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))) @@ -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 @@ -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(): @@ -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...")