Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Robot freezes when running steps longer than 30s #2822

Closed
utimcraig opened this issue Dec 13, 2018 · 9 comments · Fixed by #3389
Closed

Robot freezes when running steps longer than 30s #2822

utimcraig opened this issue Dec 13, 2018 · 9 comments · Fixed by #3389
Labels
api Affects the `api` project bug medium

Comments

@utimcraig
Copy link

utimcraig commented Dec 13, 2018

overview

When I am using a protocol from protocol designer, the robot freezes after the first aspirating/dispense step. The steps after the first one use the "New pipette tip "never"" option, I'm not sure if that is related to this issue. This protocol is from the PD ignores aspirate/dispense speeds However it also occurs when using a hand-written .py protocol (attached at bottom of chain)

current behavior

Robot stops working, run timer also stops.
image

The api.log mentions a serial response error. I also have run this protocol using only USB, USB+Wifi, and Wifi connections and it happens on every type of connection between the computer and the robot. I'm guessing maybe this serial connection doesn't really have anything to due with the wifi vs usb connection but you guys can help hopefully.

Additionally, after getting this error I have to power cycle the robot to get it to communicate with the computer again.

steps to reproduce

I tried running either the test.json file (renamed here so I can upload it to github). The api and serial logs are uploaded here:
api.log
serial.log

Test-json-renamed to txt for github upload.txt

expected behavior

The robot should perform the protocol from PD without freezing.

@utimcraig
Copy link
Author

utimcraig commented Dec 13, 2018

Here is the error from the developer console:
logger.js:43 [app/src\robot\api-client\index.js] warn: Error response from robot
(anonymous) @ logger.js:43
a @ logger.js:32
e.onmessage @ index.js:27
logger.js:51 Object
logger.js:43 [app/src\robot\api-client\index.js] warn: Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 340, in _recursive_update_position
return _parse_position_response(position_response)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 144, in _parse_position_response
raise ParseError(msg)
opentrons.drivers.smoothie_drivers.driver_3_0.ParseError: Unexpected response in _parse_position_response:

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 340, in _recursive_update_position
return _parse_position_response(position_response)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 144, in _parse_position_response
raise ParseError(msg)
opentrons.drivers.smoothie_drivers.driver_3_0.ParseError: Unexpected response in _parse_position_response: L:703330305F6D756C74695F76310000000000000000000k

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 287, in make_call
self.executor, self.call_and_serialize, func)
File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
result = self.fn(*self.args, **self.kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 277, in call_and_serialize
call_result = func()
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/api/calibration.py", line 88, in return_tip
inst.return_tip(home_after=True)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/commands/commands.py", line 371, in decorated
res = f(*args, **kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/instruments/pipette.py", line 870, in return_tip
self.drop_tip(self.current_tip(), home_after=home_after)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/instruments/pipette.py", line 1064, in drop_tip
return _drop_tip(location)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/commands/commands.py", line 371, in decorated
res = f(*args, **kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/instruments/pipette.py", line 1055, in _drop_tip
self._home_after_drop_tip()
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/instruments/pipette.py", line 1101, in _home_after_drop_tip
self.robot.poses, safety_margin)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/robot/mover.py", line 77, in fast_home
safety_margin=safety_margin
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 1223, in fast_home
return self.home(axis=axis, disabled=disabled)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 1187, in home
self.update_position(default=homed)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 350, in update_position
DEFAULT_COMMAND_RETRIES)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 347, in _recursive_update_position
return _recursive_update_position(retries)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 347, in _recursive_update_position
return _recursive_update_position(retries)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 344, in _recursive_update_position
raise e
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 340, in _recursive_update_position
return _parse_position_response(position_response)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 144, in _parse_position_response
raise ParseError(msg)
opentrons.drivers.smoothie_drivers.driver_3_0.ParseError: Unexpected response in _parse_position_response: 676C655

(anonymous) @ logger.js:43
a @ logger.js:32
e.onmessage @ index.js:28
blob:file:///4eed1a3c-86c3-4d64-b0d4-fd0a5eb14632:14 "session" message: {state: "running", startTime: 1544739385916, lastCommand: {…}, _id: 1882715552}
blob:file:///4eed1a3c-86c3-4d64-b0d4-fd0a5eb14632:14 "session" message: {state: "running", startTime: 1544739385916, lastCommand: {…}, _id: 1882715312}
blob:file:///4eed1a3c-86c3-4d64-b0d4-fd0a5eb14632:14 "session" message: {state: "error", startTime: 1544739385916, lastCommand: {…}, _id: 1882714784}
logger.js:43 [app/src\robot\api-client\index.js] warn: Error response from robot
(anonymous) @ logger.js:43
a @ logger.js:32
e.onmessage @ index.js:27
logger.js:51 Object
logger.js:43 [app/src\robot\api-client\index.js] warn: Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 862, in _recursive_write_and_return
timeout=timeout)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 104, in write_and_return
response = _write_to_device_and_return(command, ack, device_connection)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 68, in _write_to_device_and_return
device_connection.timeout))
opentrons.drivers.serial_communication.SerialNoResponse: No response from serial port after 1 second(s)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 862, in _recursive_write_and_return
timeout=timeout)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 104, in write_and_return
response = _write_to_device_and_return(command, ack, device_connection)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 68, in _write_to_device_and_return
device_connection.timeout))
opentrons.drivers.serial_communication.SerialNoResponse: No response from serial port after 1 second(s)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 287, in make_call
self.executor, self.call_and_serialize, func)
File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
result = self.fn(*self.args, **self.kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 275, in call_and_serialize
call_result = loop.run_until_complete(func())
File "/usr/local/lib/python3.6/asyncio/base_events.py", line 467, in run_until_complete
return future.result()
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/api/session.py", line 273, in run
raise e
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/api/session.py", line 264, in run
execute_protocol(self._protocol)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/protocols/init.py", line 227, in execute_protocol
dispatch_commands(protocol, loaded_pipettes, loaded_labware)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/protocols/init.py", line 203, in dispatch_commands
pipette.aspirate(volume, location)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/commands/commands.py", line 371, in decorated
res = f(*args, **kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/instruments/pipette.py", line 424, in aspirate
x=mm_position
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/robot/mover.py", line 64, in move
self._driver.move(driver_target, home_flagged_axes=home_flagged_axes)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 1118, in move
self._set_saved_current()
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 694, in _set_saved_current
self._send_command(self._generate_current_command())
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 818, in _send_command
command_line, timeout, DEFAULT_COMMAND_RETRIES)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 873, in _recursive_write_and_return
cmd, timeout, retries)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 873, in _recursive_write_and_return
cmd, timeout, retries)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 866, in _recursive_write_and_return
raise e
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 862, in _recursive_write_and_return
timeout=timeout)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 104, in write_and_return
response = _write_to_device_and_return(command, ack, device_connection)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 68, in _write_to_device_and_return
device_connection.timeout))
opentrons.drivers.serial_communication.SerialNoResponse: No response from serial port after 1 second(s)

