Songpal error with 0.65

tleegaard commented 6 years ago

With https://github.com/home-assistant/home-assistant/pull/12143 Songpal was introduced. I don't think I have any Songpal equipment, but after upgrading to 0.65 I get this error:

2018-03-09 20:57:15 WARNING (SyncWorker_19) [netdisco.ssdp] Error fetching description at http://192.168.1.60:56032/devdesc.xml
2018-03-09 20:58:01 ERROR (MainThread) [homeassistant.requirements] Not initializing media_player.songpal because could not install requirement python-songpal==0.0.6
2018-03-09 20:58:01 ERROR (MainThread) [homeassistant.setup] Unable to prepare setup for platform media_player.songpal: Could not install all requirements.

I do have a Sony smart/android tv though (on 192.168.1.60). Maybe that's the problem?

Home Assistant release (hass --version): 0.65.0

Python release (python3 --version): 3.6

balloob commented 6 years ago

CC @rytilahti - is the Songpal discovery too broad? Or is that a songpal TV? (also, why would the requirement not install?)

rytilahti commented 6 years ago

The discovery is looks for urn:schemas-sony-com:service:ScalarWebAPI:1 which I thought would be the description of this API. Maybe it is too broad, or maybe those televisions also support songpal protocol, too. As for why the requirements is not installed, I have really no idea. Installing it from pypi works just fine here.

@tleegaard what television do you have? Would you mind installing songpal manually pip install python-songpal and check what information songpal discover returns back? Most interesting are probably the name & model + what services are being offered, here's what my soundbar returns:

$ songpal discover
Discovering for 3 seconds

Found HT-XT3 - BAR-2015
* API version: 1.0
* Endpoint: http://192.168.XXX.XXX:10000/sony
* Services:
  - Service: guide
  - Service: system
  - Service: audio
  - Service: avContent

vlad36N commented 6 years ago

After upgrading to 0.65 I get this error:

Error while setting up platform songpal
7:34 AM components/media_player/songpal.py (ERROR)

Log Details (ERROR)
Sat Mar 10 2018 07:34:10 GMT-0500 (Eastern Standard Time)

Error while setting up platform songpal
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 82, in async_setup
    SLOW_SETUP_MAX_WAIT, loop=hass.loop)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
    return fut.result()
  File "/usr/lib/python3.6/asyncio/futures.py", line 245, in result
    raise self._exception
  File "/usr/lib/python3.6/asyncio/tasks.py", line 180, in _step
    result = coro.send(None)
  File "/usr/lib/python3.6/site-packages/homeassistant/components/media_player/songpal.py", line 68, in async_setup_platform
    await device.initialize()
  File "/usr/lib/python3.6/site-packages/homeassistant/components/media_player/songpal.py", line 122, in initialize
    self._sysinfo = await self.dev.get_system_info()
  File "/usr/lib/python3.6/site-packages/songpal/protocol.py", line 158, in get_system_info
    return Sysinfo.make(**await self.services["system"]["getSystemInformation"]())
KeyError: 'system'

rytilahti commented 6 years ago

@vlad36N what is the device in question? You could try running songpal discover in console to see what is being detected, perhaps the device has no system service.

vlad36N commented 6 years ago

No device in question. Just update to 0.65 and automatically restart hassio. This error show up in error log. Error while setting up platform songpal 7:34 AM components/media_player/songpal.py (ERROR) Didn't set any new device or use of platform songpal.

rytilahti commented 6 years ago

Yes, songpal-supported devices are autodetected and the platform is loaded, indicating that you have some Sony device reporting to be songpal-compatible in your network.

Anyway, I will add some guards for cases where it does not receive expected responses from the device to make it error out gracefully.

MPopti0n commented 6 years ago

I got the same errors, I have a Sony Bravia XBR-55X850D (Android TV) on my network, and discovery is on in HA

rytilahti commented 6 years ago

@MPopti0n the original error or the same as reported by Vlad above? Could you try the songpal discover to see what it reports? The detection needs to be made more stringent, but as I have no such device I cannot test it myself.

MPopti0n commented 6 years ago

Vlad's error, i'll try the songpal discover when I get home

tleegaard commented 6 years ago

@rytilahti

My TV is a KDL 8505C.

Trying to install songpal:

$ pip install python-songpal
Collecting python-songpal
  Using cached python_songpal-0.0.6-py3-none-any.whl
Collecting upnpclient (from python-songpal)
  Using cached uPnPClient-0.0.8.tar.gz
Requirement already satisfied: websockets in /srv/homeassistant/lib/python3.6/site-packages (from python-songpal)
Requirement already satisfied: attrs in /srv/homeassistant/lib/python3.6/site-packages (from python-songpal)
Requirement already satisfied: click in /srv/homeassistant/lib/python3.6/site-packages (from python-songpal)
Requirement already satisfied: requests in /srv/homeassistant/lib/python3.6/site-packages (from upnpclient->python-songpal)
Requirement already satisfied: six in /srv/homeassistant/lib/python3.6/site-packages (from upnpclient->python-songpal)
Requirement already satisfied: netdisco in /srv/homeassistant/lib/python3.6/site-packages (from upnpclient->python-songpal)
Requirement already satisfied: python-dateutil in /srv/homeassistant/lib/python3.6/site-packages (from upnpclient->python-songpal)
Collecting lxml (from upnpclient->python-songpal)
  Using cached lxml-4.1.1.tar.gz
