Cognitive-services-speech-sdk: Python SDK Doesn't Close Resources, Causes WS_ERROR_UNDERLYING_IO_ERROR

[Checkroth]

Describe the bug
Python Implementation of the SDK does not close resources. Open file handlers and TCP connections will grow unbounded unless the parent process of the SDK is killed.

When resources are left open and growing, WebSocket operation failed. Internal error: 3. Error details: WS_ERROR_UNDERLYING_IO_ERROR comes out of the SDK at an alarming rate (sometimes more than 50% of requests will spit out the error)

To Reproduce

Steps to reproduce the behavior:

1. Implement a simple gunicorn server that will call the speech to text SDK (like this example)
2. Access your server, which should trigger speech to text
3. Check lsof and netstat and you will see file handlers grow with every request

LSOF will show the following two files open by the gunicorn worker process indefinitely. Additional file handlers to the same two files will be added with every request, while previous ones will not close.

python3.7/site-packages/azure/cognitiveservices/speech/libMicrosoft.CognitiveServices.Speech.core.so
python3.7/site-packages/azure/cognitiveservices/speech/libMicrosoft.CognitiveServices.Speech.extension.kws.so

In addition to the underlying IO error from the sdk, this will eventually lead to a too many open files system error if the sdk is being used in a persistent API.

And netstat will show dangling TCP connections indefinitely

Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 10.200.11.137:47238     52.184.80.197:443       ESTABLISHED 30945/python3.7
tcp        0      0 10.200.11.137:47240     52.184.80.197:443       ESTABLISHED 30946/python3.7
tcp        0      0 10.200.11.137:47246     52.184.80.197:443       ESTABLISHED 30945/python3.7

1. Restart the server -> This will close all of the TCP connections and open file handlers.
2. Repeated requests without restarting the server will lead to WebSocket operation failed. Internal error: 3. Error details: WS_ERROR_UNDERLYING_IO_ERROR coming out of the SDK very frequently.

Expected behavior
One of the following:

• Python's SpeechRecognizer class should implement a close method to clean up resources.
• stop_continuous_recognition should clean up resources.

Version of the Cognitive Services Speech SDK

azure-cognitiveservices-speech==1.6.0 from Pip

Platform, Operating System, and Programming Language

• OS: Debian Streth, Amazon Linux 2, Ubuntu 19.04
• Hardware - x64

model name      : Intel(R) Xeon(R) Platinum 8175M CPU @ 2.50GHz
stepping        : 4
cpu MHz         : 2500.000
cache size      : 33792 KB

• Programming language: Python 3.7

Additional context

• All of my requests to the sdk are using the same audio file
• If I restart the parent worker, TCP connections and open file handlers are closed
  
  
  
  • Additionally, with this restart the underlying IO error stops happening
  
  
• I have reproduced this issue on several different AWS EC2 instances, as well as on locally running Docker machines so I don't think it's a system-level network issue.
• I have tried the following settings in sysctl to fix the issue from a system level to no avail

net.ipv4.tcp_fin_timeout = 5
net.ipv4.tcp_tw_recycle = 1
net.ipv4.tcp_tw_reuse = 1

TCPDump for sdk connections that end with WS_ERROR_UNDERELYING_IO_ERROR ends with the following:

    52.184.80.197.https > ip-10-200-11-29.49110: Flags [F.], cksum 0xda84 (correct), seq 5031, ack 195333, win 1517, options [nop,nop,TS val 1505324782 ecr 3200938], length 0
05:07:45.758722 IP (tos 0x0, ttl 64, id 61588, offset 0, flags [DF], proto TCP (6), length 1438)
    ip-10-200-11-29.49110 > 52.184.80.197.https: Flags [.], cksum 0xa0f2 (incorrect -> 0xc34a), seq 197445:198831, ack 5032, win 343, options [nop,nop,TS val 3200950 ecr 1505324782], length 1386
05:07:45.806866 IP (tos 0x0, ttl 41, id 0, offset 0, flags [DF], proto TCP (6), length 40)
    52.184.80.197.https > ip-10-200-11-29.49110: Flags [R], cksum 0x52c7 (correct), seq 189854933, win 0, length 0

It looks like Azure is sending a stop signal (Flags [F] and Flags [R]), but the SDK is continuing to send data anyway.

[Checkroth]

This could actually be two separate issues.

One, the SDK not closing resources is an issue because it will continue to consume memory and leave open file handlers.

The SO_UNDERLYING_IO_ERROR will happen more frequently the more TCP connections you have open through the SDK at one time. So while it will be triggered by the issue outlined here, it will also happen if you have a lot of concurrent workers for a server using the SDK. 10 concurrent requests will often fail one or more with an underlying IO error.

[chlandsi]

Thanks for reporting the issue. Can you try calling del recognizer on the recognizer objects when they are not needed any more? This should close the open resources.

