websockets.server:Error in connection handler

[at2me]

1. 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.

2. 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]

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

[at2me]

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]

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

[at2me]

# 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]

You need to solve masking issue

[at2me]

Can you see it now?

[nshmyrev]

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

[at2me]

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 https://github.com/signalwire/libks/compare/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]

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

[at2me]

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]

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

[at2me]

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]

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]

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