Requirement already satisfied: urllib3<1.23,>=1.21.1 in /srv/homeassistant/lib/python3.6/site-packages (from requests->upnpclient->python-songpal)
Requirement already satisfied: chardet<3.1.0,>=3.0.2 in /srv/homeassistant/lib/python3.6/site-packages (from requests->upnpclient->python-songpal)
Requirement already satisfied: idna<2.7,>=2.5 in /srv/homeassistant/lib/python3.6/site-packages (from requests->upnpclient->python-songpal)
Requirement already satisfied: certifi>=2017.4.17 in /srv/homeassistant/lib/python3.6/site-packages (from requests->upnpclient->python-songpal)
Requirement already satisfied: zeroconf>=0.19.1 in /srv/homeassistant/lib/python3.6/site-packages (from netdisco->upnpclient->python-songpal)
Requirement already satisfied: netifaces!=0.10.5 in /srv/homeassistant/lib/python3.6/site-packages (from zeroconf>=0.19.1->netdisco->upnpclient->python-songpal)
Installing collected packages: lxml, upnpclient, python-songpal
  Running setup.py install for lxml ... error
    Complete output from command /srv/homeassistant/bin/python3.6 -u -c "import setuptools, tokenize;__file__='/tmp/pip-build-m_o1qopy/lxml/setup.py';f=getattr(tokenize, 'open', open)(__file__);code=f.read().replace('\r\n', '\n');f.close();exec(compile(code, __file__, 'exec'))" install --record /tmp/pip-apgywmgb-record/install-record.txt --single-version-externally-managed --compile --install-headers /srv/homeassistant/include/site/python3.6/lxml:
    Building lxml version 4.1.1.
    Building without Cython.
    ERROR: b'/bin/sh: 1: xslt-config: not found\n'
    ** make sure the development packages of libxml2 and libxslt are installed **

    Using build configuration of libxslt
    running install
    running build
    running build_py
    creating build
    creating build/lib.linux-armv7l-3.6
    creating build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/doctestcompare.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/pyclasslookup.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/cssselect.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/usedoctest.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/__init__.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/ElementInclude.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/builder.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/_elementpath.py -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/sax.py -> build/lib.linux-armv7l-3.6/lxml
    creating build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/__init__.py -> build/lib.linux-armv7l-3.6/lxml/includes
    creating build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/defs.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/formfill.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/_diffcommand.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/_html5builder.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/soupparser.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/clean.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/_setmixin.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/usedoctest.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/__init__.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/builder.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/html5parser.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/ElementSoup.py -> build/lib.linux-armv7l-3.6/lxml/html
    copying src/lxml/html/diff.py -> build/lib.linux-armv7l-3.6/lxml/html
    creating build/lib.linux-armv7l-3.6/lxml/isoschematron
    copying src/lxml/isoschematron/__init__.py -> build/lib.linux-armv7l-3.6/lxml/isoschematron
    copying src/lxml/etree.h -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/etree_api.h -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/lxml.etree.h -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/lxml.etree_api.h -> build/lib.linux-armv7l-3.6/lxml
    copying src/lxml/includes/schematron.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/c14n.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/relaxng.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/xpath.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/dtdvalid.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/xmlparser.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/tree.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/xslt.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/uri.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/xmlschema.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/__init__.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/config.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/htmlparser.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/xmlerror.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/xinclude.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/etreepublic.pxd -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/lxml-version.h -> build/lib.linux-armv7l-3.6/lxml/includes
    copying src/lxml/includes/etree_defs.h -> build/lib.linux-armv7l-3.6/lxml/includes
    creating build/lib.linux-armv7l-3.6/lxml/isoschematron/resources
    creating build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/rng
    copying src/lxml/isoschematron/resources/rng/iso-schematron.rng -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/rng
    creating build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl
    copying src/lxml/isoschematron/resources/xsl/XSD2Schtrn.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl
    copying src/lxml/isoschematron/resources/xsl/RNG2Schtrn.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl
    creating build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1
    copying src/lxml/isoschematron/resources/xsl/iso-schematron-xslt1/iso_svrl_for_xslt1.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1
    copying src/lxml/isoschematron/resources/xsl/iso-schematron-xslt1/iso_schematron_message.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1    copying src/lxml/isoschematron/resources/xsl/iso-schematron-xslt1/iso_schematron_skeleton_for_xslt1.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1
    copying src/lxml/isoschematron/resources/xsl/iso-schematron-xslt1/iso_abstract_expand.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1
    copying src/lxml/isoschematron/resources/xsl/iso-schematron-xslt1/iso_dsdl_include.xsl -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1
    copying src/lxml/isoschematron/resources/xsl/iso-schematron-xslt1/readme.txt -> build/lib.linux-armv7l-3.6/lxml/isoschematron/resources/xsl/iso-schematron-xslt1
    running build_ext
    building 'lxml.etree' extension
    creating build/temp.linux-armv7l-3.6
    creating build/temp.linux-armv7l-3.6/src
    creating build/temp.linux-armv7l-3.6/src/lxml
    gcc -pthread -Wno-unused-result -Wsign-compare -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -fPIC -DCYTHON_CLINE_IN_TRACEBACK=1 -Isrc -Isrc/lxml/includes -I/srv/homeassistant/include -I/usr/local/include/python3.6m -c src/lxml/etree.c -o build/temp.linux-armv7l-3.6/src/lxml/etree.o -w
    In file included from src/lxml/etree.c:619:0:
    src/lxml/includes/etree_defs.h:14:31: fatal error: libxml/xmlversion.h: No such file or directory
     #include "libxml/xmlversion.h"
                                   ^
    compilation terminated.
    Compile failed: command 'gcc' failed with exit status 1
    creating tmp
    cc -I/usr/include/libxml2 -c /tmp/xmlXPathInitun0mdj7o.c -o tmp/xmlXPathInitun0mdj7o.o    /tmp/xmlXPathInitun0mdj7o.c:1:26: fatal error: libxml/xpath.h: No such file or directory
     #include "libxml/xpath.h"
                              ^
    compilation terminated.
    *********************************************************************************
    Could not find function xmlCheckVersion in library libxml2. Is libxml2 installed?
    *********************************************************************************
    error: command 'gcc' failed with exit status 1

    ----------------------------------------
Command "/srv/homeassistant/bin/python3.6 -u -c "import setuptools, tokenize;__file__='/tmp/pip-build-m_o1qopy/lxml/setup.py';f=getattr(tokenize, 'open', open)(__file__);code=f.read().replace('\r\n', '\n');f.close();exec(compile(code, __file__, 'exec'))" install --record /tmp/pip-apgywmgb-record/install-record.txt --single-version-externally-managed --compile --install-headers /srv/homeassistant/include/site/python3.6/lxml" failed with error code 1 in /tmp/pip-build-m_o1qopy/lxml/

MPopti0n commented 6 years ago

Sooooo.... there it is @rytilahti ! :stuck_out_tongue:

2018-03-10 09:02:04 INFO (MainThread) [homeassistant.loader] Loaded media_player.songpal from custom_components.media_player.songpal
2018-03-10 09:02:09 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.songpal

