Issue with Network pycec commands

[lorddaren]

I am seeing an issue with HA communicating with the pycec server on a Raspberry Pi B+ running Raspbian.

I get this in my HA logs:

INFO (Thread-22) [pycec] Looking for new devices...

But it does not return anything until I run the following from the RaspberryPi

echo scan | cec-client -s -d 1

The same thing happens when I issue a command from HA. It will not send the command until I run a scan on the cec-client.

Logs from pycec server

Feb  2 07:00:12 raspberrypi systemd[1]: Starting pycec...
Feb  2 07:00:12 raspberrypi systemd[1]: Started pycec.
Feb  2 07:00:14 raspberrypi pycec[21883]: 2017-02-02 07:00:14,959 - pycec - WARNING - Be aware! Network is using shared event loop!
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,004 - pycec - DEBUG - initializing
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,011 - pycec - DEBUG - setting callback
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,017 - pycec - DEBUG - Callback set
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,026 - pycec.cec - DEBUG - Initializing CEC...
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,048 - pycec.cec - DEBUG - Created adapter
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,029 - pycec - DEBUG - Init pending - <Future pending cb=[wrap_future.<locals>._check_cancel_other() at /usr/lib/python3.4/asyncio/futures.py:403]>
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,173 - pycec.cec - INFO - found a CEC adapter:
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,179 - pycec.cec - INFO - port:     RPI
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,185 - pycec.cec - INFO - vendor:   0x2708
Feb  2 07:00:15 raspberrypi pycec[21883]: 2017-02-02 07:00:15,187 - pycec.cec - INFO - product:  0x1001
Feb  2 07:00:16 raspberrypi pycec[21883]: 2017-02-02 07:00:16,447 - pycec - DEBUG - Init pending - <Future pending cb=[wrap_future.<locals>._check_cancel_other() at /usr/lib/python3.4/asyncio/futures.py:403]>
Feb  2 07:00:16 raspberrypi pycec[21883]: 2017-02-02 07:00:16,455 - pycec.cec - INFO - connection opened
Feb  2 07:00:17 raspberrypi pycec[21883]: 2017-02-02 07:00:17,464 - pycec - DEBUG - Init done
Feb  2 07:00:17 raspberrypi pycec[21883]: 2017-02-02 07:00:17,474 - pycec - INFO - CEC initialized... Starting server.
Feb  2 07:00:17 raspberrypi pycec[21883]: 2017-02-02 07:00:17,576 - pycec - INFO - Serving on ('0.0.0.0', 9526)
Feb  2 07:01:59 raspberrypi pycec[21883]: 2017-02-02 07:01:59,762 - pycec - INFO - Connection opened by ('192.168.0.10', 50528)