[Checkroth]

@chlandsi thanks for your response.

I should have put in the ticket, I've tried del on a few structures with no change. All of the following leave the open file handlers and TCP connections as outlined in the ticket.

• Deleting speech recognizer instance after start_continuous_recognition
• Deleting speech recognizer instance after start_continuous_recognition_async
• Deleting the returned Future object returned by start_continuous_recognition_async
• Note: I am appropriately calling stop_continuous_recognition_async in the session stopped callback.

From my understanding, Continuous Recognition starts an asynchronous process that isn't directly tied to the recognizer. My worry is that the dangling resources are being used there, and that resource isn't being properly cleaned up.

Any idea how we might access these resources with the information we have from the recognizer object (or the callback events)?

[chlandsi]

Can you share the code you are using for testing?

Cleaning up the recognizer should release all held resources, but with the multithreaded processing behind it this can be tricky. Depending on your application, you might also be able to reuse the recognizers (using streams), which would give you the benefit of being able to reuse the connection, which reduces latency. Or does your framework allow to use a separate process for each recognition? Despite these possible workarounds, there shouldn't be any resources left behind, of course.

[Checkroth]

Here's a gist: https://gist.github.com/Checkroth/c46727c7f852b2c1ab5f098e4e685a8a

I'm running this with Gunicorn,

gunicorn --workers 5 --threads 5 --reuse-port --preload --timeout 120 -b 0.0.0.0:8000 stt:app

Resources are cleaned up if I stop using threads, and set gunicorn's max-requests to 1 (so the worker restarts after every request).

If I remove the threads, but _don't_ set max-requests, the issue persists. If I remove the threads and set the worker count to 1, the issue still persists. So I don't think it's being caused by the server being threaded.

I've also checked from just running speech recognition in the python interactive shell, and confirmed that it's not really related to Gunicorn. Once you call start_continuous_recognition, the TCP connection stays open with the ESTABLISHED state and the open file handlers remain opened, even if you call del on the recognizer.

The performance requirements for my application mean that I realistically need to use threaded workers, so restarting the worker after each request isn't really a viable solution.

Depending on your application, you might also be able to reuse the recognizers (using streams),

Is there any documentation on how this could be achieved? From what I understand, building the recognizer requires the audio config, which requires the audio stream. Are you suggesting that I implement it in a way that I call some function directly on the PullAudioInputStreamCallback that reads in a new stream, mutating the original stream that was passed in when it was first started?

[Checkroth]

Major Update:

I haven't solved the underlying IO error -- that's a totally separate problem that is just made slightly worse by the dangling resources.

I have managed to clean up recognizer resources after speech to text is finished, after some digging through the source code.

You have to delete the Recognizer class. The SpeechRecognizer class extends it through several layers of obfuscation in a way that ensures it _doesn't_ clean up the resources of its parent classes for some unknown reason.

So, if you have an instance of SpeechRecognizer and you want to clean it up without killing the entire process its running in,

del SpeechRecognizer._impl will do the trick. del SpeechRecognizer will not.

A suggestion for the implementation: Make it so that del SpeechRecognizer cleans up its resources. Or better yet, implement a close function to allow you to do it safely.

[chlandsi]

Thanks @Checkroth for the code, and the detailed analysis. We'll investigate, and try to put a fix into the next release.

Regarding reusing the recognizer, you can leave the stream open, and just push new audio when it's available. Your mileage will vary though, since segmentation depends on seeing a certain amount of silence between utterances, and timestamps will always be relative to the first audio segment sent. We are working on a clearer way to separate segments inside a single stream, but there is no timeline for this yet.

[Checkroth]

@chlandsi Thanks for your input.

I'd like to avoid pushing new audio due to the related error outlined in this ticket. I've been getting intermittent WS_UNDERLYING_IO_ERRORs thrown. Sometimes I get none for hours, and other times its upwards of 50% of requests throwing them. I suspect its related to bandwidth on my server, but its very difficult to find out exactly what is happening. Ultimately this means that connections to auzre through the SDK are unstable at best, so reusing them isn't likely to solve any of my problems.

In any case, deleting ._impl cleans up the resources properly. I've confirmed that all TCP connections and dangling file handlers are closed.

I'd prefer a dedicated method to close SpeechRecognizer instances, or for stop_continuous_recognition to clean up those resources for you (though that might be the right time to do it, in case somebody is reusing Recognizer instances as you outlined). Also some documentation on this functionality would be much appreciated.

Both of those suggestions are completely up to the dev team for this SDK, so I'll leave whether or not to close this ticket up to you.

[chlandsi]

Hi @Checkroth, could you post the session id of one or a couple of the sessions where you get the WS_UNDERLYING_IO_ERROR, so we can correlate with the service logs? Thanks!

[chlandsi]

Hi @Checkroth, I had a detailed look at your application code, and I found a few problems, mostly resulting from lacking documentation, and unintended behavior of our samples (thank you for pointing me to it!):

