search

Opentrons / opentrons

Software for writing protocols and running them on the Opentrons Flex and Opentrons OT-2
https://opentrons.com
Apache License 2.0
425 stars 178 forks source link

App crashes during long protocol #1021

Closed umbhau closed 6 years ago

umbhau commented 6 years ago

Applications crashes (and protocol run stops) during long protocol run.

Expected:

Observed:

Steps to Recreate

Notes

Logs

https://dashboard.resin.io/devices/7de286d4d56d02235ce7800b59a96807/summary


13.03.18 17:37:12 (-0400) 2018-03-13 21:37:12,680 opentrons.api.calibration INFO [Line 36] Probing tip with p300_multi
13.03.18 17:37:47 (-0400) 2018-03-13 21:37:47,577 opentrons.api.calibration INFO [Line 50] New config: robot_config(name='Ada Lovelace', steps_per_mm='M92 X80.00 Y80.00 Z400 A400 B768 C768', acceleration='M204 S10000 X3000 Y2000 Z1500 A1500 B2000 C2000', current='M907 X1.5 Y1.75 Z1.0 A1.0 B0.1 C0.1', gantry_calibration=[[1.000677984487715, 0.002170767004341531, 0.0, 1.9787514461379714], [-0.002576341053316695, 0.9994211287988424, 0.0, 5.334724244183678], [0.0, 0.0, 1.0, -25.650000000000006], [-6.264209483981372e-18, 0.0, 0.0, 1.0]], instrument_offset={'right': {'single': (0.0, 0.0, 0.0), 'multi': (0.28402174752875453, 30.918627499289073, -25.8)}, 'left': {'single': (-34, 0.0, 0.0), 'multi': (-34, 31.5, -25.8)}}, probe_center=[293.0480066741916, 300.41955466194156, 53.002000000000066], probe_dimensions=(35.0, 40.0, 60.0), serial_speed=115200, plunger_current_low=0.1, plunger_current_high=0.5, tip_length={'left': {'single': 51.7, 'multi': 51.7}, 'right': {'single': 51.7, 'multi': 51.278000000000006}}, default_current={'X': 1.5, 'Y': 1.75, 'Z': 1.0, 'A': 1.0, 'B': 0.1, 'C': 0.1}, default_max_speed={'X': 600, 'Y': 400, 'Z': 100, 'A': 100, 'B': 70, 'C': 70})
13.03.18 17:38:00 (-0400) 2018-03-13 21:38:00,625 opentrons.api.calibration INFO [Line 109] Moving p300_multi to p300rack in 11
13.03.18 17:38:17 (-0400) 2018-03-13 21:38:17,494 opentrons.api.calibration INFO [Line 136] Updating p300rack in 11
13.03.18 17:38:17 (-0400) 2018-03-13 21:38:17,545 opentrons.api.calibration INFO [Line 66] Picking up tip from p300rack in 11 with p300_multi
13.03.18 17:38:30 (-0400) 2018-03-13 21:38:30,964 opentrons.api.calibration INFO [Line 109] Moving p300_multi to trash-box in 3
13.03.18 17:38:44 (-0400) 2018-03-13 21:38:44,024 opentrons.api.calibration INFO [Line 136] Updating trash-box in 3
13.03.18 17:38:47 (-0400) 2018-03-13 21:38:47,421 opentrons.api.calibration INFO [Line 109] Moving p300_multi to plate in 4
13.03.18 17:38:59 (-0400) 2018-03-13 21:38:59,421 opentrons.api.calibration INFO [Line 117] Jogging p300_multi by -0.25 in z
13.03.18 17:38:59 (-0400) 2018-03-13 21:38:59,601 opentrons.api.calibration INFO [Line 117] Jogging p300_multi by -0.25 in z
13.03.18 17:39:02 (-0400) 2018-03-13 21:39:02,614 opentrons.api.calibration INFO [Line 136] Updating plate in 4
13.03.18 17:39:04 (-0400) 2018-03-13 21:39:04,740 opentrons.api.calibration INFO [Line 109] Moving p300_multi to top_plate in 5
13.03.18 17:39:13 (-0400) 2018-03-13 21:39:13,996 opentrons.api.calibration INFO [Line 136] Updating top_plate in 5
13.03.18 17:39:16 (-0400) 2018-03-13 21:39:16,576 opentrons.api.calibration INFO [Line 109] Moving p300_multi to trough in 10
13.03.18 17:39:22 (-0400) 2018-03-13 21:39:22,956 opentrons.api.calibration INFO [Line 136] Updating trough in 10
13.03.18 17:40:50 (-0400) 10.10.0.188 - - [13/Mar/2018:21:40:50 +0000] "GET /healthHTTP/1.1" 200 179 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
13.03.18 17:43:19 (-0400) fd00:0:cafe:fefe:806b:f7d1:cb3b:1688 - - [13/Mar/2018:21:43:19 +0000] "GET / HTTP/1.1" 101 41317 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) ot-app-desktop/3.0.0 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
13.03.18 17:43:20 (-0400) --- Logging error ---
13.03.18 17:43:20 (-0400) Traceback (most recent call last):
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 162, in handler
13.03.18 17:43:20 (-0400)     async for msg in client:
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 407, in __anext__
13.03.18 17:43:20 (-0400)     msg = await self.receive()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 345, in receive
13.03.18 17:43:20 (-0400)     msg = await self._reader.read()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 571, in read
13.03.18 17:43:20 (-0400)     return await super().read()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 533, in read
13.03.18 17:43:20 (-0400)     await self._waiter
13.03.18 17:43:20 (-0400) concurrent.futures._base.CancelledError
13.03.18 17:43:20 (-0400)
13.03.18 17:43:20 (-0400) During handling of the above exception, another exceptionoccurred:
13.03.18 17:43:20 (-0400)
13.03.18 17:43:20 (-0400) Traceback (most recent call last):
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 992, in emit
13.03.18 17:43:20 (-0400)     msg = self.format(record)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 838, in format
13.03.18 17:43:20 (-0400)     return fmt.format(record)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 575, in format
13.03.18 17:43:20 (-0400)     record.message = record.getMessage()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 338, in getMessage
13.03.18 17:43:20 (-0400)     msg = msg % self.args
13.03.18 17:43:20 (-0400) TypeError: not all arguments converted during string formatting
13.03.18 17:43:20 (-0400) Call stack:
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/runpy.py", line 193, in _run_module_as_main
13.03.18 17:43:20 (-0400)     "__main__", mod_spec)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/runpy.py", line 85, in _run_code
13.03.18 17:43:20 (-0400)     exec(code, run_globals)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/main.py", line 134, in <module>
13.03.18 17:43:20 (-0400)     main()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/main.py", line 129, in main
13.03.18 17:43:20 (-0400)     web.run_app(init(), host=args.hostname, port=args.port, path=args.path)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/web.py", line 114, in run_app
13.03.18 17:43:20 (-0400)     loop.run_forever()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/asyncio/base_events.py",line 421, in run_forever
13.03.18 17:43:20 (-0400)     self._run_once()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/asyncio/base_events.py",line 1426, in _run_once
13.03.18 17:43:20 (-0400)     handle._run()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/asyncio/events.py", line127, in _run
13.03.18 17:43:20 (-0400)     self._callback(*self._args)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 170, in handler
13.03.18 17:43:20 (-0400)     .format(traceback.format_exc()), e)
13.03.18 17:43:20 (-0400) Message: 'While reading from socket: Traceback (most recent call last):\n  File "/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 162, in handler\n    async for msg in client:\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 407, in __anext__\n    msg = await self.receive()\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 345, in receive\n    msg = await self._reader.read()\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 571, in read\n    return await super().read()\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 533, in read\n    await self._waiter\nconcurrent.futures._base.CancelledError\n'
13.03.18 17:43:20 (-0400) Arguments: (CancelledError(),)
13.03.18 17:43:20 (-0400) --- Logging error ---
13.03.18 17:43:20 (-0400) Traceback (most recent call last):
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 162, in handler
13.03.18 17:43:20 (-0400)     async for msg in client:
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 407, in __anext__
13.03.18 17:43:20 (-0400)     msg = await self.receive()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 345, in receive
13.03.18 17:43:20 (-0400)     msg = await self._reader.read()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 571, in read
13.03.18 17:43:20 (-0400)     return await super().read()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 533, in read
13.03.18 17:43:20 (-0400)     await self._waiter
13.03.18 17:43:20 (-0400) concurrent.futures._base.CancelledError
13.03.18 17:43:20 (-0400)
13.03.18 17:43:20 (-0400) During handling of the above exception, another exceptionoccurred:
13.03.18 17:43:20 (-0400)
13.03.18 17:43:20 (-0400) Traceback (most recent call last):
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/handlers.py", line 71, in emit
13.03.18 17:43:20 (-0400)     if self.shouldRollover(record):
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/handlers.py", line 187, in shouldRollover
13.03.18 17:43:20 (-0400)     msg = "%s\n" % self.format(record)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 838, in format
13.03.18 17:43:20 (-0400)     return fmt.format(record)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 575, in format
13.03.18 17:43:20 (-0400)     record.message = record.getMessage()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/logging/__init__.py", line 338, in getMessage
13.03.18 17:43:20 (-0400)     msg = msg % self.args
13.03.18 17:43:20 (-0400) TypeError: not all arguments converted during string formatting
13.03.18 17:43:20 (-0400) Call stack:
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/runpy.py", line 193, in _run_module_as_main
13.03.18 17:43:20 (-0400)     "__main__", mod_spec)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/runpy.py", line 85, in _run_code
13.03.18 17:43:20 (-0400)     exec(code, run_globals)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/main.py", line 134, in <module>
13.03.18 17:43:20 (-0400)     main()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/main.py", line 129, in main
13.03.18 17:43:20 (-0400)     web.run_app(init(), host=args.hostname, port=args.port, path=args.path)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/aiohttp/web.py", line 114, in run_app
13.03.18 17:43:20 (-0400)     loop.run_forever()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/asyncio/base_events.py",line 421, in run_forever
13.03.18 17:43:20 (-0400)     self._run_once()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/asyncio/base_events.py",line 1426, in _run_once
13.03.18 17:43:20 (-0400)     handle._run()
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/asyncio/events.py", line127, in _run
13.03.18 17:43:20 (-0400)     self._callback(*self._args)
13.03.18 17:43:20 (-0400)   File "/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 170, in handler
13.03.18 17:43:20 (-0400)     .format(traceback.format_exc()), e)
13.03.18 17:43:20 (-0400) Message: 'While reading from socket: Traceback (most recent call last):\n  File "/usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py", line 162, in handler\n    async for msg in client:\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 407, in __anext__\n    msg = await self.receive()\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/web_ws.py", line 345, in receive\n    msg = await self._reader.read()\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 571, in read\n    return await super().read()\n  File "/usr/local/lib/python3.6/site-packages/aiohttp/streams.py", line 533, in read\n    await self._waiter\nconcurrent.futures._base.CancelledError\n'
13.03.18 17:43:20 (-0400) Arguments: (CancelledError(),)
13.03.18 17:43:20 (-0400) 2018-03-13 21:43:20,125 opentrons.server.rpc INFO [Line 172] Closing WebSocket 1885186416
13.03.18 17:43:20 (-0400) /usr/local/lib/python3.6/site-packages/opentrons/server/rpc.py:173: RuntimeWarning: coroutine 'WebSocketResponse.close' was never awaited
13.03.18 17:43:20 (-0400)   client.close()
13.03.18 18:08:54 (-0400) fd00:0:cafe:fefe:806b:f7d1:cb3b:1688 - - [13/Mar/2018:22:08:54 +0000] "GET / HTTP/1.1" 101 4909480 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) ot-app-desktop/3.0.0 Chrome/56.0.2924.87Electron/1.6.11 Safari/537.36"
13.03.18 18:08:54 (-0400) fd00:0:cafe:fefe:806b:f7d1:cb3b:1688 - - [13/Mar/2018:22:08:54 +0000] "GET / HTTP/1.1" 101 4909480 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) ot-app-desktop/3.0.0 Chrome/56.0.2924.87Electron/1.6.11 Safari/537.36"
13.03.18 18:08:54 (-0400) 2018-03-13 22:08:54,958 opentrons.server.rpc INFO [Line 172] Closing WebSocket 1884774992
13.03.18 18:08:54 (-0400) 2018-03-13 22:08:54,964 opentrons.server.rpc INFO [Line 172] Closing WebSocket 1885909360```
mcous commented 6 years ago

Protocol run stoppage seems indicative that this is an API-side bug (during a protocol run, the run app is a passive consumer of progress notifications from the RPC API), but I'm investigating potential culprits in the app

umbhau commented 6 years ago

Potentially another incident of the same bug: @kinnari-opentrons reports a white screen during a long protocol with a 10 minute mix. Details to follow.