Unable to close grpc_channel. Connection was interrupted on the server side

romqn1999 commented 7 months ago

I set up a Qdrant Vector DB in a Docker container and created a Python script to query the Vector DB using QdrantClient. However, after executing all queries, when the QdrantClient attempts to close the connection, it throws an error stating, "Unable to close grpc_channel. Connection was interrupted on the server side."

Current Behavior

The error message from QdrantClient:

[2024-01-30 12:27:28,956-WARNING: close:163] Unable to close grpc_channel. Connection was interrupted on the server side
Exception ignored in: <function QdrantClient.__del__ at 0x7fea068b9ee0>
Traceback (most recent call last):
  File "/lib/python3.9/site-packages/qdrant_client/qdrant_client.py", line 132, in __del__
  File "/lib/python3.9/site-packages/qdrant_client/qdrant_client.py", line 139, in close
  File "/lib/python3.9/site-packages/qdrant_client/qdrant_remote.py", line 163, in close
  File "/lib/python3.9/logging/__init__.py", line 2082, in warning
  File "/lib/python3.9/logging/__init__.py", line 1458, in warning
  File "/lib/python3.9/logging/__init__.py", line 1589, in _log
  File "/lib/python3.9/logging/__init__.py", line 1599, in handle
  File "/lib/python3.9/site-packages/sentry_sdk/integrations/logging.py", line 102, in sentry_patched_callhandlers
TypeError: argument of type 'NoneType' is not iterable

Steps to Reproduce

Config the vector DB using docker-compose
```
version: '3.9'
```

services: vector-db: image: qdrant/qdrant volumes:

./data/qdrant_storage:/qdrant/storage:z ports:
6333:6333
6334:6334 networks:
my-net

networks: my-net:

2. Initialize `QdrantClient` in a custom Python class's `__init__` method to execute queries in other methods:
```python
class MyClass(ABC):
    def __init__(self):
        self.vector_db_client = QdrantClient("vector-db", prefer_grpc=True)

    def my_func(self):
        # Make queries to the Vector DB using `self.vector_db_client`

Run the script and encounter the above error upon exiting.

Expected Behavior

The script should exit successfully without any errors.

Context (Environment)

Qdrant Vector DB: v1.7.3
qdrant-client: v1.7.1

timvisee commented 7 months ago

Do you stop the container before or after closing the client?

romqn1999 commented 7 months ago

No, the container is still running.

joein commented 7 months ago

Are there any logs in the container?

romqn1999 commented 7 months ago

Logs from the container:

$ docker logs -f vector-db-1
           _                 _    
  __ _  __| |_ __ __ _ _ __ | |_  
 / _` |/ _` | '__/ _` | '_ \| __| 
