websockets.server:Error in connection handler #231

at2me · 2023-07-14T18:55:11Z

I use alphacep/kaldi together with freeswitch mod_vosk every time when freeswich accesses kaldi this error pops up, while the module fulfills the request. But it seems to me that due to the fact that the load is quite high, this service loads the processor very much. Is there any way to fix this problem, or mute the error.
Is it possible somewhere in the settings to reduce the time for one session. As far as I know the time is 60 seconds, is it possible to do for example 30 seconds?

uname -a

Linux dk02 5.10.0-9-amd64 #1 SMP Debian 5.10.70-1 (2021-09-30) x86_64 GNU/Linux

docker ps -a

CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
5f7bc1b08479 alphacep/kaldi-ru:latest "python3 ./asr_serve…" 2 months ago Up 21 minutes 0.0.0.0:2700->2700/tcp, :::2700->2700/tcp nifty_tharp

tail -f /var/lib/docker/containers/5f7bc1b08479f4e14c632462938df6b1e60c3c0a61db43d51b54d16fd44db1ca/5f7bc1b08479f4e14c632462938df6b1e60c3c0a61db43d51b54d16fd44db1ca-json.log

{"log":"INFO:root:Connection from ('10.3.0.9', 41660)\n","stream":"stderr","time":"2023-07-14T18:40:00.855462379Z"}
{"log":"ERROR:websockets.server:Error in connection handler\n","stream":"stderr","time":"2023-07-14T18:40:20.107813533Z"}
{"log":"Traceback (most recent call last):\n","stream":"stderr","time":"2023-07-14T18:40:20.107854279Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 827, in transfer_data\n","stream":"stderr","time":"2023-07-14T18:40:20.107860284Z"}
{"log":" message = await self.read_message()\n","stream":"stderr","time":"2023-07-14T18:40:20.107864689Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 895, in read_message\n","stream":"stderr","time":"2023-07-14T18:40:20.107868311Z"}
{"log":" frame = await self.read_data_frame(max_size=self.max_size)\n","stream":"stderr","time":"2023-07-14T18:40:20.107872012Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 971, in read_data_frame\n","stream":"stderr","time":"2023-07-14T18:40:20.107890052Z"}
{"log":" frame = await self.read_frame(max_size)\n","stream":"stderr","time":"2023-07-14T18:40:20.107894352Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 1047, in read_frame\n","stream":"stderr","time":"2023-07-14T18:40:20.107897758Z"}
{"log":" frame = await Frame.read(\n","stream":"stderr","time":"2023-07-14T18:40:20.107901397Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/framing.py", line 116, in read\n","stream":"stderr","time":"2023-07-14T18:40:20.107904452Z"}
{"log":" raise ProtocolError("incorrect masking")\n","stream":"stderr","time":"2023-07-14T18:40:20.107907699Z"}
{"log":"websockets.exceptions.ProtocolError: incorrect masking\n","stream":"stderr","time":"2023-07-14T18:40:20.108038092Z"}
{"log":"\n","stream":"stderr","time":"2023-07-14T18:40:20.108044721Z"}
{"log":"The above exception was the direct cause of the following exception:\n","stream":"stderr","time":"2023-07-14T18:40:20.108047779Z"}
{"log":"\n","stream":"stderr","time":"2023-07-14T18:40:20.108051066Z"}
{"log":"Traceback (most recent call last):\n","stream":"stderr","time":"2023-07-14T18:40:20.108054064Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/server.py", line 191, in handler\n","stream":"stderr","time":"2023-07-14T18:40:20.108057295Z"}
{"log":" await self.ws_handler(self, path)\n","stream":"stderr","time":"2023-07-14T18:40:20.10811902Z"}
{"log":" File "/opt/vosk-server/websocket/./asr_server.py", line 38, in recognize\n","stream":"stderr","time":"2023-07-14T18:40:20.108129606Z"}
{"log":" message = await websocket.recv()\n","stream":"stderr","time":"2023-07-14T18:40:20.108133162Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 509, in recv\n","stream":"stderr","time":"2023-07-14T18:40:20.108136303Z"}
{"log":" await self.ensure_open()\n","stream":"stderr","time":"2023-07-14T18:40:20.108139497Z"}
{"log":" File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 803, in ensure_open\n","stream":"stderr","time":"2023-07-14T18:40:20.108142811Z"}
{"log":" raise self.connection_closed_exc()\n","stream":"stderr","time":"2023-07-14T18:40:20.108218495Z"}
{"log":"websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason\n","stream":"stderr","time":"2023-07-14T18:40:20.108229049Z"}

nshmyrev · 2023-07-14T19:47:21Z

'Incorrect masking' error means you are using wrong libks, you need our fork with a fix.

at2me · 2023-07-14T20:00:59Z

I'm using the official docker image, so there might be a bug there then it's worth fixing.

@nshmyrev Could you please tell me where it can be downloaded and if it can be used in docker?

nshmyrev · 2023-07-14T22:21:59Z

https://github.com/alphacep/freeswitch/blob/master/src/mod/asr_tts/mod_vosk/README.md?plain=1#L31

at2me · 2023-11-22T20:52:38Z

# cat Dockerfile

FROM alphacep/kaldi-vosk-server:latest

ENV RUVERSION 0.42
RUN mkdir /opt/vosk-model-ru \
   && cd /opt/vosk-model-ru \
   && wget -q http://alphacephei.com/kaldi/models/vosk-model-ru-${RUVERSION}.zip \
   && unzip vosk-model-ru-${RUVERSION}.zip \
   && mv vosk-model-ru-${RUVERSION} model \
   && rm -rf model/extra \
   && rm -rf vosk-model-ru-${RUVERSION}.zip

RUN apt update && \
    apt-get install -yq build-essential cmake uuid-dev libssl-dev

RUN mkdir /src \
    && cd /src \
    && git clone --branch vosk-fix --single-branch https://github.com/alphacep/libks  \
    && cd libks \
    && cmake . -DCMAKE_BUILD_TYPE=Release \
    && make \
    && make install \
    && cd .. \
    && rm -rf /src/libks

EXPOSE 2700
WORKDIR /opt/vosk-server/websocket
CMD [ "python3", "./asr_server.py", "/opt/vosk-model-ru/model" ]

# docker build -t alphacep/kaldi-ru:custom .
# docker run -d -p 2700:2700 alphacep/kaldi-ru:custom

After run docker I try to make call again, but problem still not resolved.

# docker logs -f 5f7bc1b08479

INFO:root:Connection from ('10.1.1.2', 56228)
ERROR:websockets.server:Error in connection handler
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 827, in transfer_data
    message = await self.read_message()
  File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 895, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 971, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 1047, in read_frame
    frame = await Frame.read(
  File "/usr/lib/python3/dist-packages/websockets/framing.py", line 116, in read
    raise ProtocolError("incorrect masking")
websockets.exceptions.ProtocolError: incorrect masking

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/websockets/server.py", line 191, in handler
    await self.ws_handler(self, path)
  File "/opt/vosk-server/websocket/./asr_server.py", line 38, in recognize
    message = await websocket.recv()
  File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 509, in recv
    await self.ensure_open()
  File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 803, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason

nshmyrev · 2023-11-22T22:33:53Z

You need to solve masking issue

at2me · 2023-11-22T23:11:51Z

Can you see it now?

nshmyrev · 2023-11-25T11:44:25Z

You need to install libks on freeswitch side, not on the vosk side. Freeswitch links with libks for websocket. connection.

at2me · 2023-11-27T18:21:46Z

I compiled the lib on a separate server,

git clone --branch vosk-fix --single-branch https://github.com/alphacep/libks

cmake .
make

copied the libks.so.1 library to Freeswitch

mv /usr/lib/libks.so.1 /usr/lib/libks.so.1.bak
cp ~user01/libks.so.1 /usr/lib/libks.so.1

ls -l | grep lib
-rw------- 1 root root 688312 Nov 27 20:48 libks.so.1
-rw------- 1 root root 778376 Nov 27 20:49 libks.so.1.bak

service freeswitch restart
fs_cli
freeswitch@freeswitch> module_exists mod_vosk
true

I checked the performance, I did not notice any changes in the work.

I looked at the changes, there are practically no corrections
signalwire/libks@master...alphacep:libks:vosk-fix

Tell me, maybe I compiled it somehow wrong, maybe I need to use some keys or do it directly on the freeswitch server?

nshmyrev · 2023-11-28T01:18:27Z

Do you still see websockets.exceptions.ProtocolError: incorrect masking message on the server?

at2me · 2023-11-28T10:30:01Z

Unfortunately, after replacing the library and restarting Freeswitch, the situation did not change at all:

INFO:root:Connection from ('10.1.2.2', 42846)
ERROR:websockets.server:Error in connection handler
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 838, in transfer_data
await asyncio.shield(self._put_message_waiter)
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/websockets/server.py", line 191, in handler
await self.ws_handler(self, path)
File "/opt/vosk-server/websocket/./asr_server.py", line 70, in recognize
await websocket.send(response)
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 555, in send
await self.ensure_open()
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 812, in ensure_open
raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason
ERROR:websockets.server:Error in connection handler

nshmyrev · 2023-11-28T11:36:04Z

I see masking issue went away. It should be better now. Do you get recognition results in freeswitch or what?

at2me · 2023-11-28T12:22:08Z

I'll check. In the evening I will upload this library to the rest of FS and look at the results.
Can anything be done about the remaining errors? As I understand it, you need to close the channel somehow correctly.
On the FS we analyze the message for matches,

cat detected_speech.lua
local body = event:getBody()
--freeswitch.consoleLog("DEBUG", event:serialize() .. "\n");
if body then
local uuid = event:getHeader("Other-Leg-Unique-ID") or "Empty UUID"
local number = event:getHeader("Caller-Destination-Number") or "Empty AON"
freeswitch.consoleLog("DEBUG", uuid .. " " .. number .. " Channels text:" .. body .. "\n");
if string.match(body, "недоступен") or
string.match(body, "номер занят") then
local api = freeswitch.API()
freeswitch.consoleLog("DEBUG", "Bot " .. number .. " detected. Killing the main channel " .. uuid .. ". Phrase:" .. body .. "\n")
local kill = api:execute("uuid_kill", uuid)
end

cat dialplan.lua
....
if caller_id_table["vosk-busy"] == "t" then
table.insert(b_leg_on_pre_answer, "detect_speech vosk default default")
table.insert(b_leg_on_answer, "detect_speech vosk default default")
table.insert(bridge_params, "fire_asr_events=true")
end
...
and if we get match, we hang up.
by default vosk listens to the all conversation. Is it possible to reduce this parameter?
For example, set it to 30 seconds to reduce the load on the vosk-docker by half.

at2me · 2023-11-28T20:43:21Z

I replaced the lib (libks.so.1), unfortunately there is an error in the log:

INFO:root:Connection from ('10.2.1.2', 39046)
ERROR:websockets.server:Error in connection handler
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 827, in transfer_data
message = await self.read_message()
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 895, in read_message
frame = await self.read_data_frame(max_size=self.max_size)
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 971, in read_data_frame
frame = await self.read_frame(max_size)
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 1047, in read_frame
frame = await Frame.read(
File "/usr/lib/python3/dist-packages/websockets/framing.py", line 116, in read
raise ProtocolError("incorrect masking")
websockets.exceptions.ProtocolError: incorrect masking

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/websockets/server.py", line 191, in handler
await self.ws_handler(self, path)
File "/opt/vosk-server/websocket/./asr_server.py", line 38, in recognize
message = await websocket.recv()
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 509, in recv
await self.ensure_open()
File "/usr/lib/python3/dist-packages/websockets/protocol.py", line 803, in ensure_open
raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason

nshmyrev · 2023-11-30T00:49:19Z

You have masking message again. I'm sorry I will not repeat myself

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

websockets.server:Error in connection handler #231

websockets.server:Error in connection handler #231

at2me commented Jul 14, 2023

nshmyrev commented Jul 14, 2023

at2me commented Jul 14, 2023

nshmyrev commented Jul 14, 2023

at2me commented Nov 22, 2023 •

edited by nshmyrev

Loading

nshmyrev commented Nov 22, 2023

at2me commented Nov 22, 2023

nshmyrev commented Nov 25, 2023

at2me commented Nov 27, 2023

nshmyrev commented Nov 28, 2023

at2me commented Nov 28, 2023 •

edited

Loading

nshmyrev commented Nov 28, 2023

at2me commented Nov 28, 2023 •

edited

Loading

at2me commented Nov 28, 2023

nshmyrev commented Nov 30, 2023

websockets.server:Error in connection handler #231

websockets.server:Error in connection handler #231

Comments

at2me commented Jul 14, 2023

uname -a

docker ps -a

tail -f /var/lib/docker/containers/5f7bc1b08479f4e14c632462938df6b1e60c3c0a61db43d51b54d16fd44db1ca/5f7bc1b08479f4e14c632462938df6b1e60c3c0a61db43d51b54d16fd44db1ca-json.log

nshmyrev commented Jul 14, 2023

at2me commented Jul 14, 2023

nshmyrev commented Jul 14, 2023

at2me commented Nov 22, 2023 • edited by nshmyrev Loading

nshmyrev commented Nov 22, 2023

at2me commented Nov 22, 2023

nshmyrev commented Nov 25, 2023

at2me commented Nov 27, 2023

nshmyrev commented Nov 28, 2023

at2me commented Nov 28, 2023 • edited Loading

nshmyrev commented Nov 28, 2023

at2me commented Nov 28, 2023 • edited Loading

at2me commented Nov 28, 2023

nshmyrev commented Nov 30, 2023

at2me commented Nov 22, 2023 •

edited by nshmyrev

Loading

at2me commented Nov 28, 2023 •

edited

Loading

at2me commented Nov 28, 2023 •

edited

Loading