(anonymous) @ logger.js:43
a @ logger.js:32
e.onmessage @ index.js:28
logger.js:47 [app/src\analytics\index.js] debug: Trackable event
logger.js:51 Object
temp1
{type: "@@router/LOCATION_CHANGE", event: {…}}'

@utimcraig
Copy link
Author

Hi, I also wrote a python program directly to do this protocol and I am getting the same error
'
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 862, in _recursive_write_and_return
timeout=timeout)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 104, in write_and_return
response = _write_to_device_and_return(command, ack, device_connection)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 68, in _write_to_device_and_return
device_connection.timeout))
opentrons.drivers.serial_communication.SerialNoResponse: No response from serial port after 1 second(s)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 862, in _recursive_write_and_return
timeout=timeout)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 104, in write_and_return
response = _write_to_device_and_return(command, ack, device_connection)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 68, in _write_to_device_and_return
device_connection.timeout))
opentrons.drivers.serial_communication.SerialNoResponse: No response from serial port after 1 second(s)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 287, in make_call
self.executor, self.call_and_serialize, func)
File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
result = self.fn(*self.args, **self.kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 275, in call_and_serialize
call_result = loop.run_until_complete(func())
File "/usr/local/lib/python3.6/asyncio/base_events.py", line 467, in run_until_complete
return future.result()
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/api/session.py", line 273, in run
raise e
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/api/session.py", line 266, in run
exec(self._protocol, {})
File "completed_phytips.py", line 42, in
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/commands/commands.py", line 371, in decorated
res = f(*args, **kwargs)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/instruments/pipette.py", line 424, in aspirate
x=mm_position
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/legacy_api/robot/mover.py", line 64, in move
self._driver.move(driver_target, home_flagged_axes=home_flagged_axes)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 1118, in move
self._set_saved_current()
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 694, in _set_saved_current
self._send_command(self._generate_current_command())
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 818, in _send_command
command_line, timeout, DEFAULT_COMMAND_RETRIES)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 873, in _recursive_write_and_return
cmd, timeout, retries)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 873, in _recursive_write_and_return
cmd, timeout, retries)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 866, in _recursive_write_and_return
raise e
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/smoothie_drivers/driver_3_0.py", line 862, in _recursive_write_and_return
timeout=timeout)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 104, in write_and_return
response = _write_to_device_and_return(command, ack, device_connection)
File "/data/packages/usr/local/lib/python3.6/site-packages/opentrons/drivers/serial_communication.py", line 68, in _write_to_device_and_return
device_connection.timeout))
opentrons.drivers.serial_communication.SerialNoResponse: No response from serial port after 1 second(s)
'
Here is the python version of the program:
completed_phytips please rename to py.txt

