kaldi-gstreamer-server icon indicating copy to clipboard operation
kaldi-gstreamer-server copied to clipboard

decoder2 resetting state forever

Open burin-n opened this issue 5 years ago • 8 comments

I downloaded librispeech model from test folder and used your's librispeech yaml.

There was no response transcript to the client side. It seemed like decoder was resetting state forever. I tracked the code and found that decoder2 stuck at this line https://github.com/alumae/kaldi-gstreamer-server/blob/master/kaldigstserver/decoder2.py#L171 There was no problem when I tested with tedlium model on the same machine.

Below is my librispeech's worker.log

   DEBUG 2019-01-09 18:20:18,855 Starting up worker 
2019-01-09 18:20:18 -    INFO:   decoder2: Creating decoder using conf: {'post-processor': "perl -npe 'BEGIN {use IO::Handle; STDOUT->autoflush(1);} s/(.*)/\\1./;'", '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, 'decoder': {'ivector-extraction-config': 'test/models/english/librispeech_nnet_a_online/conf/ivector_extractor.fixed.conf', 'num-nbest': 10, 'lattice-beam': 6.0, 'acoustic-scale': 0.083, 'do-endpointing': True, 'beam': 10.0, 'max-active': 10000, 'fst': 'test/models/english/librispeech_nnet_a_online/HCLG.fst', 'mfcc-config': 'test/models/english/librispeech_nnet_a_online/conf/mfcc.conf', 'use-threaded-decoder': True, 'traceback-period-in-secs': 0.25, 'model': 'test/models/english/librispeech_nnet_a_online/final.mdl', 'word-syms': 'test/models/english/librispeech_nnet_a_online/words.txt', 'endpoint-silence-phones': '1:2:3:4:5:6:7:8:9:10', 'chunk-length-in-secs': 0.25}, 'silence-timeout': 10, 'out-dir': 'tmp', 'use-nnet2': True}
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: ivector-extraction-config = test/models/english/librispeech_nnet_a_online/conf/ivector_extractor.fixed.conf
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: num-nbest = 10
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: lattice-beam = 6.0
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: acoustic-scale = 0.083
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: do-endpointing = True
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: beam = 10.0
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: max-active = 10000
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: mfcc-config = test/models/english/librispeech_nnet_a_online/conf/mfcc.conf
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: traceback-period-in-secs = 0.25
2019-01-09 18:20:18 -    INFO:   decoder2: Setting decoder property: word-syms = test/models/english/librispeech_nnet_a_online/words.txt
2019-01-09 18:20:19 -    INFO:   decoder2: Setting decoder property: endpoint-silence-phones = 1:2:3:4:5:6:7:8:9:10
2019-01-09 18:20:19 -    INFO:   decoder2: Setting decoder property: chunk-length-in-secs = 0.25
2019-01-09 18:20:19 -    INFO:   decoder2: Setting decoder property: fst = test/models/english/librispeech_nnet_a_online/HCLG.fst
2019-01-09 18:20:27 -    INFO:   decoder2: Setting decoder property: model = test/models/english/librispeech_nnet_a_online/final.mdl
2019-01-09 18:20:28 -    INFO:   decoder2: Created GStreamer elements
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstAppSrc object at 0x7f2b65d2a320 (GstAppSrc at 0x14de1c0)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstDecodeBin object at 0x7f2b65d2a2d0 (GstDecodeBin at 0x14ec090)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstAudioConvert object at 0x7f2b65d2a3c0 (GstAudioConvert at 0x14f9510)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstAudioResample object at 0x7f2b65d2a280 (GstAudioResample at 0x13b6bd0)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstTee object at 0x7f2b65d2a370 (GstTee at 0x150a000)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstQueue object at 0x7f2b65d2a460 (GstQueue at 0x150e210)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstFileSink object at 0x7f2b65d2a4b0 (GstFileSink at 0x1512600)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstQueue object at 0x7f2b65d2a500 (GstQueue at 0x150e500)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.Gstkaldinnet2onlinedecoder object at 0x7f2b65d2a550 (Gstkaldinnet2onlinedecoder at 0x15340a0)> to the pipeline
2019-01-09 18:20:28 -   DEBUG:   decoder2: Adding <__main__.GstFakeSink object at 0x7f2b65d2a5a0 (GstFakeSink at 0x140e600)> to the pipeline
2019-01-09 18:20:28 -    INFO:   decoder2: Linking GStreamer elements
LOG ([5.4.176~1-be967]:ComputeDerivedVars():ivector-extractor.cc:183) Computing derived variables for iVector extractor
LOG ([5.4.176~1-be967]:ComputeDerivedVars():ivector-extractor.cc:204) Done.
2019-01-09 18:20:29 -    INFO:   decoder2: Setting pipeline to READY
2019-01-09 18:20:29 -    INFO:   decoder2: Set pipeline to READY
2019-01-09 18:20:29 -    INFO:   __main__: Opening websocket connection to master server
2019-01-09 18:20:29 -    INFO:   __main__: Opened websocket connection to server
2019-01-09 18:20:33 -   DEBUG:   __main__: <undefined>: Got message from server of type <class 'ws4py.messaging.TextMessage'>
2019-01-09 18:20:33 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Initializing request
2019-01-09 18:20:33 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Started timeout guard
2019-01-09 18:20:33 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Initialized request
2019-01-09 18:20:33 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:33 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:33 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:33 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:33 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Connecting audio decoder
2019-01-09 18:20:33 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Connected audio decoder
2019-01-09 18:20:33 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:33 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:33 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:33 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:33 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:33 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:34 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:34 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:34 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:34 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:34 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER
2019-01-09 18:20:34 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:34 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Starting postprocessing: MISTER
2019-01-09 18:20:34 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:34 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:34 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUATERMAIN
2019-01-09 18:20:34 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:34 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:35 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:35 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:35 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS
2019-01-09 18:20:35 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:35 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:35 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:35 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE
2019-01-09 18:20:35 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:35 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:35 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:35 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE
2019-01-09 18:20:35 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:35 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:35 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF
2019-01-09 18:20:35 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:35 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:36 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:36 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:36 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE
2019-01-09 18:20:36 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:36 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:36 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:36 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE
2019-01-09 18:20:36 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:36 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:36 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:36 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASS
2019-01-09 18:20:36 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:36 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:36 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:36 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:36 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES
2019-01-09 18:20:36 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:36 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:37 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:37 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:37 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND
2019-01-09 18:20:37 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:37 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:37 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:37 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND
2019-01-09 18:20:37 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:37 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD
2019-01-09 18:20:37 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:37 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:37 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:37 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:37 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO
2019-01-09 18:20:37 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:37 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:38 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:38 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:38 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD
2019-01-09 18:20:38 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:38 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:38 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:38 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIM
2019-01-09 18:20:38 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:38 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:38 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:38 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS
2019-01-09 18:20:38 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:38 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:38 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 8000 to pipeline
2019-01-09 18:20:38 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:38 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL
2019-01-09 18:20:38 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Postprocessing (final=False) result..
2019-01-09 18:20:38 -   DEBUG:       root: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Skipping postprocessing since post-processor already in use
2019-01-09 18:20:39 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:39 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.BinaryMessage'>
2019-01-09 18:20:39 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer of size 3404 to pipeline
2019-01-09 18:20:39 -   DEBUG:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing buffer done
2019-01-09 18:20:39 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got message from server of type <class 'ws4py.messaging.TextMessage'>
2019-01-09 18:20:39 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Pushing EOS to pipeline
2019-01-09 18:20:39 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got partial result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL
2019-01-09 18:20:39 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got final result: MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL
2019-01-09 18:20:39 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Got full final result: {"segment-length": 5.84, "status": 0, "result": {"final": true, "hypotheses": [{"transcript": "MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL", "likelihood": 179.225}, {"transcript": "MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL", "likelihood": 178.999}, {"transcript": "MISTER QUARTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL", "likelihood": 178.155}, {"transcript": "MISTER QUARTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.929}, {"transcript": "MISTER CULTURE IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.816}, {"transcript": "MISTER CULTURE IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.59}, {"transcript": "MISTER QUILTER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.476}, {"transcript": "MISTER COLDER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.359}, {"transcript": "MISTER QUILTER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.25}, {"transcript": "MISTER COLDER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL", "likelihood": 177.133}]}, "segment-start": 0.0, "total-length": 5.84}
2019-01-09 18:20:39 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Before postprocessing: {u'status': 0, u'segment-start': 0.0, u'segment-length': 5.84, u'total-length': 5.84, u'result': {u'hypotheses': [{u'likelihood': 179.225, u'transcript': u'MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL'}, {u'likelihood': 178.999, u'transcript': u"MISTER QUILTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL"}, {u'likelihood': 178.155, u'transcript': u'MISTER QUARTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL'}, {u'likelihood': 177.929, u'transcript': u"MISTER QUARTER IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL"}, {u'likelihood': 177.816, u'transcript': u'MISTER CULTURE IS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL'}, {u'likelihood': 177.59, u'transcript': u"MISTER CULTURE IS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL"}, {u'likelihood': 177.476, u'transcript': u'MISTER QUILTER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL'}, {u'likelihood': 177.359, u'transcript': u'MISTER COLDER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE ARE GLAD TO WELCOME HIS GOSPEL'}, {u'likelihood': 177.25, u'transcript': u"MISTER QUILTER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL"}, {u'likelihood': 177.133, u'transcript': u"MISTER COLDER AS THE APOSTLE OF THE MIDDLE CLASSES AND WE'RE GLAD TO WELCOME HIS GOSPEL"}], u'final': True}, 'segment': 0, 'id': u'e367df1b-8540-4fa4-9c5d-70695d7c93e5'}
2019-01-09 18:20:40 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:41 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:42 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:43 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:44 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:45 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:46 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:47 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:48 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:49 -   DEBUG:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Checking that decoder hasn't been silent for more than 10 seconds
2019-01-09 18:20:50 - WARNING:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: More than 10 seconds from last decoder hypothesis update, cancelling
2019-01-09 18:20:50 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Master disconnected before decoder reached EOS?
2019-01-09 18:20:50 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Sending EOS to pipeline in order to cancel processing
2019-01-09 18:20:50 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Cancelled pipeline
2019-01-09 18:20:50 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:51 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:52 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:53 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:54 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:55 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:56 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:57 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:58 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:20:59 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:00 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:01 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:02 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:03 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:04 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:05 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:06 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:07 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:08 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:09 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:10 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:11 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:12 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:13 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:14 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:15 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:16 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:17 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:18 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:19 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Waiting for EOS from decoder
2019-01-09 18:21:20 -    INFO:   __main__: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Giving up waiting after 31 tries
2019-01-09 18:21:20 -    INFO:   decoder2: e367df1b-8540-4fa4-9c5d-70695d7c93e5: Resetting decoder state

burin-n avatar Jan 09 '19 19:01 burin-n

This error seemed to occur only on a docker image. I fixed it by building docker image myself.

burin-n avatar Jan 10 '19 14:01 burin-n

@burin-n Did you change something in the Dockerfile or have you just rebuilt the image?

I am asking this, because I also ran into this issue and a local built docker image from yesterday did not solve this problem.

From the Dockerfile I see that are potentially multiple dynamic things which will make creation of the same image again difficult: pip install tornado git clone https://github.com/kaldi-asr/kaldi git clone https://github.com/alumae/gst-kaldi-nnet2-online.git git clone https://github.com/alumae/kaldi-gstreamer-server.git

All this action do not specifiy a concrete version or commit, but always use the latest available version.

@burin-n Can you tell me what version of tornado your docker build used? Same for the git clone lines: what commits from master branch were used?

nanosonde avatar Jan 24 '19 12:01 nanosonde

My current locally built container uses the following python modules:

root@7cf654ea3692:/opt# pip list
argparse (1.2.1)
backports-abc (0.5)
cffi (0.8.6)
chardet (2.3.0)
colorama (0.3.2)
cryptography (0.6.1)
futures (3.2.0)
html5lib (0.999)
ndg-httpsclient (0.3.2)
pip (1.5.6)
ply (3.4)
pyasn1 (0.1.7)
pycparser (2.10)
pygobject (3.14.0)
pyOpenSSL (0.14)
PyYAML (3.11)
requests (2.4.3)
setuptools (5.5.1)
simplejson (3.6.5)
singledispatch (3.4.0.3)
six (1.8.0)
tornado (5.1.1)
urllib3 (1.9.1)
wheel (0.24.0)
ws4py (0.3.2)
wsgiref (0.1.2)
root@7cf654ea3692:/opt# 

nanosonde avatar Jan 24 '19 12:01 nanosonde

Ok, I think I have found the reason for this issue.

The yaml file for my german model contains this line:

# Just a sample post-processor that appends "." to the hypothesis
post-processor: perl -npe 'BEGIN {use IO::Handle; STDOUT->autoflush(1);} s/(.*)/\1./;'

After deactivating this post-processor line, the worker.log now contains this line:

2019-01-24 13:24:27 -    INFO:   decoder2: 43ebf3ad-a9c9-4745-84b8-0540d01ec370: Pipeline received eos signal

This was not the case before. So adding the "." at the end of the hypothesis broke the recognition of the "EOS" (End-Of-Stream?) marker.

nanosonde avatar Jan 24 '19 13:01 nanosonde

I used tornado==4.5.3

burin-n avatar Jan 24 '19 14:01 burin-n

@burin-n Ok. But it seems that it was not a matter of any specific version of some components but rather the provided yaml file.

I am curious: how does your yaml file look like? Does it contain any post-processing commands?

nanosonde avatar Jan 24 '19 14:01 nanosonde

@nanosonde

My yaml is exactly the same as a samplefile for librispeech English model. I didn't change anything.

I also tested with Thai. Here is my yaml https://github.com/ekapolc/ASR_classproject/blob/master/hookup/sample_nnet2.yaml

burin-n avatar Jan 24 '19 14:01 burin-n

Ok, I think I have found the reason for this issue.

The yaml file for my german model contains this line:

# Just a sample post-processor that appends "." to the hypothesis
post-processor: perl -npe 'BEGIN {use IO::Handle; STDOUT->autoflush(1);} s/(.*)/\1./;'

After deactivating this post-processor line, the worker.log now contains this line:

2019-01-24 13:24:27 -    INFO:   decoder2: 43ebf3ad-a9c9-4745-84b8-0540d01ec370: Pipeline received eos signal

This was not the case before. So adding the "." at the end of the hypothesis broke the recognition of the "EOS" (End-Of-Stream?) marker.

Jeeeeez, I have been looking for a solution for this for weeks now and I finally found it. Thanks a lot!

janengelmohr avatar Jan 24 '19 21:01 janengelmohr