| (_| | (_| | | | (_| | | | | |_  
 \__, |\__,_|_|  \__,_|_| |_|\__| 
    |_|                           

Access web UI at http://0.0.0.0:6333/dashboard

2024-01-30T05:15:39.925684Z  INFO storage::content_manager::consensus::persistent: Loading raft state from ./storage/raft_state.json       
2024-01-30T05:16:04.807505Z  INFO storage::content_manager::toc: Loading collection: user_emb    
2024-01-30T05:16:14.101076Z  INFO storage::content_manager::toc: Loading collection: item_emb    
2024-01-30T05:16:14.229290Z  INFO qdrant: Distributed mode disabled    
2024-01-30T05:16:14.229318Z  INFO qdrant: Telemetry reporting enabled, id: cb82a921-d38e-41ee-90c0-9ceb7c2ee0d1    
2024-01-30T05:16:14.238894Z  INFO qdrant::tonic: Qdrant gRPC listening on 6334    
2024-01-30T05:16:14.238924Z  INFO qdrant::tonic: TLS disabled for gRPC API    
2024-01-30T05:16:14.239222Z  INFO qdrant::actix: TLS disabled for REST API    
2024-01-30T05:16:14.239476Z  INFO qdrant::actix: Qdrant HTTP listening on 6333    
2024-01-30T05:16:14.239497Z  INFO actix_server::builder: Starting 63 workers
2024-01-30T05:16:14.239516Z  INFO actix_server::server: Actix runtime found; starting in Actix runtime
2024-01-30T06:16:06.842397Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/index-014e4952.css HTTP/1.1" 200 32159 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.002809    
2024-01-30T06:16:06.977221Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/index-9558a693.js HTTP/1.1" 200 1697433 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.138256    
2024-01-30T06:16:07.464954Z  INFO actix_web::middleware::logger: x.x.x.x "GET /telemetry HTTP/1.1" 200 358 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.000534    
2024-01-30T06:16:07.530184Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/openapi.json HTTP/1.1" 200 45554 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.002767    
2024-01-30T06:16:07.688511Z  INFO actix_web::middleware::logger: x.x.x.x "GET /collections HTTP/1.1" 200 166 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.000172    
2024-01-30T06:16:07.749565Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/editor.worker-01324a4b.js HTTP/1.1" 200 80295 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.003138    
2024-01-30T06:16:07.918943Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/codicon-8b349ebc.ttf HTTP/1.1" 200 46405 "http://y.y.y.y:6333/dashboard/assets/index-014e4952.css" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.003582    
2024-01-30T06:16:15.059907Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/jsonMode-a15a0cf4.js HTTP/1.1" 200 13817 "http://y.y.y.y:6333/dashboard/assets/index-9558a693.js" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.002896    
2024-01-30T06:16:15.172856Z  INFO actix_web::middleware::logger: x.x.x.x "GET /collections HTTP/1.1" 200 167 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.000347    
2024-01-30T06:16:15.193394Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/json.worker-dcfd985a.js HTTP/1.1" 200 126407 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.012863    
2024-01-30T06:16:17.171795Z  INFO actix_web::middleware::logger: x.x.x.x "GET /collections HTTP/1.1" 200 166 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.000362    
2024-01-30T06:16:18.394516Z  INFO actix_web::middleware::logger: x.x.x.x "GET /dashboard/assets/prism-json-7ae4e91d.js HTTP/1.1" 200 275 "http://y.y.y.y:6333/dashboard/assets/index-9558a693.js" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.000985    
2024-01-30T11:04:56.380292Z  INFO actix_web::middleware::logger: x.x.x.x "GET /telemetry HTTP/1.1" 200 495 "http://y.y.y.y:6333/dashboard" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" 0.002199

It appears that the logs don't show any messages related to my queries, even though my queries were successfully executed.

timvisee commented 7 months ago

It appears that the logs don't show any messages related to my queries, even though my queries were successfully executed.

Your queries might go over gRPC. We only log REST requests, not gRPC requests.

romqn1999 commented 7 months ago

Ah, I see. Even after changing the QdrantClient without prefer_grpc, I'm still encountering the error.

Logs from the container:

2024-01-31T09:11:16.432574Z  INFO actix_web::middleware::logger: x.x.x.x "POST /collections/item_emb/points/scroll HTTP/1.1" 200 675463 "-" "python-httpx/0.25.0" 0.068555    
2024-01-31T09:11:17.521822Z  INFO actix_web::middleware::logger: x.x.x.x "POST /collections/item_emb/points/search/batch HTTP/1.1" 200 220599 "-" "python-httpx/0.25.0" 0.121472

Logs from the client:

$ python my_script.py
[2024-01-31 16:15:58,376-DEBUG: load_ssl_context:79] load_ssl_context verify=True cert=None trust_env=True http2=False
[2024-01-31 16:15:58,377-DEBUG: load_ssl_context_verify:146] load_verify_locations cafile='/home/daclth/.local/lib/python3.9/site-packages/certifi/cacert.pem'
[2024-01-31 16:15:58,453-DEBUG: load_ssl_context:79] load_ssl_context verify=True cert=None trust_env=True http2=False
[2024-01-31 16:15:58,454-DEBUG: load_ssl_context_verify:146] load_verify_locations cafile='/home/daclth/.local/lib/python3.9/site-packages/certifi/cacert.pem'
[2024-01-31 16:15:59,437-DEBUG: trace:45] connect_tcp.started host='x.x.x.x' port=6333 local_address=None timeout=5.0 socket_options=None
[2024-01-31 16:15:59,438-DEBUG: trace:45] connect_tcp.complete return_value=<httpcore._backends.sync.SyncStream object at 0x7f58ed3ca430>
[2024-01-31 16:15:59,438-DEBUG: trace:45] send_request_headers.started request=<Request [b'POST']>
[2024-01-31 16:15:59,438-DEBUG: trace:45] send_request_headers.complete
[2024-01-31 16:15:59,438-DEBUG: trace:45] send_request_body.started request=<Request [b'POST']>
[2024-01-31 16:15:59,439-DEBUG: trace:45] send_request_body.complete
[2024-01-31 16:15:59,439-DEBUG: trace:45] receive_response_headers.started request=<Request [b'POST']>
[2024-01-31 16:15:59,460-DEBUG: trace:45] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'transfer-encoding', b'chunked'), (b'content-type', b'application/json'), (b'content-encoding', b'gzip'), (b'vary', b'accept-encoding, Origin, Access-Control-Request-Method, Access-Control-Request-Headers'), (b'date', b'Wed, 31 Jan 2024 09:15:59 GMT')])
[2024-01-31 16:15:59,462-INFO: _send_single_request:1013] HTTP Request: POST http://x.x.x.x:6333/collections/item_emb/points/scroll "HTTP/1.1 200 OK"
[2024-01-31 16:15:59,463-DEBUG: trace:45] receive_response_body.started request=<Request [b'POST']>
[2024-01-31 16:15:59,511-DEBUG: trace:45] receive_response_body.complete
[2024-01-31 16:15:59,511-DEBUG: trace:45] response_closed.started
[2024-01-31 16:15:59,511-DEBUG: trace:45] response_closed.complete
[2024-01-31 16:16:00,443-DEBUG: trace:45] send_request_headers.started request=<Request [b'POST']>
[2024-01-31 16:16:00,443-DEBUG: trace:45] send_request_headers.complete
[2024-01-31 16:16:00,443-DEBUG: trace:45] send_request_body.started request=<Request [b'POST']>
[2024-01-31 16:16:00,449-DEBUG: trace:45] send_request_body.complete
[2024-01-31 16:16:00,449-DEBUG: trace:45] receive_response_headers.started request=<Request [b'POST']>
[2024-01-31 16:16:00,565-DEBUG: trace:45] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'transfer-encoding', b'chunked'), (b'content-type', b'application/json'), (b'content-encoding', b'gzip'), (b'vary', b'accept-encoding, Origin, Access-Control-Request-Method, Access-Control-Request-Headers'), (b'date', b'Wed, 31 Jan 2024 09:16:00 GMT')])
[2024-01-31 16:16:00,565-INFO: _send_single_request:1013] HTTP Request: POST http://x.x.x.x:6333/collections/item_emb/points/search/batch "HTTP/1.1 200 OK"
[2024-01-31 16:16:00,566-DEBUG: trace:45] receive_response_body.started request=<Request [b'POST']>
[2024-01-31 16:16:00,580-DEBUG: trace:45] receive_response_body.complete
[2024-01-31 16:16:00,581-DEBUG: trace:45] response_closed.started
[2024-01-31 16:16:00,581-DEBUG: trace:45] response_closed.complete
[2024-01-31 16:16:00,992-DEBUG: trace:45] close.started
[2024-01-31 16:16:00,992-WARNING: close:181] Unable to close http connection. Connection was interrupted on the server side
Exception ignored in: <function QdrantClient.__del__ at 0x7f5860a153a0>
Traceback (most recent call last):
  File "/lib/python3.9/site-packages/qdrant_client/qdrant_client.py", line 132, in __del__
  File "/lib/python3.9/site-packages/qdrant_client/qdrant_client.py", line 139, in close
  File "/lib/python3.9/site-packages/qdrant_client/qdrant_remote.py", line 181, in close
  File "/lib/python3.9/logging/__init__.py", line 2082, in warning
  File "/lib/python3.9/logging/__init__.py", line 1458, in warning
  File "/lib/python3.9/logging/__init__.py", line 1589, in _log
  File "/lib/python3.9/logging/__init__.py", line 1599, in handle
  File "/lib/python3.9/site-packages/sentry_sdk/integrations/logging.py", line 102, in sentry_patched_callhandlers