Seems no programs can work at all. What is going on?

@utimcraig utimcraig changed the title Robot freezes when using protocol from PD Robot freezes when running protocol Dec 16, 2018
@sfoster1
Copy link
Member

@utimcraig thanks for this report!

This is a bug with the robot's safety features to catch bugs in its motor controller board. It uses a fixed 30-second timeout. If a command takes more than 30 seconds to complete - so, for a move command, more than 30 seconds to start and stop moving - you get the error you see.

In your protocol, on line 28 you set the flow rate of the pipette to 3 uL/s:

p300.set_flow_rate(aspirate=3, dispense=3)

Later, on line 42, you aspirate 160 uL:

p300.aspirate(160, lysate_plate.cols('1'))

Because of the flow rate restriction, this takes (160/3) 53.33 seconds, longer than the 30 second timeout, and so the error is raised.;

To be clear, this is not your mistake - we intend to fix this, and will use this issue to track the work to do so. However, as a workaround until then, you have two options:

  • Increase your flow rate
  • Split your aspirates into smaller segments, in this case always less than 89 uL (to give the system time to accelerate)

On our part, we will add dynamic timeouts for serial commands based on a projection of how long the command will take.

Again, thank you for this report!

@sfoster1 sfoster1 added bug api Affects the `api` project medium labels Dec 17, 2018
@utimcraig
Copy link
Author

Thanks @sfoster1 , it would be nice to not have to worry about a step being under a time limit. Especially mixing steps. This kind of aspirate-dispense with low flow rate is critical for phytip purifications:

I think a lot of people may be interested in this application. This time limit especially hurts in .mix() operations

@utimcraig
Copy link
Author

utimcraig commented Dec 17, 2018

@sfoster1 It appears this time limit is not only for single steps, the aspirate+dispense time needs to be less than 30s. So the example you gave is incorrect, each aspirate/dispense needs to not be 89 uL, but rather (89/2) = 44.5 uL.

I think the best thing is to dynamically calculate a timeout, though this gets complicated because you also have to include head moving times. Perhaps a heuristic upper limit could be set for the steps taking into account the slowest flow rates, largest volumes, largest moving distances, and head movement speeds.

For mix() commands I'm not sure how you could set it other than dynamically. That really is the best option.

This also is good advertising for my feature request posted before I knew about the time limit: Feature request: Time to next step #2821

@utimcraig utimcraig changed the title Robot freezes when running protocol Robot freezes when running steps longer than 30s Dec 18, 2018
@utimcraig
Copy link
Author

I have a bit of a workaround for this issue. If you use a pipette.delay(seconds=0) in-between aspirate steps it seems to re-start the 30s timer. So in order to aspirate 100ul at 1ul/sec you can do something like this-

pipette.aspirate()
pipette.delay()
pipette.aspirate()
pipette.delay()

The best solution is still to dynamically calculate the limit on the time of a step though

@utimcraig
Copy link
Author

Hope everyone had a good holiday. Is anyone working on this bug? Thanks

@utimcraig
Copy link
Author

Any updates on the dynamic time calculation?

@mcous
Copy link
Contributor

mcous commented Feb 11, 2019

HI @utimcraig! We're busy working on some core problems in the code base that are preventing us from tackling this problem. You'll see updates in this thread when that work is complete and we have engineering resources available to tackle this one. Thank you for your patience!

sfoster1 added a commit that referenced this issue Apr 26, 2019
Currently, after every command we send an M400, which delays until the
smoothie's queue is empty. We couple this with retrying unacked commands. The
problem is, this couples command acknowledgement with command execution. The
timeouts need to be short enough to be responsive if a command isn't
acknowledged, but short timeouts cause problems with commands that take a long
time - like long motions at low speeds.

Instead, write the command and retry it if not acknowledged, but do not do an
M400 until the command is acknowledged. Once that's done, you can use a very
long timeout for the M400 without worrying about having to retry.

Closes #3300, closes #2822
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api Affects the `api` project bug medium
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants