alumae / kaldi-gstreamer-server

Real-time full-duplex speech recognition server, based on the Kaldi toolkit and the GStreamer framwork.
BSD 2-Clause "Simplified" License
1.07k stars 341 forks source link

Server Error: ERROR 2020-05-28 02:33:05,356 Uncaught exception in /client/ws/speech #237

Open WorldHellow opened 4 years ago

WorldHellow commented 4 years ago

I am exposing my local server through ngrok and ssh. I am using kaldi-gstreamer.

Worker output when I speak through the mic

2020-05-28 02:32:43 -    INFO:   __main__: Opened websocket connection to server
2020-05-28 02:32:53 -   DEBUG:   __main__: <undefined>: Got message from server of type <class 'ws4py.messaging.TextMessage'>
2020-05-28 02:32:53 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Initializing request
2020-05-28 02:32:53 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Setting caps to audio/x-raw, layout=(string)interleaved, rate=(int)16000, format=(string)S16LE, channels=(int)1
2020-05-28 02:32:53 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Connecting audio decoder
2020-05-28 02:32:53 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Connected audio decoder
2020-05-28 02:32:53 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Started timeout guard
2020-05-28 02:32:53 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:32:53 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Initialized request
2020-05-28 02:32:54 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:32:55 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:32:56 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:32:56 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 8916 to pipeline
2020-05-28 02:32:56 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:32:56 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:32:57 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:32:57 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 8916 to pipeline
2020-05-28 02:32:57 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:32:57 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:32:58 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:32:58 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 5944 to pipeline
2020-05-28 02:32:58 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:32:58 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:32:59 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:32:59 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 8916 to pipeline
2020-05-28 02:32:59 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:32:59 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:33:00 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:33:00 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:33:00 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 8918 to pipeline
2020-05-28 02:33:00 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:33:01 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:33:01 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 5944 to pipeline
2020-05-28 02:33:01 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:33:01 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:33:02 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:33:02 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer of size 5944 to pipeline
2020-05-28 02:33:02 -   DEBUG:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pushing buffer done
2020-05-28 02:33:02 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Checking that decoder hasn't been silent for more than 10 seconds
2020-05-28 02:33:03 - WARNING:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: More than 10 seconds from last decoder hypothesis update, cancelling
2020-05-28 02:33:03 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Master disconnected before decoder reached EOS?
2020-05-28 02:33:03 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Sending EOS to pipeline in order to cancel processing
2020-05-28 02:33:03 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Cancelled pipeline
2020-05-28 02:33:03 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Waiting for EOS from decoder
2020-05-28 02:33:03 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got final result: ایک سو
2020-05-28 02:33:03 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got full final result: {"status": 0, "result": {"final": true, "hypotheses": [{"transcript": "ایک سو", "likelihood": 19.0102}]}, "segment-length": 1.65, "segment-start": 0.0, "total-length": 1.65}
2020-05-28 02:33:03 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Before postprocessing: {u'status': 0, u'segment-start': 0.0, u'segment-length': 1.65, u'total-length': 1.65, u'result': {u'hypotheses': [{u'likelihood': 19.0102, u'transcript': u'ایک سو'}], u'final': True}, 'segment': 0, 'id': u'a7bc3e4d-d3cc-4732-8e91-492db73090c3'}
2020-05-28 02:33:03 -   DEBUG:       root: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Waiting for postprocessor lock
2020-05-28 02:33:03 -   DEBUG:       root: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Starting postprocessing: ایک سو
2020-05-28 02:33:03 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Pipeline received eos signal
2020-05-28 02:33:03 -    INFO:   decoder2: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Resetting decoder state
2020-05-28 02:33:03 -   DEBUG:       root: Waiting until processing threads finish (1)
2020-05-28 02:33:04 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2020-05-28 02:33:04 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Ignoring data, worker already in state 8
2020-05-28 02:33:04 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Waiting for EOS from decoder
2020-05-28 02:33:04 -   DEBUG:       root: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Postprocessing returned: ایک سو.

2020-05-28 02:33:04 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Postprocessing done.
2020-05-28 02:33:04 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: After postprocessing: {u'status': 0, u'segment-start': 0.0, u'segment-length': 1.65, u'total-length': 1.65, u'result': {u'hypotheses': [{u'likelihood': 19.0102, u'transcript': u'ایک سو.', 'original-transcript': u'ایک سو'}], u'final': True}, 'segment': 0, 'id': u'a7bc3e4d-d3cc-4732-8e91-492db73090c3'}
2020-05-28 02:33:04 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Sending adaptation state to client...
2020-05-28 02:33:04 -   DEBUG:      ws4py: Closing message received (1000) ''
2020-05-28 02:33:04 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Websocket closed() called
2020-05-28 02:33:04 -   DEBUG:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Websocket closed() finished
2020-05-28 02:33:05 -    INFO:   decoder2: <undefined>: Resetting decoder state
2020-05-28 02:33:05 -    INFO:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Finished waiting for EOS
2020-05-28 02:33:05 - WARNING:   __main__: a7bc3e4d-d3cc-4732-8e91-492db73090c3: Failed to send error event to master
2020-05-28 02:33:05 -    INFO:   __main__: Opening websocket connection to master server
2020-05-28 02:33:05 -    INFO:   __main__: Opened websocket connection to server

