search

redis-stack / redis-stack-docs

6 stars 55 forks source link

Timeout reading from socket when connected by django application (both docker-containerized) #223

Closed alicia-lyu closed 1 year ago

alicia-lyu commented 1 year ago

I encountered an issue when my Django application tries to connect to redis. Both are running in docker containers locally on my MacBook Sonoma 14.1.1 (23B81). The issue was not present when I run the same containers on AWS EC2. This issue happens every time I send a request to the Django APIs, which should be the only traffic to redis.

redis itself is running and responding correctly

> make test-redis
docker compose exec redis redis-cli ping
PONG
> docker logs [redis_container_id]
9:C 17 Nov 2023 00:40:00.838 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
9:C 17 Nov 2023 00:40:00.838 * Redis version=7.2.1, bits=64, commit=00000000, modified=0, pid=9, just started
9:C 17 Nov 2023 00:40:00.838 * Configuration loaded
9:M 17 Nov 2023 00:40:00.839 * monotonic clock: POSIX clock_gettime
9:M 17 Nov 2023 00:40:00.839 * Running mode=standalone, port=6379.
9:M 17 Nov 2023 00:40:00.851 * <search> Redis version found by RedisSearch : 7.2.1 - oss
9:M 17 Nov 2023 00:40:00.851 * <search> RediSearch version 2.8.4 (Git=HEAD-7797d39d)
9:M 17 Nov 2023 00:40:00.851 * <search> Low level api version 1 initialized successfully
9:M 17 Nov 2023 00:40:00.851 * <search> concurrent writes: OFF, gc: ON, prefix min length: 2, prefix max expansions: 200, query timeout (ms): 500, timeout policy: return, cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 1000000, max number of search results:  10000, search pool size: 20, index pool size: 8, 
9:M 17 Nov 2023 00:40:00.852 * <search> Initialized thread pools!
9:M 17 Nov 2023 00:40:00.852 * <search> Enabled role change notification
9:M 17 Nov 2023 00:40:00.852 * Module 'search' loaded from /opt/redis-stack/lib/redisearch.so
9:M 17 Nov 2023 00:40:00.854 * <timeseries> RedisTimeSeries version 11004, git_sha=c10178d33caf11177e12ca575092b072d81a5cd2
9:M 17 Nov 2023 00:40:00.855 * <timeseries> Redis version found by RedisTimeSeries : 7.2.1 - oss
9:M 17 Nov 2023 00:40:00.855 * <timeseries> loaded default CHUNK_SIZE_BYTES policy: 4096
9:M 17 Nov 2023 00:40:00.855 * <timeseries> loaded server DUPLICATE_POLICY: block
9:M 17 Nov 2023 00:40:00.855 * <timeseries> Setting default series ENCODING to: compressed
9:M 17 Nov 2023 00:40:00.855 * <timeseries> Detected redis oss
9:M 17 Nov 2023 00:40:00.855 * Module 'timeseries' loaded from /opt/redis-stack/lib/redistimeseries.so
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> Created new data type 'ReJSON-RL'
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> version: 20606 git sha: unknown branch: unknown
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> Exported RedisJSON_V1 API
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> Exported RedisJSON_V2 API
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> Exported RedisJSON_V3 API
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> Exported RedisJSON_V4 API
9:M 17 Nov 2023 00:40:00.859 * <ReJSON> Enabled diskless replication
9:M 17 Nov 2023 00:40:00.859 * Module 'ReJSON' loaded from /opt/redis-stack/lib/rejson.so
9:M 17 Nov 2023 00:40:00.859 * <search> Acquired RedisJSON_V4 API
9:M 17 Nov 2023 00:40:00.860 * <bf> RedisBloom version 2.6.3 (Git=unknown)
9:M 17 Nov 2023 00:40:00.861 * Module 'bf' loaded from /opt/redis-stack/lib/redisbloom.so
9:M 17 Nov 2023 00:40:00.864 * <redisgears_2> Created new data type 'GearsType'
9:M 17 Nov 2023 00:40:00.865 * <redisgears_2> Detected redis oss
9:M 17 Nov 2023 00:40:00.866 # <redisgears_2> could not initialize RedisAI_InitError