After running scan from cec-client locally

Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,314 - pycec - DEBUG - >> 4f:87:00:10:fa
Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,339 - pycec - INFO - Sending 4f:87:00:10:fa to ('192.168.0.10', 50528)
Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,360 - pycec - INFO - Received poll f0 from ('192.168.0.10', 50528)
Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,369 - pycec - INFO - Received poll f1 from ('192.168.0.10', 50528)
Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,689 - pycec - DEBUG - >> 4f:84:10:00:04
Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,694 - pycec - INFO - Received poll f2 from ('192.168.0.10', 50528)
Feb  2 07:08:32 raspberrypi pycec[21883]: 2017-02-02 07:08:32,710 - pycec - INFO - Received poll f3 from ('192.168.0.10', 50528)
Feb  2 07:08:33 raspberrypi pycec[21883]: 2017-02-02 07:08:33,024 - pycec - DEBUG - >> 41:9e:05
Feb  2 07:08:33 raspberrypi pycec[21883]: 2017-02-02 07:08:33,029 - pycec - INFO - Received poll f4 from ('192.168.0.10', 50528)
Feb  2 07:08:33 raspberrypi pycec[21883]: 2017-02-02 07:08:33,674 - pycec - INFO - Received poll f5 from ('192.168.0.10', 50528)
Feb  2 07:08:33 raspberrypi pycec[21883]: 2017-02-02 07:08:33,729 - pycec - INFO - Received poll f6 from ('192.168.0.10', 50528)
Feb  2 07:08:34 raspberrypi pycec[21883]: 2017-02-02 07:08:34,120 - pycec - DEBUG - >> 41:90:01
Feb  2 07:08:34 raspberrypi pycec[21883]: 2017-02-02 07:08:34,123 - pycec - INFO - Received poll f7 from ('192.168.0.10', 50528)
Feb  2 07:08:34 raspberrypi pycec[21883]: 2017-02-02 07:08:34,512 - pycec - INFO - Received poll f8 from ('192.168.0.10', 50528)
Feb  2 07:08:34 raspberrypi pycec[21883]: 2017-02-02 07:08:34,796 - pycec - DEBUG - >> 41:47:41:70:70:6c:65:20:54:56
Feb  2 07:08:34 raspberrypi pycec[21883]: 2017-02-02 07:08:34,801 - pycec - INFO - Received poll f9 from ('192.168.0.10', 50528)
Feb  2 07:08:35 raspberrypi pycec[21883]: 2017-02-02 07:08:34,862 - pycec - DEBUG - >> 41:00:91:00
Feb  2 07:08:35 raspberrypi pycec[21883]: 2017-02-02 07:08:34,871 - pycec - INFO - Received poll fa from ('192.168.0.10', 50528)
Feb  2 07:08:35 raspberrypi pycec[21883]: 2017-02-02 07:08:35,230 - pycec - INFO - Received poll fb from ('192.168.0.10', 50528)
Feb  2 07:08:35 raspberrypi pycec[21883]: 2017-02-02 07:08:35,242 - pycec - INFO - Received poll fc from ('192.168.0.10', 50528)
Feb  2 07:08:35 raspberrypi pycec[21883]: 2017-02-02 07:08:35,834 - pycec - INFO - Received poll fd from ('192.168.0.10', 50528)
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:35,831 - pycec - DEBUG - >> 8f:87:08:00:46
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,417 - pycec - DEBUG - >> 8f:84:40:00:04
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,168 - pycec - INFO - Received poll fe from ('192.168.0.10', 50528)
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,431 - pycec - INFO - Received poll f0 from ('192.168.0.10', 50528)
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,622 - pycec - INFO - Received poll f1 from ('192.168.0.10', 50528)
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,618 - pycec - DEBUG - >> 81:9e:05
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,820 - pycec - DEBUG - >> 81:90:01
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,810 - pycec - INFO - Received poll f2 from ('192.168.0.10', 50528)
Feb  2 07:08:36 raspberrypi pycec[21883]: 2017-02-02 07:08:36,834 - pycec - INFO - Received poll f3 from ('192.168.0.10', 50528)
Feb  2 07:08:37 raspberrypi pycec[21883]: 2017-02-02 07:08:37,021 - pycec - DEBUG - >> 81:47:42:44
Feb  2 07:08:37 raspberrypi pycec[21883]: 2017-02-02 07:08:37,219 - pycec - DEBUG - >> 81:00:91:00
Feb  2 07:08:37 raspberrypi pycec[21883]: 2017-02-02 07:08:37,025 - pycec - INFO - Received poll f4 from ('192.168.0.10', 50528)

[konikvranik]

@Xorso: Thank you for this report. Can you test if this behavior repeats when you run pyCEC in HA locally (no client/server).

Another question: when you run server, do you also connect client? Because server is only bridge or we cal call it adapter - it does not do anything else than brigding commands between HDMI and TCP. Scanning and polling CEC devices is done by clients side. So when you run server you have to connect to it by client - e.g. HA runnyng hdmi_cec with host set to servers address.

[lorddaren]

Is pycec the default now for hdmi_cec in HA? If so then yes it was tested and worked (with limited functionality) as I did it a couple of weeks back.

If I connect to the server locally using the following it works and the server receives the events:

>>> from pycec.commands import CecCommand, KeyPressCommand, KeyReleaseCommand, \
...     PollCommand
>>> from pycec.const import CMD_STANDBY, KEY_POWER
>>> from pycec.network import AbstractCecAdapter, HDMINetwork
>>> from pycec.tcp import TcpAdapter
>>> tcp_adapter = TcpAdapter('192.168.0.52', name='HASS', activate_source=False)
>>> hdmi_network = HDMINetwork(tcp_adapter)
>>> hdmi_network.start()
>>> Not initialized. Waiting for init.

