"Stream is closed" 500 error

[sushain97]

apy_1         | [E 171227 22:37:04 web:1590] Uncaught exception GET /translateChain?q=house&markUnknown=no&langpairs=eng%7Crus&callback=_jqjsp&_1514414224113= (76.30.93.54)
apy_1         |     HTTPServerRequest(protocol='http', host='beta.apertium.org:2738', method='GET', uri='/translateChain?q=house&markUnknown=no&langpairs=eng%7Crus&callback=_jqjsp&_1514414224113=', version='HTTP/1.1', remote_ip='76.30.93.54', headers={'Accept': '*/*', 'Pragma': 'no-cache', 'Cache-Control': 'no-cache', 'User-Agent': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.108 Safari/537.36', 'Connection': 'keep-alive', 'Dnt': '1', 'Referer': 'http://beta.apertium.org/index.eng.html?dir=eng-rus&q=house', 'Host': 'beta.apertium.org:2738', 'Accept-Encoding': 'gzip, deflate', 'Accept-Language': 'en-US,en;q=0.9'})
apy_1         |     Traceback (most recent call last):
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/web.py", line 1511, in _execute
apy_1         |         result = yield result
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1055, in run
apy_1         |         value = future.result()
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/concurrent.py", line 238, in result
apy_1         |         raise_exc_info(self._exc_info)
apy_1         |       File "<string>", line 4, in raise_exc_info
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1063, in run
apy_1         |         yielded = self.gen.throw(*exc_info)
apy_1         |       File "/root/apertium-apy/servlet.py", line 578, in get
apy_1         |         nosplit=False, deformat=deformat, reformat=reformat)
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1055, in run
apy_1         |         value = future.result()
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/concurrent.py", line 238, in result
apy_1         |         raise_exc_info(self._exc_info)
apy_1         |       File "<string>", line 4, in raise_exc_info
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1063, in run
apy_1         |         yielded = self.gen.throw(*exc_info)
apy_1         |       File "/root/apertium-apy/servlet.py", line 543, in translateAndRespond
apy_1         |         translated = yield translation.coreduce(toTranslate, [p.translate for p in pipelines], nosplit, deformat, reformat)
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1055, in run
apy_1         |         value = future.result()
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/concurrent.py", line 238, in result
apy_1         |         raise_exc_info(self._exc_info)
apy_1         |       File "<string>", line 4, in raise_exc_info
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1063, in run
apy_1         |         yielded = self.gen.throw(*exc_info)
apy_1         |       File "/root/apertium-apy/translation.py", line 258, in coreduce
apy_1         |         result = yield funcs[0](init, *args)
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1055, in run
apy_1         |         value = future.result()
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/concurrent.py", line 238, in result
apy_1         |         raise_exc_info(self._exc_info)
apy_1         |       File "<string>", line 4, in raise_exc_info
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1063, in run
apy_1         |         yielded = self.gen.throw(*exc_info)
apy_1         |       File "/root/apertium-apy/translation.py", line 74, in translate
apy_1         |         for part in all_split]
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1055, in run
apy_1         |         value = future.result()
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/concurrent.py", line 238, in result
apy_1         |         raise_exc_info(self._exc_info)
apy_1         |       File "<string>", line 4, in raise_exc_info
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 828, in callback
apy_1         |         result_list.append(f.result())
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/concurrent.py", line 238, in result
apy_1         |         raise_exc_info(self._exc_info)
apy_1         |       File "<string>", line 4, in raise_exc_info
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/gen.py", line 1069, in run
apy_1         |         yielded = self.gen.send(value)
apy_1         |       File "/root/apertium-apy/translation.py", line 279, in translateNULFlush
apy_1         |         proc_in.stdin.write(bytes('\0', "utf-8"))
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 387, in write
apy_1         |         self._check_closed()
apy_1         |       File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 925, in _check_closed
apy_1         |         raise StreamClosedError(real_error=self.error)
apy_1         |     tornado.iostream.StreamClosedError: Stream is closed

[sushain97]