9:M 17 Nov 2023 00:40:00.866 * <redisgears_2> Failed loading RedisAI API.
9:M 17 Nov 2023 00:40:00.866 * <redisgears_2> RedisGears v2.0.11, sha='0aa55951836750ceabd9733decb200f8a5e7bac3', build_type='release', built_for='Linux-ubuntu22.04.arm64v8'.
9:M 17 Nov 2023 00:40:00.877 * <redisgears_2> Registered backend: js.
9:M 17 Nov 2023 00:40:00.887 * Module 'redisgears_2' loaded from /opt/redis-stack/lib/redisgears.so
9:M 17 Nov 2023 00:40:00.887 * Server initialized
9:M 17 Nov 2023 00:40:00.887 * Ready to accept connections tcp

Error Message returned by docker logs [django_container_id]

Watching for file changes with StatReloader
Performing system checks...

System check identified no issues (0 silenced).
November 17, 2023 - 00:40:03
Django version 4.2, using settings 'mmland.settings'
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.

(<WSGIRequest: GET '/v1/TableTest/list/'>,) {'api_ver': '1', 'mod_name': 'TableTest', 'func': 'list', 'json_attr': ''} {}
/usr/local/lib/python3.9/site-packages/django/views/debug.py:487: ExceptionCycleWarning: Cycle in the exception chain detected: exception 'Timeout reading from socket' encountered again.
  warnings.warn(
Internal Server Error: /v1/TableTest/list/
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/django_redis/cache.py", line 31, in _decorator
    return method(self, *args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/django_redis/cache.py", line 98, in _get
    return self.client.get(key, default=default, version=version, client=client)
  File "/usr/local/lib/python3.9/site-packages/django_redis/client/default.py", line 260, in get
    raise ConnectionInterrupted(connection=client) from e
django_redis.exceptions.ConnectionInterrupted: Redis TimeoutError: Timeout reading from socket

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/django/core/handlers/exception.py", line 55, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.9/site-packages/django/core/handlers/base.py", line 197, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/usr/src/app/dj_easy/view.py", line 112, in wrapper
    raise e
  File "/usr/src/app/dj_easy/view.py", line 107, in wrapper
    rsp = Decorator.user_prepare(func, rsp=False)(req)
  File "/usr/src/app/dj_easy/ext.py", line 496, in wrapper
    user = cache.get(token, None)
  File "/usr/local/lib/python3.9/site-packages/django_redis/cache.py", line 91, in get
    value = self._get(key, default, version, client)
  File "/usr/local/lib/python3.9/site-packages/django_redis/cache.py", line 38, in _decorator
    raise e.__cause__
  File "/usr/local/lib/python3.9/site-packages/django_redis/client/default.py", line 258, in get
    value = client.get(key)
  File "/usr/local/lib/python3.9/site-packages/redis/commands/core.py", line 1790, in get
    return self.execute_command("GET", name)
  File "/usr/local/lib/python3.9/site-packages/redis/client.py", line 1255, in execute_command
    conn = self.connection or pool.get_connection(command_name, **options)
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 1442, in get_connection
    connection.connect()
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 710, in connect
    self.on_connect()
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 775, in on_connect
    if str_if_bytes(self.read_response()) != "OK":
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 865, in read_response
    response = self._parser.read_response(disable_decoding=disable_decoding)
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 346, in read_response
    result = self._read_response(disable_decoding=disable_decoding)
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 356, in _read_response
    raw = self._buffer.readline()
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 259, in readline
    self._read_from_socket()
  File "/usr/local/lib/python3.9/site-packages/redis/connection.py", line 222, in _read_from_socket
    raise TimeoutError("Timeout reading from socket")
redis.exceptions.TimeoutError: Timeout reading from socket
[17/Nov/2023 00:40:20] "GET /v1/TableTest/list/ HTTP/1.1" 500 136409
[17/Nov/2023 00:40:20] "GET /static/admin/img/calendar-icons.svg HTTP/1.1" 200 1094
[17/Nov/2023 00:40:20] "GET /static/admin/css/base.css HTTP/1.1" 200 21207

Static files, which doesn't depend on redis, are served correctly.

django setting

...
INTERNAL_IPS = [
    "127.0.0.1",
    "192.168.0.171",
]
ALLOWED_HOSTS = ['our-domain.com', 'localhost', 'host.docker.internal'] + INTERNAL_IPS
CSRF_TRUSTED_ORIGINS = ['https://our-domain.com']
# Application definition

INSTALLED_APPS = [
    'django.contrib.admin',
    'django.contrib.auth',
    'django.contrib.contenttypes',
    'django.contrib.sessions',
    'django.contrib.messages',
    'django.contrib.staticfiles',
    'app.apps.AppConfig',
    #'debug_toolbar',
    'storages',
]

MIDDLEWARE = [
    'django.middleware.security.SecurityMiddleware',
    'django.contrib.sessions.middleware.SessionMiddleware',
    'django.middleware.common.CommonMiddleware',
    #'debug_toolbar.middleware.DebugToolbarMiddleware',
    # 'django.middleware.csrf.CsrfViewMiddleware',
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    'django.contrib.messages.middleware.MessageMiddleware',
    'django.middleware.clickjacking.XFrameOptionsMiddleware',
]
...
DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.mysql',
        'CHARSET': 'utf8mb4',
        'NAME': 'mmland',
        'HOST': os.environ.get("DATABASE_DEFAULT_HOST"),
        'PORT': '8006',
        'USER': 'root',
        'PASSWORD': os.environ.get("DATABASE_ROOT_PASSWORD"),
        #'CONN_MAX_AGE': 5,
        'OPTIONS': {
            'charset': 'utf8mb4',
            'use_unicode': True,
            'init_command': "SET sql_mode='STRICT_TRANS_TABLES'",
        },
    },
}

