timeout when running facade loop

glibersat commented 8 years ago

Hi Matt,

Here's what I get when running a ControllerDiscoveryFacade in a celery task with these discoveries:

discoveries = [ ControllerDiscoveryFacade.build_serial_discovery(sniffer), ControllerDiscoveryFacade.build_tcp_server_discovery(sniffer, "brewpi", known_addresses=(TCPServerEndpoint('localhost', '127.0.0.1', 8332),)), ]

Traceback:

timed out Traceback (most recent call last): File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/protocol/async.py", line 201, in _do callme() File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/connector_facade.py", line 78, in loop self._open() File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/connector_facade.py", line 64, in _open connector.connect() File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/connector/base.py", line 125, in connect self._conduit = self._connect() File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/connector/base.py", line 302, in _connect self._protocol = self._sniffer(result) File "/home/glibersat/Sources/brewpi-env/brewpiweb/controller/tasks.py", line 14, in sniffer return determine_line_protocol(conduit, all_sniffers) File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/protocol/io.py", line 69, in determine_line_protocol l = conduit.input.readline() File "/home/glibersat/Sources/brewpi-env/controlbox-connect-py/controlbox/support/proxy.py", line 28, in wrapped result = func(_args, *_kwargs) File "/usr/lib/python3.5/socket.py", line 575, in readinto return self._sock.recv_into(b) socket.timeout: timed out

You can try that once I've updated the connector-integration branch on brewpiweb.

Guillaume

glibersat commented 8 years ago

Retried it from the example (no celery integration), I now get the same error.

m-mcgowan commented 8 years ago

Hiya, what's the setup here - are you using a real controller, or a virtual one? What problems does it cause? some of the exception messages are harmless and just logged for completeness, and will probably be removed to avoid clutter.

glibersat commented 8 years ago

I'm using a virtual one and it seems like it's preventing events from occuring. My loggings and prints won't show anything.

m-mcgowan commented 7 years ago

I'm not able to reproduce this.

Here's my setup:

OSX
Running connector.test.connector_test.py
using the local executable cbox-gcc.

When I run I see the various events as expected:

controlbox.events.ObjectUpdatedEvent object at 0x1070a7dd8>:{'connector': '<controlbox.events.ControlboxEvents object at 0x1070a7a90>', 'idchain': 'bytearray(b'\x01')', 'requested_state': None, 'state': '<brewpi.connector.codecs.time.ScaledTime object at 0x1070a7e48>:{'scale': '1', 'time': '10038'}', 'type': '1'}
<controlbox.events.ObjectUpdatedEvent object at 0x1070a7cf8>:{'connector': '<controlbox.events.ControlboxEvents object at 0x1070a7a90>', 'idchain': 'bytearray(b'\x00')', 'requested_state': None, 'state': 'b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'', 'type': '0'}
<controlbox.events.ObjectUpdatedEvent object at 0x1070a7e80>:{'connector': '<controlbox.events.ControlboxEvents object at 0x1070a7a90>', 'idchain': 'bytearray(b'\x01')', 'requested_state': None, 'state': '<brewpi.connector.codecs.time.ScaledTime object at 0x1070a7438>:{'scale': '1', 'time': '11043'}', 'type': '1'}
<controlbox.events.ObjectUpdatedEvent object at 0x1070a7b38>:{'connector': '<controlbox.events.ControlboxEvents object at 0x1070a7a90>', 'idchain': 'bytearray(b'\x00')', 'requested_state': None, 'state': 'b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'', 'type': '0'}
<contro

m-mcgowan commented 7 years ago

I found that if I launch the executable manually, and then kill it I get lots of output, and things are not good. So I have something to investigate here :-)

glibersat commented 7 years ago

Hi Matt,

Just tried your fix, but unfortunately, I still get a timeout. Here's my log with debug statements to help you trace the problem:

(brewpi-env) glibersat@mouette:~/Sources/brewpi-env/brewpi-service$ python service.py 2016-11-03 21:39:03 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:03 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:03 mouette controller.controlbox[16726] DEBUG _handle_connection 2016-11-03 21:39:03 mouette controlbox.connector.socketconn[16726] INFO opened socket to ('localhost', 8332) 2016-11-03 21:39:04 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:04 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:04 mouette controller.controlbox[16726] DEBUG _handle_connection 2016-11-03 21:39:05 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:05 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:05 mouette controller.controlbox[16726] DEBUG _handle_connection 2016-11-03 21:39:06 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:06 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:06 mouette controller.controlbox[16726] DEBUG _handle_connection 2016-11-03 21:39:07 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:07 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:07 mouette controller.controlbox[16726] DEBUG _handle_connection 2016-11-03 21:39:08 mouette controlbox.protocol.async[16726] ERROR timed out Traceback (most recent call last): File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/protocol/async.py", line 201, in _do callme() File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/connector_facade.py", line 78, in loop self._open() File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/connector_facade.py", line 64, in _open connector.connect() File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/connector/base.py", line 125, in connect self._conduit = self._connect() File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/connector/base.py", line 302, in _connect self._protocol = self._sniffer(result) File "/home/glibersat/Sources/brewpi-env/brewpi-service/controller/controlbox.py", line 27, in sniffer return determine_line_protocol(conduit, all_sniffers) File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/protocol/io.py", line 69, in determine_line_protocol l = conduit.input.readline() File "/home/glibersat/Sources/brewpi-env/lib/python3.5/site-packages/controlbox_connector_py-0.0.1-py3.5.egg/controlbox/support/proxy.py", line 28, in wrapped result = func(_args, *_kwargs) File "/usr/lib/python3.5/socket.py", line 575, in readinto return self._sock.recv_into(b) socket.timeout: timed out 2016-11-03 21:39:08 mouette controlbox.connector.socketconn[16726] INFO opened socket to ('localhost', 8332) 2016-11-03 21:39:08 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:08 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:08 mouette controller.controlbox[16726] DEBUG _handle_connection 2016-11-03 21:39:09 mouette controller.controlbox[16726] DEBUG update facade... 2016-11-03 21:39:09 mouette controller.controlbox[16726] DEBUG loop over connections... 2016-11-03 21:39:09 mouette controller.controlbox[16726] DEBUG _handle_connection

elcojacobs commented 7 years ago

It it possible that the socket just times out because no data has been received before the timeout setting of the socket?

Maybe the default configuration is different on OSX compared to linux.

We should either:

Have a timeout and an exception handler for it (in case of no data received)
Have a non-blocking socket (timeout = 0) and poll the socket regularly for new data received. Never wait for data in the read.

And also probably:

Configure all socket settings explicitly instead of using defaults.

m-mcgowan commented 7 years ago

it's failing to detect the protocol. Can you check that the socket is providing some data? it should output a line like this

["a":"brewpi","v":"0.3.0"]

You should see this when running cbox-gcc - it's echoed to stdout, and also to each socket connection:

# cbox-gcc already running elsewhere
mat1$ telnet localhost 8332
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
["a":"brewpi","v":"0.3.0"]

glibersat commented 7 years ago

Something interesting here:

That's what I have in stdout: ["a":"brewpi","v":"0.3.0"]

But, when using telnet:

$ telnet localhost 8332 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'.

Nothing is outputted. You're on the right track I guess @m-mcgowan :)

m-mcgowan commented 7 years ago

Resolved - was a bug in the USB HAL for the gcc device, which caused the executable to lock up. fixed here https://github.com/BrewPi/firmware/commit/260da373ff9a9b0f60905c473d4ec04308314257

ctlbox / controlbox-connector-py

timeout when running facade loop #4