Songpal error with 0.65

[tleegaard]

With #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]

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

[rytilahti]

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]

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]

@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]

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]

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]

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

[rytilahti]

@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]

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

[tleegaard]

@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]

Sooooo.... there it is @rytilahti ! 😛

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]

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]

@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]

@rytilahti I already did that:

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

[rytilahti]

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 **