Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

run_forever() terminates too early #152

Open
alumae opened this issue Nov 25, 2014 · 5 comments
Open

run_forever() terminates too early #152

alumae opened this issue Nov 25, 2014 · 5 comments
Labels

Comments

@alumae
Copy link

alumae commented Nov 25, 2014

I expect the run_forever() in threadedclient.py to return when the websocket has completely finished. However, it can return before the websocket's closed() method has returned.

The run_forver() method checks whether the terminated() method return true. However, ws4py/websocket.py terminate(), the client_terminated and server_terminated properties that terminate() checks are set to true in the beginning, before calling closed(). This means that if the closed() method takes some time (e.g., to do some cleanup), run_forver() returns before closed() has finished.

The solution would be to move the line

self.client_terminated = self.server_terminated = True

in ws4py/websocket.py to the finally block.

@Lawouach
Copy link
Owner

Lawouach commented Dec 3, 2014

Good catch. Thanks for the report. I will try to fix this this week.

@Lawouach Lawouach added the bug label May 11, 2015
@skoocda
Copy link

skoocda commented May 22, 2016

Any update on this?

@steowens
Copy link
Contributor

Any updates on this?

@psukys
Copy link

psukys commented Dec 14, 2017

@alumae can you verify that the problem persists (since the pull request was accepted)?

@EvertSchut
Copy link

EvertSchut commented Feb 6, 2018

When using Kaldi as backend to a speech recognition Android app using SpeechKit we get the strange effect that the first time we set up an session, it works fine. But after stopping this session and resuming within approx. 4 seconds, we run into the problem that this second session does not work. (If the session was setup after more than 4-5 seconds after the first, the second session is setup well and working fine.) But, always after such an uncuccesful session, a retry (third session) works again great. If I compare it with Konele, I can see that Konele does not have this problem with our Kaldi server. Also a java client on a PC has not got this problem. I was looking into the app as the cause, but this websocket server side problem as described here seems to fit the problem in our app.