>>> hdmi_network.devices
()
>>> tcp_adapter.power_on_devices()

[konikvranik]

@Xorso So everything seems to be OK.

Pycec is in home assistant from version 0.37 (released this weekend). Do you have host: "192.168.0.52" in home assistant config?

[lorddaren]

Here is what I have in my config. I should probably mention that I am running this out of the docker container. I don't think that should make much of a difference though since I am showing a connection from the pycec server.

hdmi_cec:
  host: 192.168.0.52

So I decided to try and connect to the server directly from the docker container with better results:

Feb  3 05:56:03 raspberrypi pycec[21883]: 2017-02-03 05:56:03,895 - pycec - INFO - Connection opened by ('192.168.0.10', 47336)
Feb  3 05:56:04 raspberrypi pycec[21883]: 2017-02-03 05:56:04,891 - pycec - INFO - Received poll f0 from ('192.168.0.10', 47336)
Feb  3 05:56:04 raspberrypi pycec[21883]: 2017-02-03 05:56:04,912 - pycec - INFO - Received poll f1 from ('192.168.0.10', 47336)
Feb  3 05:56:04 raspberrypi pycec[21883]: 2017-02-03 05:56:04,928 - pycec - INFO - Received poll f2 from ('192.168.0.10', 47336)
Feb  3 05:56:05 raspberrypi pycec[21883]: 2017-02-03 05:56:05,007 - pycec - INFO - Received poll f3 from ('192.168.0.10', 47336)
Feb  3 05:56:09 raspberrypi pycec[21883]: 2017-02-03 05:56:09,894 - pycec - INFO - Received poll f4 from ('192.168.0.10', 47336)
Feb  3 05:56:09 raspberrypi pycec[21883]: 2017-02-03 05:56:09,915 - pycec - INFO - Received poll f5 from ('192.168.0.10', 47336)
Feb  3 05:56:10 raspberrypi pycec[21883]: 2017-02-03 05:56:10,010 - pycec - INFO - Received poll f6 from ('192.168.0.10', 47336)
Feb  3 05:56:10 raspberrypi pycec[21883]: 2017-02-03 05:56:10,130 - pycec - INFO - Received poll f7 from ('192.168.0.10', 47336)
Feb  3 05:56:14 raspberrypi pycec[21883]: 2017-02-03 05:56:14,913 - pycec - INFO - Received poll f8 from ('192.168.0.10', 47336)
Feb  3 05:56:14 raspberrypi pycec[21883]: 2017-02-03 05:56:14,934 - pycec - INFO - Received poll f9 from ('192.168.0.10', 47336)
Feb  3 05:56:15 raspberrypi pycec[21883]: 2017-02-03 05:56:15,128 - pycec - INFO - Received poll fa from ('192.168.0.10', 47336)
Feb  3 05:56:15 raspberrypi pycec[21883]: 2017-02-03 05:56:15,220 - pycec - INFO - Received poll fb from ('192.168.0.10', 47336)
Feb  3 05:56:19 raspberrypi pycec[21883]: 2017-02-03 05:56:19,913 - pycec - INFO - Received poll fc from ('192.168.0.10', 47336)
Feb  3 05:56:19 raspberrypi pycec[21883]: 2017-02-03 05:56:19,947 - pycec - INFO - Received poll fd from ('192.168.0.10', 47336)
Feb  3 05:56:20 raspberrypi pycec[21883]: 2017-02-03 05:56:20,214 - pycec - INFO - Received poll fe from ('192.168.0.10', 47336)
Feb  3 05:56:34 raspberrypi pycec[21883]: 2017-02-03 05:56:34,991 - pycec - INFO - Received poll f0 from ('192.168.0.10', 47336)
Feb  3 05:56:35 raspberrypi pycec[21883]: 2017-02-03 05:56:35,014 - pycec - INFO - Received poll f1 from ('192.168.0.10', 47336)
Feb  3 05:56:35 raspberrypi pycec[21883]: 2017-02-03 05:56:35,024 - pycec - INFO - Received poll f2 from ('192.168.0.10', 47336)
Feb  3 05:56:35 raspberrypi pycec[21883]: 2017-02-03 05:56:35,037 - pycec - INFO - Received poll f3 from ('192.168.0.10', 47336)
Feb  3 05:56:40 raspberrypi pycec[21883]: 2017-02-03 05:56:40,008 - pycec - INFO - Received poll f4 from ('192.168.0.10', 47336)
Feb  3 05:56:40 raspberrypi pycec[21883]: 2017-02-03 05:56:40,032 - pycec - INFO - Received poll f5 from ('192.168.0.10', 47336)
Feb  3 05:56:40 raspberrypi pycec[21883]: 2017-02-03 05:56:40,043 - pycec - INFO - Received poll f6 from ('192.168.0.10', 47336)
Feb  3 05:56:40 raspberrypi pycec[21883]: 2017-02-03 05:56:40,078 - pycec - INFO - Received poll f7 from ('192.168.0.10', 47336)
Feb  3 05:56:45 raspberrypi pycec[21883]: 2017-02-03 05:56:45,013 - pycec - INFO - Received poll f8 from ('192.168.0.10', 47336)
Feb  3 05:56:45 raspberrypi pycec[21883]: 2017-02-03 05:56:45,036 - pycec - INFO - Received poll f9 from ('192.168.0.10', 47336)
Feb  3 05:56:45 raspberrypi pycec[21883]: 2017-02-03 05:56:45,047 - pycec - INFO - Received poll fa from ('192.168.0.10', 47336)
Feb  3 05:56:45 raspberrypi pycec[21883]: 2017-02-03 05:56:45,072 - pycec - INFO - Received poll fb from ('192.168.0.10', 47336)
Feb  3 05:56:50 raspberrypi pycec[21883]: 2017-02-03 05:56:50,016 - pycec - INFO - Received poll fc from ('192.168.0.10', 47336)
Feb  3 05:56:50 raspberrypi pycec[21883]: 2017-02-03 05:56:50,043 - pycec - INFO - Received poll fd from ('192.168.0.10', 47336)
Feb  3 05:56:50 raspberrypi pycec[21883]: 2017-02-03 05:56:50,063 - pycec - INFO - Received poll fe from ('192.168.0.10', 47336)
Feb  3 05:57:05 raspberrypi pycec[21883]: 2017-02-03 05:57:05,223 - pycec - INFO - Received poll f0 from ('192.168.0.10', 47336)
Feb  3 05:57:05 raspberrypi pycec[21883]: 2017-02-03 05:57:05,246 - pycec - INFO - Received poll f1 from ('192.168.0.10', 47336)
Feb  3 05:57:05 raspberrypi pycec[21883]: 2017-02-03 05:57:05,257 - pycec - INFO - Received poll f2 from ('192.168.0.10', 47336)
Feb  3 05:57:05 raspberrypi pycec[21883]: 2017-02-03 05:57:05,366 - pycec - INFO - Received poll f3 from ('192.168.0.10', 47336)
Feb  3 05:57:10 raspberrypi pycec[21883]: 2017-02-03 05:57:10,206 - pycec - INFO - Received poll f4 from ('192.168.0.10', 47336)
Feb  3 05:57:10 raspberrypi pycec[21883]: 2017-02-03 05:57:10,228 - pycec - INFO - Received poll f5 from ('192.168.0.10', 47336)
Feb  3 05:57:10 raspberrypi pycec[21883]: 2017-02-03 05:57:10,239 - pycec - INFO - Received poll f6 from ('192.168.0.10', 47336)
Feb  3 05:57:10 raspberrypi pycec[21883]: 2017-02-03 05:57:10,366 - pycec - INFO - Received poll f7 from ('192.168.0.10', 47336)
Feb  3 05:57:15 raspberrypi pycec[21883]: 2017-02-03 05:57:15,228 - pycec - INFO - Received poll f8 from ('192.168.0.10', 47336)
Feb  3 05:57:15 raspberrypi pycec[21883]: 2017-02-03 05:57:15,248 - pycec - INFO - Received poll f9 from ('192.168.0.10', 47336)
Feb  3 05:57:15 raspberrypi pycec[21883]: 2017-02-03 05:57:15,270 - pycec - INFO - Received poll fa from ('192.168.0.10', 47336)
Feb  3 05:57:15 raspberrypi pycec[21883]: 2017-02-03 05:57:15,368 - pycec - INFO - Received poll fb from ('192.168.0.10', 47336)
Feb  3 05:57:20 raspberrypi pycec[21883]: 2017-02-03 05:57:20,229 - pycec - INFO - Received poll fc from ('192.168.0.10', 47336)
Feb  3 05:57:20 raspberrypi pycec[21883]: 2017-02-03 05:57:20,250 - pycec - INFO - Received poll fd from ('192.168.0.10', 47336)
Feb  3 05:57:20 raspberrypi pycec[21883]: 2017-02-03 05:57:20,286 - pycec - INFO - Received poll fe from ('192.168.0.10', 47336)
Feb  3 05:57:20 raspberrypi pycec[21883]: 2017-02-03 05:57:20,486 - pycec - INFO - Received command ff:36 from ('192.168.0.10', 47336)
Feb  3 05:57:20 raspberrypi pycec[21883]: 2017-02-03 05:57:20,498 - pycec - DEBUG - << ff:36