CACHES = {
    "default": {
        "BACKEND": "django_redis.cache.RedisCache",
        "LOCATION": os.environ.get("REDIS_LOCATION"),
        "OPTIONS": {
            "CLIENT_CLASS": "django_redis.client.DefaultClient",
            "SOCKET_CONNECT_TIMEOUT": 10,  # in seconds
            "SOCKET_TIMEOUT": 10,  # in seconds
        }
    }
}
...

docker compose file

version: '3.8'

services:
  redis:
    image: "redis/redis-stack"
    ports:
      - "6379:6379"
    volumes:
      - redis_data:/usr/src/app/data
  web:
    build: .
    command: python manage.py runserver 0.0.0.0:8000
    volumes:
      - .:/usr/src/app
    ports:
      - 8000:8000
    env_file:
      - ./.env
    depends_on:
      - redis

volumes:
  redis_data:

Dockerfile

# pull official base image
FROM python:3.9-slim

# set work directory
WORKDIR /usr/src/app

# set environment variables
ENV PYTHONDONTWRITEBYTECODE 1
ENV PYTHONUNBUFFERED 1

# install dependencies
COPY ./requirements.txt .
RUN pip install -r requirements.txt

# copy project
COPY . /usr/src/app

Side note

As a side note, when I transferred the development from EC2 to my MacBook, the connection to redis cannot be established at all, which was resolved by changing the redis location in Django settings to 'redis://host.docker.internal:6379/1' instead of 'redis://127.0.0.1:6379/1'. But then the timeout issue occurs. The previous error message of Connection refused:

(<WSGIRequest: GET '/v1/TableTest/list/'>,) {'api_ver': '1', 'mod_name': 'TableTest', 'func': 'list', 'json_attr': ''} {}
/usr/local/lib/python3.9/site-packages/django/views/debug.py:487: ExceptionCycleWarning: Cycle in the exception chain detected: exception 'Error 111 connecting to 0.0.0.0:6379. Connection refused.' encountered again.
 warnings.warn(
Internal Server Error: /v1/TableTest/list/
Traceback (most recent call last):
 File "/usr/local/lib/python3.9/site-packages/django_redis/cache.py", line 31, in _decorator
  return method(self, *args, **kwargs)
 File "/usr/local/lib/python3.9/site-packages/django_redis/cache.py", line 98, in _get
  return self.client.get(key, default=default, version=version, client=client)
 File "/usr/local/lib/python3.9/site-packages/django_redis/client/default.py", line 260, in get
  raise ConnectionInterrupted(connection=client) from e
django_redis.exceptions.ConnectionInterrupted: Redis ConnectionError: Error 111 connecting to 0.0.0.0:6379. Connection refused.
alicia-lyu commented 1 year ago

This issue is resolved by modifying redis location from redis://host.docker.internal:6379/1 to redis://redis:6379/1. But I still would like to know why simply using 127.0.0.1 works on EC2.