cc @unhammer (I think you've reported this issue before)

@Androbin you could tackle this to make beta.apertium.org work better

[unhammer]

I can't remember seeing this in a while (and I don't think I've even used chaining …); have you got any idea what sets it off?

[sushain97]

have you got any idea what sets it off?

nope

I don't think I've even used chaining …

yeah, the chaining is fairly new and untested

[xavivars]

We're facing this problem now at Softcatalà's APy. Every few hours, some pipeline gets locked, and APy has to be restarted. Maybe we could try to add some robustness here, shutting down the pipeline that got locked and restarting it again...

[unhammer]

and the error message looks similar? "some pipeline" – which language pairs are affected?

[xavivars]

The error message is the same, "stream closed" , and it also shows "already reading".

Yesterday, it was eng-cat. Earlier today, I couldn't check which one, but I'll be monitoring it

[Androbin]

Probable cause 1: The stream is either used in multiple places or multiple times. This would explain both "stream closed" and "already reading" (_set_read_callback).

Probable cause 2: The connection is closed by the client, not the server. This would explain "stream closed" but not "already reading".

[xavivars]

This is an example of "already reading"

ERROR:tornado.application:Uncaught exception GET /translate?&markUnknown=yes&langpair=fr%7Cca&q=presunto+acoso (10.12.15.10)
HTTPServerRequest(protocol='http', host='www.softcatala.org', method='GET', uri='/translate?&markUnknown=yes&key=NWI0MjQwMzQ2MzYyMzEzNjMyNjQ&langpair=fr%7Cca&q=presunto+acoso', version='HTTP/1.0', remote_ip='10.12.15.10')
Traceback (most recent call last):
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/web.py", line 1592, in _execute
    result = yield result
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/handlers/translate.py", line 190, in get
    reformat=reformat)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/handlers/translate.py", line 166, in translate_and_respond
    translated = yield pipeline.translate(to_translate, nosplit, deformat, reformat)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/utils/translation.py", line 73, in translate
    for part in all_split]
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 883, in callback
    result_list.append(f.result())
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/utils/translation.py", line 282, in translate_nul_flush
    output = yield gen.Task(proc_out.stdout.read_until, bytes('\0', 'utf-8'))
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 665, in Task
    func(*args, callback=_argument_adapter(set_result), **kwargs)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/iostream.py", line 391, in read_until
    future = self._set_read_callback(callback)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/iostream.py", line 859, in _set_read_callback
    assert self._read_callback is None, "Already reading"
AssertionError: Already reading

[xavivars]

After that, following errors do not show the actual pair that errored:

ERROR:asyncio:Future exception was never retrieved
future: <Future finished exception=AssertionError('Already reading',)>
Traceback (most recent call last):
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/handlers/translate.py", line 190, in get
    reformat=reformat)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/handlers/translate.py", line 166, in translate_and_respond
    translated = yield pipeline.translate(to_translate, nosplit, deformat, reformat)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/utils/translation.py", line 73, in translate
    for part in all_split]
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 883, in callback
    result_list.append(f.result())
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/utils/translation.py", line 282, in translate_nul_flush
    output = yield gen.Task(proc_out.stdout.read_until, bytes('\0', 'utf-8'))
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 665, in Task
    func(*args, callback=_argument_adapter(set_result), **kwargs)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/iostream.py", line 391, in read_until
    future = self._set_read_callback(callback)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/iostream.py", line 859, in _set_read_callback
    assert self._read_callback is None, "Already reading"
AssertionError: Already reading

[xavivars]

This one was actually me. eng-cat was not working (seemed to be stuck, but didn't have access to the locks at that time), so I did a translation hoping to find the log later on. And here you have.

AssertionError: Already reading
500 GET /translate?&markUnknown=yes&langpair=en%7Cca&q=Favor+gran.+ (10.12.15.10) 24.18ms
ERROR:tornado.application:Uncaught exception GET /translate?&markUnknown=yes&langpair=en%7Cca&q=Favor+gran. (10.12.15.10)
HTTPServerRequest(protocol='http', host='www.softcatala.org', method='GET', uri='/translate?&markUnknown=yes&klangpair=en%7Cca&q=Favor+gran.', version='HTTP/1.0', remote_ip='10.12.15.10')
Traceback (most recent call last):
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/web.py", line 1592, in _execute
    result = yield result
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/handlers/translate.py", line 190, in get
    reformat=reformat)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/handlers/translate.py", line 166, in translate_and_respond
    translated = yield pipeline.translate(to_translate, nosplit, deformat, reformat)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/utils/translation.py", line 73, in translate
    for part in all_split]
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 883, in callback
    result_list.append(f.result())
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1141, in run
    yielded = self.gen.throw(*exc_info)
  File "/opt/apy/venv/lib/python3.5/site-packages/apertium_apy/utils/translation.py", line 282, in translate_nul_flush
    output = yield gen.Task(proc_out.stdout.read_until, bytes('\0', 'utf-8'))
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 1133, in run
    value = future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 293, in result
    raise self._exception
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/gen.py", line 665, in Task
    func(*args, callback=_argument_adapter(set_result), **kwargs)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/iostream.py", line 391, in read_until
    future = self._set_read_callback(callback)
  File "/opt/apy/venv/lib/python3.5/site-packages/tornado/iostream.py", line 859, in _set_read_callback
    assert self._read_callback is None, "Already reading"

[xavivars]

And, as in Apertium's official APy, fra-cat fails now and then with an Already reading error...

[xavivars]

I'm pretty sure there's a module in fra-cat that, given a specific input, makes the whole pair to crash. Ideally, we should be able to capture that specific exception and, while we find the underlying root cause, be able to at least restart the pipeline.