2018-03-10 09:02:10 DEBUG (MainThread) [songpal.protocol] WS endpoint: ws://192.168.1.174:10000/sony
2018-03-10 09:02:10 DEBUG (MainThread) [songpal.protocol] HTTP endpoint: http://192.168.1.174:10000/sony/guide
2018-03-10 09:02:10 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=songpal_set_sound_setting>
2018-03-10 09:02:10 INFO (MainThread) [homeassistant.setup] Setup of domain logbook took 0.6 seconds.
2018-03-10 09:02:10 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logbook>
2018-03-10 09:02:10 INFO (MainThread) [homeassistant.setup] Setup of domain config took 0.7 seconds.
2018-03-10 09:02:10 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config>
2018-03-10 09:02:10 ERROR (MainThread) [custom_components.media_player.songpal] Unable to get methods from songpal: Unable to get APIs: HTTPConnectionPool(host='192.168.1.174', port=10000): Max retries exceeded with url: /sony/guide (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x70c327b0>: Failed to establish a new connection: [Errno 111] Connection refused',))

2018-03-10 09:02:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690531.0578194, level=ERROR, message=Error doing job: Task exception was never retrieved, exception=Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/tasks.py", line 180, in _step
    result = coro.send(None)
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 197, in _async_add_entity
    if entity.unique_id is not None:
  File "/config/custom_components/media_player/songpal.py", line 97, in unique_id
    return self._sysinfo.macAddr
AttributeError: 'NoneType' object has no attribute 'macAddr'
, source=custom_components/media_player/songpal.py>

2018-03-10 09:05:00 INFO (MainThread) [homeassistant.components.discovery] Found new service: songpal {'host': '192.168.1.174', 'port': 41638, 'ssdp_description': 'http://192.168.1.174:41638/sony/webapi/ssdp/dd.xml', 'name': 'XBR-55X850D', 'model_name': 'XBR-55X850D', 'model_number': None, 'serial': None, 'properties': {'scalarwebapi': {'X_ScalarWebAPI_Version': '1.0', 'X_ScalarWebAPI_BaseURL': 'http://192.168.1.174/sony', 'X_ScalarWebAPI_ServiceList': {'X_ScalarWebAPI_ServiceType': ['guide', 'accessControl', 'encryption', 'contentshare', 'avContent', 'cec', 'audio', 'system', 'appControl', 'videoScreen']}}, 'endpoint': 'http://192.168.1.174/sony'}}
2018-03-10 09:05:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.media_player, platform=songpal, discovered=host=192.168.1.174, port=41638, ssdp_description=http://192.168.1.174:41638/sony/webapi/ssdp/dd.xml, name=XBR-55X850D, model_name=XBR-55X850D, model_number=None, serial=None, properties=scalarwebapi=X_ScalarWebAPI_Version=1.0, X_ScalarWebAPI_BaseURL=http://192.168.1.174/sony, X_ScalarWebAPI_ServiceList=X_ScalarWebAPI_ServiceType=['guide', 'accessControl', 'encryption', 'contentshare', 'avContent', 'cec', 'audio', 'system', 'appControl', 'videoScreen'], endpoint=http://192.168.1.174/sony>

2018-03-10 09:05:00 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.songpal

2018-03-10 09:05:01 ERROR (MainThread) [custom_components.media_player.songpal] got autodiscovered device: {'host': '192.168.1.174', 'port': 41638, 'ssdp_description': 'http://192.168.1.174:41638/sony/webapi/ssdp/dd.xml', 'name': 'XBR-55X850D', 'model_name': 'XBR-55X850D', 'model_number': None, 'serial': None, 'properties': {'scalarwebapi': {'X_ScalarWebAPI_Version': '1.0', 'X_ScalarWebAPI_BaseURL': 'http://192.168.1.174/sony', 'X_ScalarWebAPI_ServiceList': {'X_ScalarWebAPI_ServiceType': ['guide', 'accessControl', 'encryption', 'contentshare', 'avContent', 'cec', 'audio', 'system', 'appControl', 'videoScreen']}}, 'endpoint': 'http://192.168.1.174/sony'}}

2018-03-10 09:05:01 DEBUG (MainThread) [songpal.protocol] WS endpoint: ws://192.168.1.174/sony

2018-03-10 09:05:01 DEBUG (MainThread) [songpal.protocol] HTTP endpoint: http://192.168.1.174/sony/guide
2018-03-10 09:05:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=songpal_set_sound_setting>

2018-03-10 09:05:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690701.0256836, level=ERROR, message=got autodiscovered device: {'host': '192.168.1.174', 'port': 41638, 'ssdp_description': 'http://192.168.1.174:41638/sony/webapi/ssdp/dd.xml', 'name': 'XBR-55X850D', 'model_name': 'XBR-55X850D', 'model_number': None, 'serial': None, 'properties': {'scalarwebapi': {'X_ScalarWebAPI_Version': '1.0', 'X_ScalarWebAPI_BaseURL': 'http://192.168.1.174/sony', 'X_ScalarWebAPI_ServiceList': {'X_ScalarWebAPI_ServiceType': ['guide', 'accessControl', 'encryption', 'contentshare', 'avContent', 'cec', 'audio', 'system', 'appControl', 'videoScreen']}}, 'endpoint': 'http://192.168.1.174/sony'}}, exception=, source=custom_components/media_player/songpal.py>

2018-03-10 09:05:01 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'service_registered', 'data': {'domain': 'media_player', 'service': 'songpal_set_sound_setting'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 1, 131777, tzinfo=<UTC>)}}

2018-03-10 09:05:02 DEBUG (MainThread) [songpal.protocol] Got 10 services!

2018-03-10 09:05:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'service_executed', 'data': {'service_call_id': '1968474224-18'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 1, 195923, tzinfo=<UTC>)}}
2018-03-10 09:05:02 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690701.0256836, 'level': 'ERROR', 'message': "got autodiscovered device: {'host': '192.168.1.174', 'port': 41638, 'ssdp_description': 'http://192.168.1.174:41638/sony/webapi/ssdp/dd.xml', 'name': 'XBR-55X850D', 'model_name': 'XBR-55X850D', 'model_number': None, 'serial': None, 'properties': {'scalarwebapi': {'X_ScalarWebAPI_Version': '1.0', 'X_ScalarWebAPI_BaseURL': 'http://192.168.1.174/sony', 'X_ScalarWebAPI_ServiceList': {'X_ScalarWebAPI_ServiceType': ['guide', 'accessControl', 'encryption', 'contentshare', 'avContent', 'cec', 'audio', 'system', 'appControl', 'videoScreen']}}, 'endpoint': 'http://192.168.1.174/sony'}}", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 1, 237978, tzinfo=<UTC>)}}