Server output:

INFO 2020-05-28 02:32:42,855 28292b79-0c61-4949-a989-131533584eb8: Handling on_connection_close()
    INFO 2020-05-28 02:32:42,855 28292b79-0c61-4949-a989-131533584eb8: Closing worker connection
    INFO 2020-05-28 02:32:43,819 101 GET /worker/ws/speech (127.0.0.1) 0.89ms
    INFO 2020-05-28 02:32:43,819 New worker available <__main__.WorkerSocketHandler object at 0x7f3631a85b90>
    INFO 2020-05-28 02:32:53,749 101 GET /client/ws/speech?content-type=audio/x-raw,+layout=(string)interleaved,+rate=(int)16000,+format=(string)S16LE,+channels=(int)1&user-id=c376398a-ebe8-4f56-ae20-521b84c0aa30&content-id=90507e7f-fa0d-4e46-a437-406dea0c0177 (127.0.0.1) 1.24ms
    INFO 2020-05-28 02:32:53,749 a7bc3e4d-d3cc-4732-8e91-492db73090c3: OPEN
    INFO 2020-05-28 02:32:53,750 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Request arguments: user-id="c376398a-ebe8-4f56-ae20-521b84c0aa30" content-type="audio/x-raw, layout=(string)interleaved, rate=(int)16000, format=(string)S16LE, channels=(int)1" content-id="90507e7f-fa0d-4e46-a437-406dea0c0177"
    INFO 2020-05-28 02:32:53,750 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Using worker <__main__.DecoderSocketHandler object at 0x7f3631a941d0>
    INFO 2020-05-28 02:32:53,750 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Using content type: audio/x-raw, layout=(string)interleaved, rate=(int)16000, format=(string)S16LE, channels=(int)1
    INFO 2020-05-28 02:32:56,035 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 8916 to worker
    INFO 2020-05-28 02:32:57,287 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 8916 to worker
    INFO 2020-05-28 02:32:58,131 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 5944 to worker
    INFO 2020-05-28 02:32:59,607 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 8916 to worker
    INFO 2020-05-28 02:33:00,855 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 8918 to worker
    INFO 2020-05-28 02:33:01,688 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 5944 to worker
    INFO 2020-05-28 02:33:02,546 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 5944 to worker
    INFO 2020-05-28 02:33:04,024 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 8916 to worker
    INFO 2020-05-28 02:33:04,846 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Sending event {u'status': 0, u'segment-start': 0.0, u'segment-length': 1.65, u'total-length': 1.65, u'result': ... to client
    INFO 2020-05-28 02:33:04,859 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Sending event {u'status': 0, u'adaptation_state': {u'type': u'string+gzip+base64', u'id': u'a7bc3e4d-d3cc-4732-... to client
    INFO 2020-05-28 02:33:04,860 Worker <__main__.WorkerSocketHandler object at 0x7f3631a85b90> leaving
    INFO 2020-05-28 02:33:05,356 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Forwarding client message (<type 'str'>) of length 8916 to worker
   ERROR 2020-05-28 02:33:05,356 Uncaught exception in /client/ws/speech
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/tornado/websocket.py", line 494, in _run_callback
    result = callback(*args, **kwargs)
  File "/home/saad/kaldi-gstreamer-server/kaldigstserver/master_server.py", line 319, in on_message
    self.worker.write_message(message, binary=True)
  File "/usr/local/lib/python2.7/dist-packages/tornado/websocket.py", line 249, in write_message
    raise WebSocketClosedError()
WebSocketClosedError
    INFO 2020-05-28 02:33:05,357 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Handling on_connection_close()
    INFO 2020-05-28 02:33:05,357 a7bc3e4d-d3cc-4732-8e91-492db73090c3: Closing worker connection
    INFO 2020-05-28 02:33:05,864 101 GET /worker/ws/speech (127.0.0.1) 1.00ms
    INFO 2020-05-28 02:33:05,865 New worker available <__main__.WorkerSocketHandler object at 0x7f3631a94390>
    INFO 2020-05-28 02:33:12,935 Status listener left
    INFO 2020-05-28 02:34:06,125 Status listener left 

Sometimes the output is generated properly and sometimes only one or two words are recognized.