1) The problem of not cleaning up resources is not caused inside the SDK, but by a circular reference: The stop_cb callback is a closure which keeps a reference to the recognizer, but is also referenced from inside the recognizer as an event handler. Thus, the recognizer is not garbage collected unless the circle is broken, either by manually removing a reference to the recognizer._impl, or by calling recognizer.session_stopped.disconnect_all() and recognizer.canceled.disconnect_all(), once the recognizer is not needed any more. Alternatively, you can also call stop_continuous_recognition outside the callback, after the wait for either a canceled or a session-stopped event is finished. This problem is also present in our samples; we will amend them.
2) The input stream should be closed before calling stop_continuous_recognition, not after.
3) The stop_cb is called either with a SessionEventArgs or a SpeechRecognitionEventArgs instance, depending on which event it is responding to. Only the latter has a .result field, for the other type of event there will be an exception inside the event handler, which is silent due to the way the callback functions are handled.

I put a version of the code that fixes these problems here.

In my experiments, 2) and 3) had an effect on the WS_UNDERLYING_IO_ERROR; still it would be good to check the service logs for the particular problems you had.

[Checkroth]

@chlandsi thank you for pointing out potential improvements to sdk usage. I'll try implementing those.

In the mean-time, here are a few session Ids to WS_UNDERLYING_IO_ERROR requests.
I've just triggered these now, but before implementing any of the suggestions you've outlined.

Some info on the environment in which these are being executed:

• I'm sending the same 7-second-long audio file to my server 100 times asynchronously, 20 at a time
  
  
  
  • They're sent via the python interactive console using a thread pool executor. The bytes I'm sending are all the same variable, so there is no difference between each request.
  
  
  • The successful result json should be {"DisplayText":"Once we know where we are the world becomes as narrow as a map when we don\'t know the world feels unlimited.","Duration":64500000,"Offset":5500000,"RecognitionStatus":"Success"}
  
  
• The server is running on AWS and is behind a load balancer. This shouldn't impact outgoing traffic, but I've noticed that WS_UNDERLYING_ERRORS aren't reproducible if I run the server locally, so its possible this is somehow related.
• The server is running 3 workers with 5 threads each. So it should be doing 15 concurrent SDK connections.

Out of 100 requests sent 20 at a time, 5 of them failed with WS_UNDERLYING_IO_ERROR. Their SessionIDs are:

• d2c13c4e1ed34f709a3984d3cabd6c58
• 88c64373695a498ca21f2c1c5c4f3314
• 33b3fa1f5ca24f1e946c22ed1e15903a
• d9f158c19a024a6b84142b87885dddce
• 79302ecc639248a186050cafaa87b158

[Checkroth]

Small update:

I've implemented your suggestions.

I have confirmed that disconnecting the callbacks and closing the input stream _before_ stopping recognition has caused the resources to be properly cleaned up without manually deleting SpeechRecognizer._impl.

Unfortunately, it's had no impact on the WS_UNDERLYING_IO_ERROR being thrown. Here are a few session IDs that occurred after the change was implemented:

• 029e055d8d1f4861a33fccd7c624e6e8
• 858ae40a17934359ae2a82b5a061df20
• 15f11c35213f4c588f38e045a8ed49e7
• 3058b22c844742d682a2c70fda2d8047
• c844bdfbbf2643e791e50766f273ae0d
• 12341d4253524773ac546da7afbcc589

[chlandsi]

Hi @Checkroth, thank you for the update. From the service logs, it looks like you are hitting a bug in the websocket implementation we use, which causes the connection to be closed ungracefully by the server. This will be fixed in the next release of the SDK, which should drop in early September. As a workaround, throttling the input of audio data in your input stream, for example to real-time speed, should work.
I'm sorry for the inconvenience!

[Checkroth]

@chlandsi Thanks for letting me know! Good to know that it will be fixed soon.

Can you clarify a bit for me?

You say that the bug is with the connection being closed ungracefully, and that we can stop the IO errors by throttling input of the audio. This sounds like there are two issues with the SDK: One where connections are being closed ungracefully, and another where the input stream is sending data faster than the SDK expects.

Will the fix you release address both of these issues, or just the ungraceful connection closure? After the fix is released, will the error stop completely, or will it just occur with a cleaner context?

[chlandsi]

The bug in the current version can lead to packets being dropped or sent out of order in cases of high network load. This breaks decryption on the server, which then aborts the connection. Slowing down the input helps to reduce the network load; in absence of this error the SDK can accept input data at any rate. The SDK buffers it internally and throttles to a speed the service expects.

The fix will address the network problem and thus make the throttling of the stream unnecessary; the error should be gone after the update.

[chlandsi]

@Checkroth: The SDK update has been released. I'm closing this for now, please reopen/create a new issue if there are problems.