2018-03-10 09:05:03 WARNING (MainThread) [songpal.service] Invalid handshake for accessControl: Bad status code: 501
2018-03-10 09:05:03 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:03 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:03 DEBUG (MainThread) [songpal.service] Got no signature for actRegister on ws://192.168.1.174/sony
2018-03-10 09:05:03 WARNING (MainThread) [songpal.service] More than on version for {'name': 'setTextForm', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690703.9386766, level=WARNING, message=Invalid handshake for accessControl: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690703.9987261, level=WARNING, message=More than on version for {'name': 'setTextForm', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690703.9386766, 'level': 'WARNING', 'message': 'Invalid handshake for accessControl: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 15399, tzinfo=<UTC>)}}
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690703.9987261, 'level': 'WARNING', 'message': "More than on version for {'name': 'setTextForm', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 19912, tzinfo=<UTC>)}}
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] Invalid handshake for appControl: Bad status code: 501
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.0695481, level=WARNING, message=Invalid handshake for appControl: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.0695481, 'level': 'WARNING', 'message': 'Invalid handshake for appControl: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 103691, tzinfo=<UTC>)}}
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] Invalid handshake for appControl: Bad status code: 501
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getApplicationStatusList on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getApplicationList on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setTextForm on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getTextForm on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for terminateApps on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setActiveApp on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getWebAppStatus on ws://192.168.1.174/sony
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] More than on version for {'name': 'setAudioVolume', 'versions': [{'version': '1.0', 'authLevel': 'generic'}, {'version': '1.2', 'authLevel': 'generic'}]}, using the first one
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.1245794, level=WARNING, message=Invalid handshake for appControl: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.1541064, level=WARNING, message=More than on version for {'name': 'setAudioVolume', 'versions': [{'version': '1.0', 'authLevel': 'generic'}, {'version': '1.2', 'authLevel': 'generic'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.1245794, 'level': 'WARNING', 'message': 'Invalid handshake for appControl: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 163889, tzinfo=<UTC>)}}
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.1541064, 'level': 'WARNING', 'message': "More than on version for {'name': 'setAudioVolume', 'versions': [{'version': '1.0', 'authLevel': 'generic'}, {'version': '1.2', 'authLevel': 'generic'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 166767, tzinfo=<UTC>)}}
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.components.cloud.iot] Connected
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] Invalid handshake for audio: Bad status code: 501
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.585499, level=WARNING, message=Invalid handshake for audio: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.585499, 'level': 'WARNING', 'message': 'Invalid handshake for audio: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 610370, tzinfo=<UTC>)}}
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] Invalid handshake for audio: Bad status code: 501
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setSoundSettings on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setSpeakerSettings on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getSoundSettings on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setAudioMute on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setAudioVolume on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getSpeakerSettings on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getVolumeInformation on ws://192.168.1.174/sony
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] More than on version for {'name': 'setPlayTvContent', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getCurrentExternalInputsStatus', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getContentCount', 'versions': [{'version': '1.1', 'authLevel': 'private'}, {'version': '1.0', 'authLevel': 'private'}]}, using the first one
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getContentList', 'versions': [{'version': '1.0', 'authLevel': 'private'}, {'version': '1.2', 'authLevel': 'private'}]}, using the first one
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.632848, level=WARNING, message=Invalid handshake for audio: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.6743724, level=WARNING, message=More than on version for {'name': 'setPlayTvContent', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.6849616, level=WARNING, message=More than on version for {'name': 'getCurrentExternalInputsStatus', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.6973433, level=WARNING, message=More than on version for {'name': 'getContentCount', 'versions': [{'version': '1.1', 'authLevel': 'private'}, {'version': '1.0', 'authLevel': 'private'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.7098157, level=WARNING, message=More than on version for {'name': 'getContentList', 'versions': [{'version': '1.0', 'authLevel': 'private'}, {'version': '1.2', 'authLevel': 'private'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.632848, 'level': 'WARNING', 'message': 'Invalid handshake for audio: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 743025, tzinfo=<UTC>)}}
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.6743724, 'level': 'WARNING', 'message': "More than on version for {'name': 'setPlayTvContent', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 751742, tzinfo=<UTC>)}}
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.6849616, 'level': 'WARNING', 'message': "More than on version for {'name': 'getCurrentExternalInputsStatus', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 758360, tzinfo=<UTC>)}}
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.6973433, 'level': 'WARNING', 'message': "More than on version for {'name': 'getContentCount', 'versions': [{'version': '1.1', 'authLevel': 'private'}, {'version': '1.0', 'authLevel': 'private'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 765133, tzinfo=<UTC>)}}
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.7098157, 'level': 'WARNING', 'message': "More than on version for {'name': 'getContentList', 'versions': [{'version': '1.0', 'authLevel': 'private'}, {'version': '1.2', 'authLevel': 'private'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 769547, tzinfo=<UTC>)}}
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] Invalid handshake for avContent: Bad status code: 501
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.8382845, level=WARNING, message=Invalid handshake for avContent: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.8382845, 'level': 'WARNING', 'message': 'Invalid handshake for avContent: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 847179, tzinfo=<UTC>)}}
2018-03-10 09:05:04 WARNING (MainThread) [songpal.service] Invalid handshake for avContent: Bad status code: 501
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setFavoriteContentList on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setPlayTvContent on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getCurrentExternalInputsStatus on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getContentCount on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setTvContentVisibility on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getContentList on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getSchemeList on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for deleteContent on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setPlayContent on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getParentalRatingSettings on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getPlayingContentInfo on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for setDeleteProtection on ws://192.168.1.174/sony
2018-03-10 09:05:04 DEBUG (MainThread) [songpal.service] Got no signature for getSourceList on ws://192.168.1.174/sony
2018-03-10 09:05:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690704.8857396, level=WARNING, message=Invalid handshake for avContent: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:04 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690704.8857396, 'level': 'WARNING', 'message': 'Invalid handshake for avContent: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 4, 992278, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for cec: Bad status code: 501
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setCecControlMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setPowerSyncMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setMhlPowerFeedMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setMhlAutoInputChangeMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.0158262, level=WARNING, message=Invalid handshake for cec: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.0158262, 'level': 'WARNING', 'message': 'Invalid handshake for cec: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 51847, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for contentshare: Bad status code: 404
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for closeContentShare on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getContentShareServerInfo on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for togglePlayStatus on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for rotatePhoto on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getContentList on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getUserList on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setQuickInvitationMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setUserNickName on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setBgmControlMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for voteContent on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for requestToNotifyEvent on ws://192.168.1.174/sony
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.079162, level=WARNING, message=Invalid handshake for contentshare: Bad status code: 404, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.079162, 'level': 'WARNING', 'message': 'Invalid handshake for contentshare: Bad status code: 404', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 164419, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for encryption: Bad status code: 501
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getPublicKey on ws://192.168.1.174/sony
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.1954534, level=WARNING, message=Invalid handshake for encryption: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.1954534, 'level': 'WARNING', 'message': 'Invalid handshake for encryption: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 222269, tzinfo=<UTC>)}}
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getSupportedApiInfo on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getServiceProtocols on ws://192.168.1.174/sony
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getCurrentTime', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.277339, level=WARNING, message=More than on version for {'name': 'getCurrentTime', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.277339, 'level': 'WARNING', 'message': "More than on version for {'name': 'getCurrentTime', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one", 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 295090, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for system: Bad status code: 501
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.321329, level=WARNING, message=Invalid handshake for system: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.321329, 'level': 'WARNING', 'message': 'Invalid handshake for system: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 351491, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for system: Bad status code: 501
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getSystemInformation on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getLEDIndicatorStatus on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getPowerStatus on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getNetworkSettings on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setPowerStatus on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setLanguage on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setPowerSavingMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setLEDIndicatorStatus on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getDeviceMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getCurrentTime on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getInterfaceInformation on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setDeviceMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for requestReboot on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getSystemSupportedFunction on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getWolMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getPowerSavingMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getRemoteControllerInfo on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setWolMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getRemoteDeviceSettings on ws://192.168.1.174/sony
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.389325, level=WARNING, message=Invalid handshake for system: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.389325, 'level': 'WARNING', 'message': 'Invalid handshake for system: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 512580, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for videoScreen: Bad status code: 501
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.5430498, level=WARNING, message=Invalid handshake for videoScreen: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.5430498, 'level': 'WARNING', 'message': 'Invalid handshake for videoScreen: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 572564, tzinfo=<UTC>)}}
2018-03-10 09:05:05 WARNING (MainThread) [songpal.service] Invalid handshake for videoScreen: Bad status code: 501
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMethodTypes on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getVersions on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setAudioSourceScreen on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setSceneSetting on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getBannerMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getSceneSetting on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getAudioSourceScreen on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setBannerMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setPipSubScreenPosition on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setMultiScreenMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getMultiScreenMode on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for setPapScreenSize on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for getPipSubScreenPosition on ws://192.168.1.174/sony
2018-03-10 09:05:05 DEBUG (MainThread) [songpal.service] Got no signature for requestToNotifyScreenState on ws://192.168.1.174/sony
2018-03-10 09:05:05 ERROR (MainThread) [custom_components.media_player.songpal] Unable to get methods from songpal: <Service system: 0 methods, 0 protocols, 0 notifications does not contain method getSystemInformation
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.6018357, level=WARNING, message=Invalid handshake for videoScreen: Bad status code: 501, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.6652887, level=ERROR, message=Unable to get methods from songpal: <Service system: 0 methods, 0 protocols, 0 notifications does not contain method getSystemInformation, exception=, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/tasks.py", line 180, in _step
    result = coro.send(None)
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 197, in _async_add_entity
    if entity.unique_id is not None:
  File "/config/custom_components/media_player/songpal.py", line 97, in unique_id
    return self._sysinfo.macAddr
AttributeError: 'NoneType' object has no attribute 'macAddr'
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.6018357, 'level': 'WARNING', 'message': 'Invalid handshake for videoScreen: Bad status code: 501', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 716857, tzinfo=<UTC>)}}
2018-03-10 09:05:05 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.6652887, 'level': 'ERROR', 'message': 'Unable to get methods from songpal: <Service system: 0 methods, 0 protocols, 0 notifications does not contain method getSystemInformation', 'exception': '', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 720966, tzinfo=<UTC>)}}
2018-03-10 09:05:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1520690705.7483714, level=ERROR, message=Error doing job: Task exception was never retrieved, exception=Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/tasks.py", line 180, in _step
    result = coro.send(None)
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 197, in _async_add_entity
    if entity.unique_id is not None:
  File "/config/custom_components/media_player/songpal.py", line 97, in unique_id
    return self._sysinfo.macAddr
AttributeError: 'NoneType' object has no attribute 'macAddr'
, source=custom_components/media_player/songpal.py>
2018-03-10 09:05:05 DEBUG (SyncWorker_7) [phue] GET /api/ocqzCciAZ77YbiW-OwXA3zdPxBI3os4d3z0msE0v None
2018-03-10 09:05:06 DEBUG (MainThread) [homeassistant.components.websocket_api] WS 1889244272: Sending {'id': 59, 'type': 'event', 'event': {'event_type': 'system_log_event', 'data': {'timestamp': 1520690705.7483714, 'level': 'ERROR', 'message': 'Error doing job: Task exception was never retrieved', 'exception': 'Traceback (most recent call last):\n  File "/usr/lib/python3.6/asyncio/tasks.py", line 180, in _step\n    result = coro.send(None)\n  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 197, in _async_add_entity\n    if entity.unique_id is not None:\n  File "/config/custom_components/media_player/songpal.py", line 97, in unique_id\n    return self._sysinfo.macAddr\nAttributeError: \'NoneType\' object has no attribute \'macAddr\'\n', 'source': 'custom_components/media_player/songpal.py'}, 'origin': 'LOCAL', 'time_fired': datetime.datetime(2018, 3, 10, 14, 5, 5, 829404, tzinfo=<UTC>)}}

MPopti0n commented 6 years ago

For the moment, as a work around BECAUSE I DON'T USE songpal I added

discovery:
  ignore:
    - songpal

to my /config/configuration.yaml and no error on restart!

rytilahti commented 6 years ago

@tleegaard you want to do the pip install in your virtualenv :-) For compiling lxml it will require libxml2 and libxslt1.1 (names may differ depending on your distribution) packages to be installed.

