I'm working on a mobile application which uses Kaldi Gstreamer Server for speech recognition. In my application, users can start and end speech recognition at their will, meaning the server needs to keep a worker running until it is told to stop. I set the silence-timeout variable in the .yaml file to 20 seconds and figured I could try reopening the connection right after the timeout closes it. According to the guard_timeout function in worker.py, the worker tries to inform the client about the timeout with a JSON containing the value STATUS_NO_SPEECH. However, no such JSON came through to my client app after the timeout was triggered.
Reading the logs outputted by the worker, I noticed that the try-clause in guard_timeout fails each time. After reading through the logs and browsing master server code, I reasoned the execution order in guard_timeout is the cause. On lines 86-91 in the worker.py, the worker first calls master server to finish the request. Consequently, this leads to master server closing the socket before the worker can send the JSON with STATUS_NO_SPEECH to the client. Moving self.finish_request() on line 86 to line 91 solved the issue for me and now I can use the JSON as a timeout signal.
Since I'm not sure whether this order of execution is intentional or a bug, I'm posting this issue here. While solving this, I also came across a much older issue which might be connected to this. The difference here is that my master server does not raise WebSocketClosedError and runs just fine.
Below is a reproduction of the output from a worker with silence-timeout set to 5 seconds. Lines relevant for the issue ("More than 5 seconds from last decoder hypothesis update, cancelling", "Failed to send error event to master" and everything between these) are near the end of the log.
DEBUG 2018-08-17 15:03:39,992 Starting up worker
2018-08-17 15:03:40 - INFO: decoder2: Creating decoder using conf: {'logging': {'version': 1, 'root': {'level': 'DEBUG', 'handlers': ['console']}, 'formatters': {'simpleFormater': {'datefmt': '%Y-%m-%d %H:%M:%S', 'format': '%(asctime)s - %(levelname)7s: %(name)10s: %(message)s'}}, 'disable_existing_loggers': False, 'handlers': {'console': {'formatter': 'simpleFormater', 'class': 'logging.StreamHandler', 'level': 'DEBUG'}}}, 'use-vad': False, 'full-post-processor': './sample_full_post_processor.py', 'decoder': {'ivector-extraction-config': 'kaldi/ivector_extractor.conf', 'lattice-beam': 6.0, 'acoustic-scale': 1.0, 'do-endpointing': True, 'beam': 10.0, 'mfcc-config': 'kaldi/mfcc_hires.conf', 'traceback-period-in-secs': 1.0, 'nnet-mode': 3, 'endpoint-silence-phones': '1:2:3:4:5:6:7:8:9:10', 'word-syms': 'kaldi/words.txt', 'num-nbest': 10, 'frame-subsampling-factor': 3, 'max-active': 10000, 'fst': 'kaldi/HCLG.fst', 'use-threaded-decoder': False, 'model': 'kaldi/final.mdl', 'chunk-length-in-secs': 0.25}, 'silence-timeout': 5, 'out-dir': 'tmp', 'use-nnet2': True}
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: nnet-mode = 3
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: ivector-extraction-config = kaldi/ivector_extractor.conf
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: lattice-beam = 6.0
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: acoustic-scale = 1.0
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: do-endpointing = True
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: beam = 10.0
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: mfcc-config = kaldi/mfcc_hires.conf
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: traceback-period-in-secs = 1.0
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: endpoint-silence-phones = 1:2:3:4:5:6:7:8:9:10
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: word-syms = kaldi/words.txt
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: num-nbest = 10
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: frame-subsampling-factor = 3
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: max-active = 10000
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: chunk-length-in-secs = 0.25
2018-08-17 15:03:40 - INFO: decoder2: Setting decoder property: fst = kaldi/HCLG.fst
2018-08-17 15:03:45 - INFO: decoder2: Setting decoder property: model = kaldi/final.mdl
LOG ([5.4.97\~1-4abd]:CompileLooped():nnet-compile-looped.cc:334) Spent 0.331301 seconds in looped compilation.
2018-08-17 15:03:46 - INFO: decoder2: Created GStreamer elements
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstAppSrc object at 0x15c98c0 (GstAppSrc at 0x17b21c0)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstDecodeBin object at 0x15c9af0 (GstDecodeBin at 0x181c150)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstAudioConvert object at 0x15c99b0 (GstAudioConvert at 0x177f2d0)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstAudioResample object at 0x15c9960 (GstAudioResample at 0x17002d0)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstTee object at 0x15c9aa0 (GstTee at 0x1824000)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstQueue object at 0x15c9a00 (GstQueue at 0x1828070)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstFileSink object at 0x15c9a50 (GstFileSink at 0x18130e0)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstQueue object at 0x15c9b40 (GstQueue at 0x1828360)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.Gstkaldinnet2onlinedecoder object at 0x15c9b90 (Gstkaldinnet2onlinedecoder at 0x1822270)> to the pipeline
2018-08-17 15:03:46 - DEBUG: decoder2: Adding <__gi__.GstFakeSink object at 0x15c9be0 (GstFakeSink at 0x164c9e0)> to the pipeline
2018-08-17 15:03:46 - INFO: decoder2: Linking GStreamer elements
LOG ([5.4.97\~1-4abd]:ComputeDerivedVars():ivector-extractor.cc:183) Computing derived variables for iVector extractor
LOG ([5.4.97\~1-4abd]:ComputeDerivedVars():ivector-extractor.cc:204) Done.
2018-08-17 15:03:46 - INFO: decoder2: Setting pipeline to READY
2018-08-17 15:03:46 - INFO: decoder2: Set pipeline to READY
2018-08-17 15:03:46 - INFO: __main__: Opening websocket connection to master server
2018-08-17 15:03:46 - INFO: __main__: Opened websocket connection to server
2018-08-17 15:03:48 - DEBUG: __main__: <undefined>: Got message from server of type <class 'ws4py.messaging.TextMessage'>
2018-08-17 15:03:48 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Initializing request
2018-08-17 15:03:48 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Setting caps to audio/x-raw, layout=(string)interleaved, rate=(int)44100, format=(string)S16LE, channels=(int)1
2018-08-17 15:03:48 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Started timeout guard
2018-08-17 15:03:48 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Initialized request
2018-08-17 15:03:48 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Connecting audio decoder
2018-08-17 15:03:48 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Connected audio decoder
2018-08-17 15:03:48 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Checking that decoder hasn't been silent for more than 5 seconds
2018-08-17 15:03:48 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:48 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:48 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:48 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:48 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:48 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Checking that decoder hasn't been silent for more than 5 seconds
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:49 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:49 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Checking that decoder hasn't been silent for more than 5 seconds
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:50 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:50 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Checking that decoder hasn't been silent for more than 5 seconds
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:51 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:51 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Checking that decoder hasn't been silent for more than 5 seconds
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:52 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:52 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer of size 8820 to pipeline
2018-08-17 15:03:53 - DEBUG: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pushing buffer done
2018-08-17 15:03:53 - WARNING: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: More than 5 seconds from last decoder hypothesis update, cancelling
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Master disconnected before decoder reached EOS?
2018-08-17 15:03:53 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Sending EOS to pipeline in order to cancel processing
2018-08-17 15:03:53 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Cancelled pipeline
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Waiting for EOS from decoder
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Ignoring data, worker already in state 8
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Ignoring data, worker already in state 8
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Ignoring data, worker already in state 8
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Ignoring data, worker already in state 8
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Ignoring data, worker already in state 8
2018-08-17 15:03:53 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Pipeline received eos signal
2018-08-17 15:03:53 - INFO: decoder2: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Resetting decoder state
2018-08-17 15:03:53 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Sending adaptation state to client...
2018-08-17 15:03:53 - DEBUG: ws4py: Closing message received (1000) ''
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Websocket closed() called
2018-08-17 15:03:53 - DEBUG: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Websocket closed() finished
2018-08-17 15:03:54 - INFO: decoder2: <undefined>: Resetting decoder state
2018-08-17 15:03:54 - INFO: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Finished waiting for EOS
2018-08-17 15:03:54 - WARNING: __main__: f4d7be47-592c-4e31-bd2c-d3a35a101bf1: Failed to send error event to master
2018-08-17 15:03:54 - INFO: __main__: Opening websocket connection to master server
2018-08-17 15:03:54 - INFO: __main__: Opened websocket connection to server
Hello!
I'm working on a mobile application which uses Kaldi Gstreamer Server for speech recognition. In my application, users can start and end speech recognition at their will, meaning the server needs to keep a worker running until it is told to stop. I set the silence-timeout variable in the .yaml file to 20 seconds and figured I could try reopening the connection right after the timeout closes it. According to the guard_timeout function in worker.py, the worker tries to inform the client about the timeout with a JSON containing the value STATUS_NO_SPEECH. However, no such JSON came through to my client app after the timeout was triggered.
Reading the logs outputted by the worker, I noticed that the try-clause in
guard_timeoutfails each time. After reading through the logs and browsing master server code, I reasoned the execution order inguard_timeoutis the cause. On lines 86-91 in the worker.py, the worker first calls master server to finish the request. Consequently, this leads to master server closing the socket before the worker can send the JSON with STATUS_NO_SPEECH to the client. Movingself.finish_request()on line 86 to line 91 solved the issue for me and now I can use the JSON as a timeout signal.Since I'm not sure whether this order of execution is intentional or a bug, I'm posting this issue here. While solving this, I also came across a much older issue which might be connected to this. The difference here is that my master server does not raise WebSocketClosedError and runs just fine.
Below is a reproduction of the output from a worker with silence-timeout set to 5 seconds. Lines relevant for the issue ("More than 5 seconds from last decoder hypothesis update, cancelling", "Failed to send error event to master" and everything between these) are near the end of the log.