TypeError: argument of type 'NoneType' is not iterable

joein commented 7 months ago

I could not reproduce the error with the code sample you've provided :( Are you sure it is reproducible with the code sample?

Could you maybe tell us your operation system, python version, etc?

romqn1999 commented 7 months ago

Ah, I've discovered that the issue occurs when I include from feast import FeatureStore. The error disappears when I comment out this line.

joein commented 7 months ago

It would be highly appreciated if you could provide a code sample to reproduce the issue, otherwise we'll have to put it on hold for a while before we can dig into it.

romqn1999 commented 7 months ago

Here's the code snippet to reproduce the issue:

from qdrant_client import QdrantClient
from feast import FeatureStore

class MyClass():
    def __init__(self, vector_db_host, vector_db_port):
        self.vector_db_client = QdrantClient(vector_db_host, grpc_port=vector_db_port, prefer_grpc=True)

    def my_func(self):
        return self.vector_db_client.get_collections()

if __name__ == "__main__":
    obj = MyClass("x.x.x.x", 6334)
    res = obj.my_func()
    print(res)

joein commented 7 months ago

It is indeed reproducible with feast, I will take a closer look, thanks

joein commented 7 months ago

At the moment It seems like feast (or its dependencies) might be messing up with python's garbage collector

qdrant / qdrant-client