@MPopti0n great! So from the looks of it it implements some songpal protocol functionality, but exposes a different set of functionalities than those devices I know of. I would really appreciate if you could try songpal dump_devinfo in the console and e-mail me (tpr at iki dot fi) the printed out JSON. eidt: looks like it cannot do websocket handshakes on those endpoints, so it may not reveal much extra information though. songpal -dd dump_sysinfo could also be useful in that case. I think the problem could be that the service description is not giving a real port, and thus it tries to connect to wrong port with ws.

All those "Got no signature" warnings show what types of actions are exposed by those devices, so I suppose some of this could also be useful for television owners too.

tleegaard commented 6 years ago

@rytilahti I already did that:

$ source /srv/homeassistant/bin/activate
(homeassistant) homeassistant@orangepizero:/root$ pip install python-songpal

rytilahti commented 6 years ago

Did you also install those packages? Looking into your log above there is the following error:

    ERROR: b'/bin/sh: 1: xslt-config: not found\n'
    ** make sure the development packages of libxml2 and libxslt are installed **

tleegaard commented 6 years ago

root@orangepizero:~# apt install libxslt1.1 libxml2
Reading package lists... Done
Building dependency tree
Reading state information... Done
libxslt1.1 is already the newest version.
libxml2 is already the newest version.