However, if I call the standby service from within home-assistant I get this in the logs:

ha                | 17-02-03 05:59:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service_data=, service=standby, domain=hdmi_cec, service_call_id=140024558178256-74>

But on the server, I do not see any communication sent.

[konikvranik]

@Xorso: You have to allow communication between pyCEC server and pyCEC client. PyCEC uses port 9526 so be sure you have it accessible.

[lorddaren]

I believe it is allowed since I am communicating with it through the docker container. There is something within home-assistant that is not allowing the communication. When I start HA it shows the connection from HA in the pycec server logs, but no commands function as mentioned in the issue description.

[konikvranik]

@Xorso: CAn you describe architecture of your system? hwat hardware what connection betwee what is inside docker, what is outside what OS is running on your systems?

[lorddaren]

RaspberryPi B+ (Raspbian): Connected to the TV via HDMI. Nothing else running on it except PyCEC. Asus Notebook (Running Antegros or Arch Linux): Runs home-assistant in the docker container provided by the home-assistant community. There is only one switch between the two machines running over 1GB ports. Is that what you were asking?

[konikvranik]

@Xorso: What type of network driver do you use in docker? Can you connect to running docker container and test to connect RPi on 9526 via nc? And send some CEC comand to test if it works?

[lorddaren]

I did that in the comment right before you closed the ticket. Everything works from inside the docker container. It is just the commands from HASS that are not working.