I include some loggings but first I will descipe some events. Whilst the speech is recognized, frames flow. Though "err: -1" seems bad, it works fine. The loggings in the app shows still some creating frames (Creating frame for: [B@221087c op: 2 err: -1) flowing and a partial result AFTER STOP is pressed and the message (Speechkit status: STOPPING) .
Then: Not supplying enough data to HAL, expected position 33559299 , only wrote 33559200 ,
but still a frame gets created, a hump of data is exchanged and then the exception error occurs and EOF shows up.

In another log (debug) EOF shows up together with
D/WebSocketClient: WebSocket EOF!
java.io.EOFException at java.io.DataInputStream.readByte(DataInputStream.java:270)
at com.codebutler.android_websockets.HybiParser.start(HybiParser.java:117)
at com.codebutler.android_websockets.WebSocketClient$1.run(WebSocketClient.java:185)
at java.lang.Thread.run(Thread.java:761)
02-06 12:32:10.849 5601-5738/nl.app D/MyLog.d():12: Disconnect! EOF

Looking at the log, it seems to me that one process seems still busy while the data gets interrupted unexpectedly, maybe the socket gets killed by the server. Anyone has a suggestion?

So I am very interested if this issue (also [https://github.com/alumae/kaldi-gstreamer-server/issues/7] ) is already solved, and could the behavior of our app be explained by this issue?

Could this problem be caused by the bug signalled by @alumae in ws4py 3.5.0, where the problem is that ws4py finishes the websocket handling thread before the websocket has actually done its cleanup? And is the current workaround is to use an earlier version of ws4py (3.0.0 ... 3.2.0 should be fine)?

Please excuse me for maybe not following normal guidelines, I am still a bit noob on Github.

------------ Android Studio Debug Log:-----------------------

First the app is installed in the emulator.
Starting recognizer yields:

02-06 13:38:15.633 1706-1719/system_process I/UsageStatsService: User[0] Flushing usage stats to disk
02-06 13:38:21.110 6077-6077/nl.app D/MyLog.d():12: Connecting to speech server
02-06 13:38:21.113 1400-1426/? W/audio_hw_generic: Not supplying enough data to HAL, expected position 33405194 , only wrote 33405120
02-06 13:38:21.176 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:21.374 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:21.379 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:21.485 6077-6077/nl.app I/MainActivity: onUpdateStatus Speechkit status: RECOGNIZING
02-06 13:38:21.492 6077-6099/nl.app D/MyLog.d():12: {"num_workers_available": 3, "num_requests_processed": 230}
02-06 13:38:21.503 6077-6077/nl.app I/MainActivity: onReady
02-06 13:38:21.503 6077-6077/nl.app I/MainActivity: onUpdateStatus Speechkit status: READY
02-06 13:38:21.520 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:21.551 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:21.581 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:21.611 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
(I omit al lot more of this flowing data).
02-06 13:38:23.320 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.330 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment": 0, "result": {"hypotheses": [{"transcript": "ik."}], "final": false}, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:23.331 6077-6077/nl.app I/MainActivity: Partial Result
02-06 13:38:23.350 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.380 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.411 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.440 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.470 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.500 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.530 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.561 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.579 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment": 0, "result": {"hypotheses": [{"transcript": "ik probeer."}], "final": false}, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:23.580 6077-6077/nl.app I/MainActivity: Partial Result
02-06 13:38:23.591 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.620 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.650 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.680 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.711 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.741 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:23.770 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
(etcetera)

At releasing the STOP buttom we get:
02-06 13:38:30.281 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.281 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment-start": 0.0, "segment-length": 7.77, "total-length": 8.0, "result": {"hypotheses": [{"transcript": "ik probeer nu nu iets herkent iets ik druk op -top knopje ingedrukt.", "confidence": 0.19828331970980762, "likelihood": 309.073, "word-alignment": [{"start": 1.08, "length": 0.3, "word": "ik"}, {"start": 1.38, "length": 0.39, "word": "probeer"}, {"start": 1.77, "length": 0.15, "word": "nu"}, {"start": 1.92, "length": 0.63, "word": ""}, {"start": 2.55, "length": 0.21, "word": "nu"}, {"start": 2.76, "length": 0.42, "word": "iets"}, {"start": 3.51, "length": 0.63, "word": "herkent"}, {"start": 4.14, "length": 0.15, "word": "iets"}, {"start": 4.29, "length": 0.09, "word": "ik"}, {"start": 4.38, "length": 0.21, "word": "druk"}, {"start": 4.59, "length": 0.15, "word": "op"}, {"start": 4.74, "length": 0.18, "word": ""}, {"start": 4.95, "length": 0.48, "word": "-top"}, {"start": 6.18, "length": 0.42, "word": "knopje"}, {"start": 6.6, "length": 0.66, "word": "ingedrukt"}]}], "final": true}, "segment": 0, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:30.282 6077-6077/nl.app I/MyLog.i():22: Final: ik probeer nu nu iets herkent iets ik druk op -top knopje ingedrukt.
02-06 13:38:30.288 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:30.295 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:30.310 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.333 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment": 1, "result": {"hypotheses": [{"transcript": "u laat."}], "final": false}, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:30.333 6077-6077/nl.app I/MainActivity: Partial Result
02-06 13:38:30.340 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.366 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment": 1, "result": {"hypotheses": [{"transcript": "u laat ik."}], "final": false}, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:30.367 6077-6077/nl.app I/MainActivity: Partial Result
02-06 13:38:30.370 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.400 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.430 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.460 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.490 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.520 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.550 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.580 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.590 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment": 1, "result": {"hypotheses": [{"transcript": "u laat ik 'm."}], "final": false}, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:30.591 6077-6077/nl.app I/MainActivity: Partial Result
02-06 13:38:30.610 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.640 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.647 6077-6077/nl.app D/HybiParser: Creating frame for: EOS op: 1 err: -1
02-06 13:38:30.647 6077-6077/nl.app I/MainActivity: onUpdateStatus Speechkit status: STOPPING
02-06 13:38:30.649 1400-1426/? W/audio_hw_generic: Not supplying enough data to HAL, expected position 33559299 , only wrote 33559200
02-06 13:38:30.670 6077-6109/nl.app D/HybiParser: Creating frame for: [B@221087c op: 2 err: -1
02-06 13:38:30.971 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "segment-start": 8.0, "segment-length": 1.14, "total-length": 9.15, "result": {"hypotheses": [{"transcript": "u laat ik 'm los.", "confidence": 0.6697482379201027, "likelihood": 49.2539, "word-alignment": [{"start": 0.0, "length": 0.09, "word": "u"}, {"start": 0.09, "length": 0.21, "word": "laat"}, {"start": 0.3, "length": 0.09, "word": "ik"}, {"start": 0.39, "length": 0.09, "word": "'m"}, {"start": 0.48, "length": 0.45, "word": "los"}]}], "final": true}, "segment": 1, "id": "157206fe-790e-4562-89e7-7f3086cff23c"}
02-06 13:38:30.972 6077-6077/nl.app I/MyLog.i():22: Final: ik probeer nu nu iets herkent iets ik druk op -top knopje ingedrukt. u laat ik 'm los.
02-06 13:38:30.987 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:30.993 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:31.014 6077-6099/nl.app D/MyLog.d():12: {"num_workers_available": 3, "num_requests_processed": 230}
02-06 13:38:31.014 6077-6077/nl.app I/MainActivity: onReady
02-06 13:38:31.014 6077-6077/nl.app I/MainActivity: onUpdateStatus Speechkit status: READY
02-06 13:38:31.267 6077-6106/nl.app D/MyLog.d():12: {"status": 0, "adaptation_state": {"type": "string+gzip+base64", "id": "..content omitted on GitHub..", "value": "..content omitted on GitHub.. ...(..a lot of data...)..
02-06 13:38:31.267 6077-6077/nl.app E/MainActivity: Exception error
02-06 13:38:31.267 6077-6106/nl.app D/HybiParser: Got close op! 0 null
02-06 13:38:31.267 6077-6077/nl.app I/MainActivity: onUpdateStatus Speechkit status: READY
02-06 13:38:31.268 6077-6106/nl.app D/MyLog.d():12: Disconnect! null
02-06 13:38:31.270 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:31.274 6077-6102/nl.app D/OpenGLRenderer: endAllActiveAnimators on 0xabe4d880 (RippleDrawable) with handle 0x99cc1680
02-06 13:38:31.286 6077-6077/nl.app I/MainActivity: onFinish
02-06 13:38:31.302 6077-6102/nl.app D/EGL_emulation: eglMakeCurrent: 0xa7624400: ver 2 0 (tinfo 0xa767e8b0)
02-06 13:38:31.998 6077-6099/nl.app D/MyLog.d():12: {"num_workers_available": 4, "num_requests_processed": 230}
02-06 13:38:31.998 6077-6077/nl.app I/MainActivity: onReady
02-06 13:38:31.998 6077-6077/nl.app I/MainActivity: onUpdateStatus Speechkit status: READY

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

6 participants