rytilahti commented 6 years ago

Maybe also install libxml2-dev, although it's a bit weird that it's all working just fine here without having that installed (running debian 9.3). If you are on discord, maybe we could continue this discussion there as the github issues are not very good for chatting?

tleegaard commented 6 years ago

libxml2-dev is already the newest version.

Sorry, I'm not in discord. I think I'll just add ignore songpal to the discovery component for now as suggested above..

rytilahti commented 6 years ago

Fair enough, I hope someone will post some logs or propose PRs improve the library to handle other, non-soundbar songpal devices. For now I will just find a way to be not so verbose on errors on not supported devices.

wwolkers commented 6 years ago

I seem to have run into the same errors in HA with a Sony KD-49X8305C:

songpal discover: https://pastebin.com/59kTj6zD songpal dump_devinfo: https://pastebin.com/LpPhcaYL

rytilahti commented 6 years ago

Ok, so also no port information is given. You could try to setting the port manually:

songpal --endpoint http://192.168.16.28:10000/sony status

or instead of 10000 it could also be 54480. Alternatively you could make discover to print out the XML file as shown in this line inside songpal/main.py: https://github.com/rytilahti/python-songpal/commit/8a12e90052497ba89ebb4263a762ddeb6dc8ab31#diff-4ec0c53887b5abcafe860dedefd582efR143

balloob commented 6 years ago

@rytilahti any reason you're using lxml instead of something like xml2dict? Dependencies that require compilation are often difficult for people running custom setups.

rytilahti commented 6 years ago