[treynaer]

I'm having the same issue. Other people with a similar issue: HDMI CEC with pycec Remote

[demonspork]

Yeah. My setup is Docker on Unraid, pycec is running on a raspberry pi that used to run my Home Assistant installation and was working with the previous cec component. I get a messagie about "connection opened" in the logs for pycec on the pi, and the Home-Assistant logs occasioanlly say [pycec] Looking for new devices... but nothing is ever found and no further messages are ever played in the pycec log.

[schmittx]

Similar but related concern, I want to use pyCEC TCP network commands with multiple hosts. Anyone have any experience with this? Current capability doesn't seem to support this so I'm looking for some dev advice/support...

[hamishfagg]

FWIW i am now having the exact same issue. Pycec running and sees a new connection opened from the HASS machine, but no other data is sent from hdmi_cec to pycec. I can connect and operate pycec manually from another pc just fine.

[konikvranik]

Hi guys, looks more of you has similar problem, so I try to reserve some time to investigate this in the future. Can you exactly describe environment where this happen? Looks like this happens just with HA in docker?

[hamishfagg]

@konikvranik I have moved to using a cec-mqtt bidge to get this working. But I was running pyCEC on a pi-zero W connected to my wifi. HASS is running on an UnRAID server in docker. The HASS container's network is set to bridge (not host). Though I tried host networking and it made no difference.

Let me know if you need any other specific info.

[konikvranik]

So trouble makes pyCEC running somewhere directly on host and hass in docker if I understand it correctly. then connection is created but communication not working in this connection?

[hamishfagg]

Yep that's correct

[rocksolid2018]

did anyone get the pycec to work over network? HA simply not sending any commands to pycec server

[glassbase]

Really wish there was a fix for this. I am in same boat. HA in Docker running on dedicated docker host. RasPi connected to my dumb TV, installed and running pyCEC server.

I see HA open the connection with pyCEC using verbose logging, but nothing initializes in HA.