Lawouach
run_forever() terminates too early
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.
@alumae can you verify that the problem persists (since the pull request was accepted)?
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