No specific reason, it came to me as the "go-to" xml parsing library. I will take a look at xml2dict to see if I could use it directly, there is only a minimal level of xml parsing used in general by that lib (it's used just for the discovery process). edit: actually upnpclient uses lxml, and returns back lxml elements, so that's the real reason here.

MPopti0n commented 6 years ago

@rytilahti

I'll do it, just tell me how 😄 for the songpal dump_devinfo and songpal -dd dump_sysinfo and with the original component enable or the custom?

FYI it's running on hassio/raspberry pi 3

wwolkers commented 6 years ago

I ran the status like you asked, but get a connection refused no matter if I user 10000 or 54480 https://pastebin.com/PKaVTewM

rytilahti commented 6 years ago

@wwolkers okay (those are the ports mentioned to be mainly used by the official api homepage), so I'm at loss currently. Maybe you could try it with the autodetected endpoint (songpal discover) and then simply adding some more debug levels (e.g. songpal -dd dump_devinfo).

@MPopti0n I think the way one can do that with hassio is by enabling ssh access and simply connecting to it. The songpal is just a command-line tool for that library and not related directly to homeassistant (so it doesn't matter what kind of component setup you have).

wwolkers commented 6 years ago

I ran the dump_dev with extra debugging, output here: https://pastebin.com/vSHn417m

dshokouhi commented 6 years ago

just upgraded to 0.65.4 and do not have any songpal devices, can we disable this in discovery or something? I dont see the docs mentioning this.

looks like I needed to add songpal to discovery ignore list here is the PR for the doc update https://github.com/home-assistant/home-assistant.github.io/pull/4906.

rytilahti commented 6 years ago

@wwolkers thanks for that, on the hindsight the problem seems obvious now (and well done engineering from sony devels to include 'protocols' part for payloads). The problem was that the library was expecting that all devices use websockets for communication which is not the case, but some (as yours) only support post requests.

I just changed the behavior of the library (https://github.com/rytilahti/python-songpal/commit/4b96e30f580ae539d47830e5360abe109e82e3ff), it would be nice if you could test if it works now for you! pip install -U git+https://github.com/rytilahti/python-songpal.git should do the trick to install the git version. It should detect the protocol to use automatically, but you can also force it to use post by using --post option, e.g. to list available commands use songpal --post list_all or songpal --post status.

edit: to add for someone reading here, I suppose the only real limitation for using the post protocol is the inability to receive push notifications from the device (which I'll be adding soon to the homeassistant platform to receive instantaneous notifications when there are changes in volume, power or source). Other than that the websocket version will likely be faster if the library starts re-using the existing connection for commands instead of connecting to the device separately for each request.

rytilahti commented 6 years ago

@dshokouhi ignoring the auto-detected devices work as with any other automatically discovered device (as you found out), it's documented in https://home-assistant.io/components/discovery/ . Looking into docs of other discovered devices I don't see a mention about how to disable the discovery, although I agree that it could be useful to have that linked to the docs of all auto-discovered devices.

Btw, here's a working link to that PR: https://github.com/home-assistant/home-assistant.github.io/pull/4906 .

rytilahti commented 6 years ago

I made some fixes based on feedback from shakuyi on discord to make it not crash, and I realized this protocol is the very same that is used by the braviarc (the library behind bravia component).

So I suppose what is needed is to figure out what is the best way to handle this case, bravia devices are just a subset of those supported by that protocol, so the songpal library will likely be extended to add support for those too. For the time being the netdisco part could do some magic to try to detect if the device is a bravia and ignore them. Or conversely the songpal platform could ignore the setup of platforms where it is hinted that it's one. Ideas & opinions?

Titirangikid commented 6 years ago

Hi, I have a Sony STR-DN1080 receiver I can adjust source and power but not the volume Home Assistant release Hass.io version 0.65.3

2018-03-13 22:57:48 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getSourceList', 'versions': [{'version': '1.1'}, {'version': '1.2'}]}, using the first one
2018-03-13 22:57:49 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getStorageList', 'versions': [{'authLevel': 'generic', 'version': '1.1'}, {'version': '1.2'}]}, using the first one
2018-03-13 22:57:49 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getSystemInformation', 'versions': [{'version': '1.3'}, {'version': '1.4'}]}, using the first one
2018-03-13 22:57:49 WARNING (MainThread) [root] The device seems to have more than one volume setting.
2018-03-13 22:57:49 WARNING (MainThread) [homeassistant.components.media_player.songpal] Got [Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=1', step=1, volume=23), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=2', step=0, volume=-1), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=4', step=0, volume=-1)] volume controls, using the first one
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-13 22:57:49 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2']} - please create an issue!

rytilahti commented 6 years ago

@Titirangikid for now you could modify the platform source directly, I have mistakenly forgotten to give a parameter to volume.pop() in components/media_player/songpal.py, it should be volume.pop(0).

Titirangikid commented 6 years ago

@rytilahti thanks for your work with this, I don't know how to modify the platform source directly but I will have a read and look into it.

rytilahti commented 6 years ago

@Titirangikid I just created https://github.com/home-assistant/home-assistant/pull/13222 to fix the volume control problem.

Titirangikid commented 6 years ago

@rytilahti Thanks, I will have a look when I get home this evening.

rwifall commented 6 years ago

I get the following errors after upgrading to 0.65.5: (TV is Sony XBR-65X810C)

2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for accessControl: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'setTextForm', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for appControl: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for appControl: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'setAudioVolume', 'versions': [{'version': '1.0', 'authLevel': 'generic'}, {'version': '1.2', 'authLevel': 'generic'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for audio: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for audio: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'setPlayTvContent', 'versions': [{'version': '1.1', 'authLevel': 'generic'}, {'version': '1.0', 'authLevel': 'generic'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getCurrentExternalInputsStatus', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getContentCount', 'versions': [{'version': '1.1', 'authLevel': 'private'}, {'version': '1.0', 'authLevel': 'private'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getContentList', 'versions': [{'version': '1.0', 'authLevel': 'private'}, {'version': '1.2', 'authLevel': 'private'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for avContent: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for avContent: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for cec: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for contentshare: Bad status code: 404
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for encryption: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getCurrentTime', 'versions': [{'version': '1.1'}, {'version': '1.0'}]}, using the first one
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for system: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for system: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for videoScreen: Bad status code: 501
2018-03-15 20:30:22 WARNING (MainThread) [songpal.service] Invalid handshake for videoScreen: Bad status code: 501
2018-03-15 20:30:22 ERROR (MainThread) [homeassistant.components.media_player.songpal] Unable to get methods from songpal: <Service system: 0 methods, 0 protocols, 0 notifications does not contain method getSystemInformation
2018-03-15 20:30:22 WARNING (MainThread) [homeassistant.components.media_player] Platform songpal not ready yet. Retrying in 30 seconds.

Here is the output of songpal discover:

Discovering for 3 seconds
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error 'Start tag expected, '<' not found, line 1, column 1 (<string>, line 1)' for http://10.0.0.45:9080
ERROR:ssdp:Error 'Start tag expected, '<' not found, line 1, column 1 (<string>, line 1)' for http://10.0.0.45:9080
ERROR:ssdp:Error 'Start tag expected, '<' not found, line 1, column 1 (<string>, line 1)' for http://10.0.0.45:9080
ERROR:ssdp:Error 'Start tag expected, '<' not found, line 1, column 1 (<string>, line 1)' for http://10.0.0.45:9080
Found XBR-65X810C - None
* API version: 1.0
* Endpoint: http://10.0.0.209/sony
* Services:
  - Service: guide
  - Service: accessControl
  - Service: encryption
  - Service: contentshare
  - Service: avContent
  - Service: cec
  - Service: audio
  - Service: system
  - Service: appControl
  - Service: videoScreen

rwifall commented 6 years ago

After installing the latest songpal from the github repository:

songpal --post discover returns:

Discovering for 3 seconds
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:32425/DIALSCPD.xml' for http://10.0.0.209:32425/dd.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
ERROR:ssdp:Error '404 Client Error: Not Found for url: http://10.0.0.209:8008/ssdp/notfound' for http://10.0.0.209:8008/ssdp/device-desc.xml
Found XBR-65X810C - None
* API version: 1.0
* Endpoint: http://10.0.0.209/sony
* Services:
  - Service: guide
  - Service: accessControl
  - Service: encryption
  - Service: contentshare
  - Service: avContent
  - Service: cec
  - Service: audio
  - Service: system
  - Service: appControl
  - Service: videoScreen

After further checking both with and without --post returns the same.

rytilahti commented 6 years ago

That is how it is supposed to work, --post just forces post requests for other calls besides 'discovery', but it is also automatically detected, so those errors related to invalid handshakes should also be gone.

Could you please do songpal -dd discover (it will return the service description xml in full), I will use it to disable the auto-detection for bravias for the time being.

rwifall commented 6 years ago

Here it is: songpal_discover.txt

rytilahti commented 6 years ago

Thanks, I picked modelNumber use as a filter, as it seemed to be unavailable on that and other examples (another possibility would have been to do ignore based on exposed services or something similar). Assuming that PR gets accepted the next homeassistant release will not anymore discover the bravias, this can then be considered as closed.

Titirangikid commented 6 years ago

Sony STR-DN1080 receiver Home Assistant release Hass.io version 0.65.6

@rytilahti thanks again, Worked out how to use custom_components ;). Down loaded songpal.py from GitHub and placed it under /custom_components/media_player/

Now volume up/ down, mute and source selection are working but not HDMI Zone, could a separate drop down menu be made for this?

And getting the following logs


2018-03-23 23:18:49 WARNING (MainThread) [songpal.service] Invalid handshake for audio: Malformed HTTP message
2018-03-23 23:18:49 WARNING (MainThread) [songpal.service] Invalid handshake for audio: Malformed HTTP message
2018-03-23 23:18:49 ERROR (MainThread) [homeassistant.components.media_player] Error while setting up platform songpal
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 82, in async_setup
    SLOW_SETUP_MAX_WAIT, loop=hass.loop)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
    return fut.result()
  File "/usr/lib/python3.6/asyncio/futures.py", line 245, in result
    raise self._exception
  File "/usr/lib/python3.6/asyncio/tasks.py", line 180, in _step
    result = coro.send(None)
  File "/config/custom_components/media_player/songpal.py", line 68, in async_setup_platform
    await device.initialize()
  File "/config/custom_components/media_player/songpal.py", line 121, in initialize
    await self.dev.get_supported_methods()
  File "/usr/lib/python3.6/site-packages/songpal/protocol.py", line 82, in get_supported_methods
    self.debug)
  File "/usr/lib/python3.6/site-packages/songpal/service.py", line 93, in from_payload
    for notification in payload["notifications"]]
  File "/usr/lib/python3.6/site-packages/songpal/service.py", line 93, in <listcomp>
    for notification in payload["notifications"]]
KeyError: 'switchNotifications'
2018-03-23 23:18:58 WARNING (MainThread) [homeassistant.components.sensor.template] Could not render template Harmony Activity, the state is unknown.
2018-03-23 23:19:20 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getSourceList', 'versions': [{'version': '1.1'}, {'version': '1.2'}]}, using the first one
2018-03-23 23:19:21 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getStorageList', 'versions': [{'authLevel': 'generic', 'version': '1.1'}, {'version': '1.2'}]}, using the first one
2018-03-23 23:19:21 WARNING (MainThread) [songpal.service] More than on version for {'name': 'getSystemInformation', 'versions': [{'version': '1.3'}, {'version': '1.4'}]}, using the first one
2018-03-23 23:19:21 WARNING (MainThread) [root] The device seems to have more than one volume setting.
2018-03-23 23:19:21 WARNING (MainThread) [custom_components.media_player.songpal] Got [Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=1', step=1, volume=18), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=2', step=0, volume=-1), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=4', step=0, volume=-1)] volume controls, using the first one
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:21 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2']} - please create an issue!
2018-03-23 23:19:25 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2018-03-23 23:19:32 WARNING (MainThread) [root] The device seems to have more than one volume setting.
2018-03-23 23:19:32 WARNING (MainThread) [custom_components.media_player.songpal] Got [Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=1', step=1, volume=18), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=2', step=0, volume=-1), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=4', step=0, volume=-1)] volume controls, using the first one
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2', 'extOutput:zone?zone=4']} - please create an issue!
2018-03-23 23:19:32 WARNING (MainThread) [songpal.containers] Got unknowns for Input: {'outputs': ['extOutput:zone?zone=1', 'extOutput:zone?zone=2']} - please create an issue!
2018-03-23 23:19:43 WARNING (MainThread) [root] The device seems to have more than one volume setting.```

rytilahti commented 6 years ago

This platform is a part of the official release, so there's no need for custom components. Most of those warnings you see (+ the exception when no notifications are available) are already fixed in the library, and I hope I'll manage to get it in for the next homeassistant release. At the moment there is no support for multi-zone and I have no plans to work on it myself, but if someone wants to contribute I'll happily accept PRs: https://github.com/rytilahti/python-songpal/issues/13 .

Titirangikid commented 6 years ago

Sony STR-DN1080 receiver Home Assistant release Hass.io version 0.66.1

@rytilahti I removed songsal from the custom_component, now songpal is not discovered? I also tried adding including to configuration.yaml with no luck.


2018-04-10 00:22:08 ERROR (SyncWorker_10) [pywemo.ssdp] Found malformed XML at http://192.168.1.159:9080: status=ok
2018-04-10 00:22:16 WARNING (MainThread) [homeassistant.helpers.entity] Updating state for camera.camera_gate (<class 'homeassistant.components.camera.uvc.UnifiVideoCamera'>) took 0.412 seconds. Please report platform to the developers at https://goo.gl/Nvioub
2018-04-10 00:22:17 WARNING (MainThread) [homeassistant.setup] Setup of wemo is taking over 10 seconds.
2018-04-10 00:22:25 WARNING (MainThread) [homeassistant.components.sensor.template] Could not render template Harmony Activity, the state is unknown.
2018-04-10 00:22:34 ERROR (SyncWorker_6) [homeassistant.core] Error doing job: Task was destroyed but it is pending!
2018-04-10 00:22:36 WARNING (SyncWorker_10) [netdisco.ssdp] Error fetching description at http://192.168.1.159:55201/devdesc.xml
2018-04-10 00:22:36 WARNING (SyncWorker_10) [netdisco.ssdp] Found malformed XML at http://192.168.1.159:9080: status=ok
2018-04-10 00:22:50 ERROR (MainThread) [homeassistant.components.media_player] Error while setting up platform songpal
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/homeassistant/helpers/entity_platform.py", line 82, in async_setup
    SLOW_SETUP_MAX_WAIT, loop=hass.loop)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 358, in wait_for
    return fut.result()
  File "/usr/lib/python3.6/site-packages/homeassistant/components/media_player/songpal.py", line 61, in async_setup_platform
    device = SongpalDevice(name, endpoint)
  File "/usr/lib/python3.6/site-packages/homeassistant/components/media_player/songpal.py", line 104, in __init__
    self.dev = songpal.Protocol(self.endpoint)
AttributeError: module 'songpal' has no attribute 'Protocol'```

rytilahti commented 6 years ago

@Titirangikid you are using too old version of songpal library, Protocol was renamed to Device (fixed in f3ccbda mentioned above).

Titirangikid commented 6 years ago

@rytilahti sorry for late reply, did a full fresh install and songpal discovered :) Sony STR-DN1080 receiver - multi-zone warnings


4:13 PM components/media_player/songpal.py (WARNING)
The device seems to have more than one volume setting.
4:13 PM components/media_player/songpal.py (WARNING)
Got [Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=1', step=1, volume=12), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=2', step=0, volume=-1), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=4', step=0, volume=-1)] volume controls, using the first one
4:12 PM components/media_player/songpal.py (WARNING)
The device seems to have more than one volume setting.
4:12 PM components/media_player/songpal.py (WARNING)
Got [Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=1', step=1, volume=12), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=2', step=0, volume=-1), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=4', step=0, volume=-1)] volume controls, using the first one
4:12 PM components/media_player/songpal.py (WARNING)
The device seems to have more than one volume setting.
4:12 PM components/media_player/songpal.py (WARNING)
Got [Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=1', step=1, volume=12), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=2', step=0, volume=-1), Volume(maxVolume=55, minVolume=0, mute='off', output='extOutput:zone?zone=4', step=0, volume=-1)] volume controls, using the first one
4:12 PM components/media_player/songpal.py (WARNING)
The device seems to have more than one volume setting.
4:12 PM components/media_player/songpal.py (WARNING)```

rytilahti commented 6 years ago

Hmm, maybe it'd make sense also to move those to DEBUG level, the original idea was just to have some sort of indicator if there'd be more than the one controlled volume level.

home-assistant / core

Songpal error with 0.65 #13022