Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Question] Restarting redisearch sometimes doesn't reload all indexes from disk #4471

Open
Czechh opened this issue Feb 15, 2024 · 10 comments
Open
Assignees

Comments

@Czechh
Copy link

Czechh commented Feb 15, 2024

Describe the bug
I'm running redisearch in a docker container, sometimes it restarts and doesn't load all of the data from disk.

 redis:
    image: redis/redis-stack-server:latest
    ports:
      - "6379:6379"
    environment:
      REDIS_ARGS: "--appendonly yes"

Here's the startup logs:

redis_1               | 9:C 15 Feb 2024 03:34:10.864 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
redis_1               | 9:C 15 Feb 2024 03:34:10.864 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
redis_1               | 9:C 15 Feb 2024 03:34:10.864 * Redis version=7.2.4, bits=64, commit=00000000, modified=0, pid=9, just started
redis_1               | 9:C 15 Feb 2024 03:34:10.864 * Configuration loaded
redis_1               | 9:M 15 Feb 2024 03:34:10.865 * monotonic clock: POSIX clock_gettime
redis_1               | 9:M 15 Feb 2024 03:34:10.865 * Running mode=standalone, port=6379.
redis_1               | 9:M 15 Feb 2024 03:34:10.866 * Module 'RedisCompat' loaded from /opt/redis-stack/lib/rediscompat.so
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * <search> Redis version found by RedisSearch : 7.2.4 - oss
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * <search> RediSearch version 2.8.11 (Git=2.8-7368bb3)
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * <search> Low level api version 1 initialized successfully
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * <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,
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * <search> Initialized thread pools!
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * <search> Enabled role change notification
redis_1               | 9:M 15 Feb 2024 03:34:10.868 * Module 'search' loaded from /opt/redis-stack/lib/redisearch.so
redis_1               | 9:M 15 Feb 2024 03:34:10.870 * <timeseries> RedisTimeSeries version 11011, git_sha=0299ac12a6bf298028859c41ba0f4d8dc842726b
redis_1               | 9:M 15 Feb 2024 03:34:10.870 * <timeseries> Redis version found by RedisTimeSeries : 7.2.4 - oss
redis_1               | 9:M 15 Feb 2024 03:34:10.870 * <timeseries> loaded default CHUNK_SIZE_BYTES policy: 4096
redis_1               | 9:M 15 Feb 2024 03:34:10.870 * <timeseries> loaded server DUPLICATE_POLICY: block
redis_1               | 9:M 15 Feb 2024 03:34:10.870 * <timeseries> Setting default series ENCODING to: compressed
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <timeseries> Detected redis oss
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * Module 'timeseries' loaded from /opt/redis-stack/lib/redistimeseries.so
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Created new data type 'ReJSON-RL'
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> version: 20609 git sha: unknown branch: unknown
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Exported RedisJSON_V1 API
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Exported RedisJSON_V2 API
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Exported RedisJSON_V3 API
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Exported RedisJSON_V4 API
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Exported RedisJSON_V5 API
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <ReJSON> Enabled diskless replication
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * Module 'ReJSON' loaded from /opt/redis-stack/lib/rejson.so
redis_1               | 9:M 15 Feb 2024 03:34:10.871 * <search> Acquired RedisJSON_V5 API
redis_1               | 9:M 15 Feb 2024 03:34:10.872 * <bf> RedisBloom version 2.6.11 (Git=unknown)
redis_1               | 9:M 15 Feb 2024 03:34:10.872 * Module 'bf' loaded from /opt/redis-stack/lib/redisbloom.so
redis_1               | 9:M 15 Feb 2024 03:34:10.872 * <redisgears_2> Created new data type 'GearsType'
redis_1               | 9:M 15 Feb 2024 03:34:10.873 * <redisgears_2> Detected redis oss
redis_1               | 9:M 15 Feb 2024 03:34:10.873 # <redisgears_2> could not initialize RedisAI_InitError
redis_1               |
redis_1               | 9:M 15 Feb 2024 03:34:10.873 * <redisgears_2> Failed loading RedisAI API.
redis_1               | 9:M 15 Feb 2024 03:34:10.873 * <redisgears_2> RedisGears v2.0.16, sha='9559f21d0c3fd6ab4a0edb55d8b89ab125c8cc52', build_type='release', built_for='Linux-ubuntu22.04.x86_64'.
redis_1               | 9:M 15 Feb 2024 03:34:10.874 * <redisgears_2> Registered backend: js.
redis_1               | 9:M 15 Feb 2024 03:34:10.874 * Module 'redisgears_2' loaded from /opt/redis-stack/lib/redisgears.so
redis_1               | 9:M 15 Feb 2024 03:34:10.874 * Server initialized
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * <search> Loading event starts
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * <redisgears_2> Got a loading start event, clear the entire functions data.
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * Reading RDB base file on AOF loading...
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * Loading RDB produced by version 7.2.4
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * RDB age 134122 seconds
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * RDB memory usage when created 978.38 Mb
redis_1               | 9:M 15 Feb 2024 03:34:10.876 * RDB is base AOF
redis_1               | 9:M 15 Feb 2024 03:34:10.876 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16703305824B
redis_1               | 9:M 15 Feb 2024 03:34:10.876 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16703189056B
redis_1               | 9:M 15 Feb 2024 03:34:10.876 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16703074744B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702961328B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702846800B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702733040B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702620456B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702507576B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702394720B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702281992B
redis_1               | 9:M 15 Feb 2024 03:34:10.877 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702169944B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16702057384B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701944800B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701832240B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701717192B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701602736B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701489040B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701373136B
redis_1               | 9:M 15 Feb 2024 03:34:10.878 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701259120B
redis_1               | 9:M 15 Feb 2024 03:34:10.879 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701145680B
redis_1               | 9:M 15 Feb 2024 03:34:10.879 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16701031344B
redis_1               | 9:M 15 Feb 2024 03:34:10.879 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16700917104B
redis_1               | 9:M 15 Feb 2024 03:34:15.078 * Done loading RDB, keys loaded: 58195, keys expired: 0.
redis_1               | 9:M 15 Feb 2024 03:34:15.079 * DB loaded from base file appendonly.aof.13.base.rdb: 4.203 seconds
redis_1               | 9:M 15 Feb 2024 03:34:15.466 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15613798496B
redis_1               | 9:M 15 Feb 2024 03:34:15.470 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15605937336B
redis_1               | 9:M 15 Feb 2024 03:34:15.474 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15598090640B
redis_1               | 9:M 15 Feb 2024 03:34:15.475 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15597923720B
redis_1               | 9:M 15 Feb 2024 03:34:16.493 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15465453536B
redis_1               | 9:M 15 Feb 2024 03:34:16.496 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15457612232B
redis_1               | 9:M 15 Feb 2024 03:34:16.500 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15449410808B
redis_1               | 9:M 15 Feb 2024 03:34:16.503 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15441686552B
redis_1               | 9:M 15 Feb 2024 03:34:16.511 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15434343912B
redis_1               | 9:M 15 Feb 2024 03:34:16.514 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15434041552B
redis_1               | 9:M 15 Feb 2024 03:34:16.516 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15426605872B
redis_1               | 9:M 15 Feb 2024 03:34:16.519 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15418858392B
redis_1               | 9:M 15 Feb 2024 03:34:16.523 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15411546008B
redis_1               | 9:M 15 Feb 2024 03:34:16.533 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15403101584B
redis_1               | 9:M 15 Feb 2024 03:34:16.543 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 15402853200B
redis_1               | 9:M 15 Feb 2024 03:34:16.560 * <redisgears_2> Got a flush started event
redis_1               | 9:M 15 Feb 2024 03:34:16.855 * DB saved on disk
redis_1               | 9:M 15 Feb 2024 03:34:16.914 * <redisgears_2> Got a flush started event
redis_1               | 9:M 15 Feb 2024 03:34:16.921 * DB saved on disk
redis_1               | 9:M 15 Feb 2024 03:34:16.922 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16698794424B
redis_1               | 9:M 15 Feb 2024 03:34:16.924 # <search> creating vector index. Server memory limit: 16704536576B, required memory: 6316424B, available memory: 16697955496B
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * DB loaded from incr file appendonly.aof.13.incr.aof: 1.848 seconds
redis_1               | 9:M 15 Feb 2024 03:34:16.927 # <search> Skip background reindex scan, redis version contains loaded event.
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <search> Loading event ends
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <redisgears_2> Loading finished, re-enable key space notificaitons.
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * DB loaded from append only file: 6.051 seconds
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * Opening AOF incr file appendonly.aof.13.incr.aof on server start
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * Ready to accept connections tcp
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65cb9c67fed252d51de4dc9e in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=62558)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65cb9e6afed252d51de4dd2a in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=62600)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65cba168fed252d51de4ddd4 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=62641)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65cba529fed252d51de4ddf2 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=62640)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65cca9ca218868299a469490 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70505)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccaab0218868299a4694c8 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70547)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccae6d218868299a4694fe in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70588)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccb454218868299a469527 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70614)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccd29f218868299a4695a5 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70644)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccedf5218868299a4695e5 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70610)
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccf89d218868299a469608 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.927 * <module> Scanning indexes in background: cancelled (scanned=70611)
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-65830deff0f82d38de3397e0-session-65ccfa8f218868299a469644 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning indexes in background: cancelled (scanned=70641)
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d in background
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning indexes in background: cancelled (scanned=70642)
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65cd2d5d9c04fe16cf905a5f in background
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning indexes in background: cancelled (scanned=70738)
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65cd305b9c04fe16cf905a61 in background
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning indexes in background: cancelled (scanned=70740)
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd7d283cddae2e6f227cab in background
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd7d283cddae2e6f227cab in background: done (scanned=6)
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd81ce3cddae2e6f227cad in background
redis_1               | 9:M 15 Feb 2024 03:34:16.928 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd81ce3cddae2e6f227cad in background: done (scanned=6)
redis_1               | 9:M 15 Feb 2024 03:39:17.067 * 100 changes in 300 seconds. Saving...

I noticed these:

* <module> Scanning index org-65830deff0f82d38de3397e0-session-65cb9e6afed252d51de4dd2a in background
* <module> Scanning indexes in background: cancelled (scanned=62600)

So for some reason some of these operations are getting cancelled. I believe causing some indexes to not get created.

Expected behavior
All indexes get re-created.

Environment (please complete the following information):

  • OS: ubuntu 20.04
  • CPU model
  • Version/branch module:name=search,ver=20811,api=1,filters=0,usedby=[],using=[ReJSON],options=[handle-io-errors]
@GuyAv46
Copy link
Collaborator

GuyAv46 commented Feb 17, 2024

Cancelling background indexing should only happen if the index was altered with FT.ALTER (and in this case we would've seen Scanning index %s in background: cancelled and restarted), or because the index was dropped before the scan was complete.
Can you confirm this is not the case for you? Loading index from AOF file may yield this log if an index is both created and deleted in the AOF

@Czechh
Copy link
Author

Czechh commented Feb 17, 2024

We don't drop indexes. But it's really imposible to tell if that happened or not.

We went through the whole aof file and didn't find any evidence of drops. But the file is just a segment. Is there another way to ensure that that command didn't happen?

Thank for the response. @GuyAv46

@GuyAv46
Copy link
Collaborator

GuyAv46 commented Feb 18, 2024

No problem :)
What is the source of the AOF file? Do you have a single redis instance? Replication? Cluster?
Can you try restarting the instance with log level verbose or debug? We might get more useful information

@Czechh
Copy link
Author

Czechh commented Feb 18, 2024

It's a single Redis contianer, running with docker-compose inside of a VM. Something like this:

version: "3"
services:
  redis:
    image: redis/redis-stack-server:latest
    ports:
      - "6379:6379"
    environment:
      REDIS_ARGS: "--appendonly yes --loglevel debug"
      LL_VERBOSE: 
    volumes:
      - ./local:/data

Here's the debug logs

8:C 18 Feb 2024 17:00:49.655 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
8:C 18 Feb 2024 17:00:49.660 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
8:C 18 Feb 2024 17:00:49.660 * Redis version=7.2.3, bits=64, commit=00000000, modified=0, pid=8, just started
8:C 18 Feb 2024 17:00:49.660 * Configuration loaded
8:M 18 Feb 2024 17:00:49.667 * monotonic clock: POSIX clock_gettime
8:M 18 Feb 2024 17:00:49.672 * Running mode=standalone, port=6379.
8:M 18 Feb 2024 17:00:49.673 * Module 'RedisCompat' loaded from /opt/redis-stack/lib/rediscompat.so
8:M 18 Feb 2024 17:00:49.682 * <search> Redis version found by RedisSearch : 7.2.3 - oss
8:M 18 Feb 2024 17:00:49.682 * <search> RediSearch version 2.8.9 (Git=HEAD-58db69da)
8:M 18 Feb 2024 17:00:49.683 * <search> Low level api version 1 initialized successfully
8:M 18 Feb 2024 17:00:49.683 * <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,
8:M 18 Feb 2024 17:00:49.683 - <search> Creating background thread--1148656192
8:M 18 Feb 2024 17:00:49.683 - <search> Thread pool of size ��z created successfully
8:M 18 Feb 2024 17:00:49.683 - <search> Creating background thread--1157110336
8:M 18 Feb 2024 17:00:49.683 - <search> Thread pool of size ��z created successfully
8:M 18 Feb 2024 17:00:49.683 * <search> Initialized thread pools!
8:M 18 Feb 2024 17:00:49.683 * <search> Enabled role change notification
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed DictRegister
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed TrieType_Register
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed IndexSpec_RegisterType
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed TagIndex_RegisterType
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed InvertedIndex_RegisterType
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed NumericIndexType_Register
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 * Module 'search' loaded from /opt/redis-stack/lib/redisearch.so
8:M 18 Feb 2024 17:00:49.686 * <timeseries> RedisTimeSeries version 11009, git_sha=6782c54bcb7dddeb6669f24cd5113dad64a4b03d
8:M 18 Feb 2024 17:00:49.686 * <timeseries> Redis version found by RedisTimeSeries : 7.2.3 - oss
8:M 18 Feb 2024 17:00:49.686 * <timeseries> loaded default CHUNK_SIZE_BYTES policy: 4096
8:M 18 Feb 2024 17:00:49.686 * <timeseries> loaded server DUPLICATE_POLICY: block
8:M 18 Feb 2024 17:00:49.686 * <timeseries> Setting default series ENCODING to: compressed
8:M 18 Feb 2024 17:00:49.687 * <timeseries> Detected redis oss
8:M 18 Feb 2024 17:00:49.687 * Module 'timeseries' loaded from /opt/redis-stack/lib/redistimeseries.so
8:M 18 Feb 2024 17:00:49.688 * <ReJSON> Created new data type 'ReJSON-RL'
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> version: 20607 git sha: unknown branch: unknown
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V1 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V2 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V3 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V4 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V5 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Enabled diskless replication
8:M 18 Feb 2024 17:00:49.689 * Module 'ReJSON' loaded from /opt/redis-stack/lib/rejson.so
8:M 18 Feb 2024 17:00:49.689 * <search> Acquired RedisJSON_V4 API
8:M 18 Feb 2024 17:00:49.689 * <bf> RedisBloom version 2.6.8 (Git=unknown)
8:M 18 Feb 2024 17:00:49.689 * Module 'bf' loaded from /opt/redis-stack/lib/redisbloom.so
8:M 18 Feb 2024 17:00:49.692 * <redisgears_2> Created new data type 'GearsType'
8:M 18 Feb 2024 17:00:49.693 * <redisgears_2> Detected redis oss
8:M 18 Feb 2024 17:00:49.693 # <redisgears_2> could not initialize RedisAI_InitError
redis-1  |
8:M 18 Feb 2024 17:00:49.693 * <redisgears_2> Failed loading RedisAI API.
8:M 18 Feb 2024 17:00:49.693 * <redisgears_2> RedisGears v2.0.14, sha='7b124f80636f6b58007a6b7093d65b96a8c2d920', build_type='release', built_for='Linux-ubuntu22.04.arm64v8'.
8:M 18 Feb 2024 17:00:49.699 * <redisgears_2> Registered backend: js.
8:M 18 Feb 2024 17:00:49.699 * Module 'redisgears_2' loaded from /opt/redis-stack/lib/redisgears.so
8:M 18 Feb 2024 17:00:49.699 * Server initialized
8:M 18 Feb 2024 17:00:49.700 * <search> Loading event starts
8:M 18 Feb 2024 17:00:49.700 * <redisgears_2> Got a loading start event, clear the entire functions data.
8:M 18 Feb 2024 17:00:49.711 * Reading RDB base file on AOF loading...
8:M 18 Feb 2024 17:00:49.711 * Loading RDB produced by version 7.2.4
8:M 18 Feb 2024 17:00:49.711 * RDB age 263778 seconds
8:M 18 Feb 2024 17:00:49.711 * RDB memory usage when created 395.68 Mb
8:M 18 Feb 2024 17:00:49.711 * RDB is base AOF
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14648171208B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce28fa108c43f5203907bd
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14648059832B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd81ce3cddae2e6f227cad
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647949872B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce2ba2108c43f5203907bf
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647839992B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-65830deff0f82d38de3397e0-session-65ce2067f52e4257f0c720e2
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647730152B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce2f3d108c43f5203907c1
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647620136B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd7d283cddae2e6f227cab
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647510112B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-65830deff0f82d38de3397e0-index-65ce1d43108c43f5203907b7
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647399992B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-65830deff0f82d38de3397e0-session-65ce25e5f52e4257f0c7214f
8:M 18 Feb 2024 17:00:51.918 * Done loading RDB, keys loaded: 23753, keys expired: 0.
8:M 18 Feb 2024 17:00:51.918 * DB loaded from base file appendonly.aof.14.base.rdb: 2.218 seconds
8:M 18 Feb 2024 17:00:52.098 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242562192B
8:M 18 Feb 2024 17:00:52.098 - <search> Starting GC for index org-65830deff0f82d38de3397e0-index-65ce3659108c43f5203907c3
8:M 18 Feb 2024 17:00:52.098 - <search> Creating background thread--1512163904
8:M 18 Feb 2024 17:00:52.098 - <search> Thread pool of size (�z created successfully
8:M 18 Feb 2024 17:00:52.098 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.099 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.099 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.100 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242524240B
8:M 18 Feb 2024 17:00:52.100 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d
8:M 18 Feb 2024 17:00:52.103 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.104 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.104 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242502856B
8:M 18 Feb 2024 17:00:52.104 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d
8:M 18 Feb 2024 17:00:52.106 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.106 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.106 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242492112B
8:M 18 Feb 2024 17:00:52.106 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca
8:M 18 Feb 2024 17:00:52.107 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14235987704B
8:M 18 Feb 2024 17:00:52.107 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65b2e28dff2b62055f53a514
8:M 18 Feb 2024 17:00:52.139 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.139 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.140 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14235817816B
8:M 18 Feb 2024 17:00:52.140 - <search> Starting GC for index org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12
8:M 18 Feb 2024 17:00:52.237 * DB loaded from incr file appendonly.aof.14.incr.aof: 0.319 seconds
8:M 18 Feb 2024 17:00:52.237 # <search> Skip background reindex scan, redis version contains loaded event.
8:M 18 Feb 2024 17:00:52.237 * <search> Loading event ends
8:M 18 Feb 2024 17:00:52.237 * <redisgears_2> Loading finished, re-enable key space notificaitons.
8:M 18 Feb 2024 17:00:52.237 * DB loaded from append only file: 2.537 seconds
8:M 18 Feb 2024 17:00:52.241 * Opening AOF incr file appendonly.aof.14.incr.aof on server start
8:M 18 Feb 2024 17:00:52.241 * Ready to accept connections tcp
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65ce3659108c43f5203907c3 in background
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning indexes in background: cancelled (scanned=27837)
8:M 18 Feb 2024 17:00:52.241 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.241 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d in background
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning indexes in background: cancelled (scanned=27846)
8:M 18 Feb 2024 17:00:52.241 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.241 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d in background
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning indexes in background: cancelled (scanned=27845)
8:M 18 Feb 2024 17:00:52.241 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.241 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca in background
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca in background: done (scanned=27845)
8:M 18 Feb 2024 17:00:52.295 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.295 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65b2e28dff2b62055f53a514 in background
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning indexes in background: cancelled (scanned=27854)
8:M 18 Feb 2024 17:00:52.295 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.295 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12 in background
8:M 18 Feb 2024 17:00:52.390 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12 in background: done (scanned=27853)
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:54.675 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:00:54.676 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:00:59.771 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:00:59.771 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:04.892 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:04.892 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:10.014 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:10.014 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:15.099 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:15.099 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:20.207 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:20.207 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:24.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:24.717 . <search> All threads are idle
8:M 18 Feb 2024 17:01:25.309 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:25.309 . 0 clients connected (0 replicas), 441804984 bytes in use
8:M 18 Feb 2024 17:01:28.714 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:28.715 . <search> All threads are idle
8:M 18 Feb 2024 17:01:28.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:28.715 . <search> All threads are idle
8:M 18 Feb 2024 17:01:28.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:28.715 . <search> All threads are idle
8:M 18 Feb 2024 17:01:29.141 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:29.179 - Module fork started pid: 17
8:M 18 Feb 2024 17:01:29.195 - Killing running module fork child: 17
8:M 18 Feb 2024 17:01:29.199 . <search> All threads are idle
8:M 18 Feb 2024 17:01:30.406 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:30.406 . 0 clients connected (0 replicas), 441762128 bytes in use
8:M 18 Feb 2024 17:01:30.712 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:30.712 . <search> All threads are idle
8:M 18 Feb 2024 17:01:32.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:32.714 . <search> All threads are idle
8:M 18 Feb 2024 17:01:33.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:33.714 . <search> All threads are idle
8:M 18 Feb 2024 17:01:34.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:34.713 . <search> All threads are idle
8:M 18 Feb 2024 17:01:35.506 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:35.506 . 0 clients connected (0 replicas), 441762120 bytes in use
8:M 18 Feb 2024 17:01:40.604 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:40.604 . 0 clients connected (0 replicas), 441762120 bytes in use
8:M 18 Feb 2024 17:01:42.714 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:42.714 . <search> All threads are idle
8:M 18 Feb 2024 17:01:45.712 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:45.712 . 0 clients connected (0 replicas), 441762080 bytes in use
8:M 18 Feb 2024 17:01:47.108 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:47.108 . <search> All threads are idle
8:M 18 Feb 2024 17:01:50.008 * 10000 changes in 60 seconds. Saving...
8:M 18 Feb 2024 17:01:50.076 * Background saving started by pid 18
18:C 18 Feb 2024 17:01:50.084 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
8:M 18 Feb 2024 17:01:50.878 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:50.878 . 0 clients connected (0 replicas), 441762104 bytes in use
18:C 18 Feb 2024 17:01:51.109 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:52.272 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:53.405 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:54.515 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:55.666 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
8:M 18 Feb 2024 17:01:55.904 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:55.904 . 0 clients connected (0 replicas), 441762104 bytes in use
18:C 18 Feb 2024 17:01:56.429 * DB saved on disk
18:C 18 Feb 2024 17:01:56.433 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
8:M 18 Feb 2024 17:01:56.509 * Background saving terminated with success
8:M 18 Feb 2024 17:02:00.716 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:00.716 . <search> All threads are idle
8:M 18 Feb 2024 17:02:00.981 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:00.981 . 0 clients connected (0 replicas), 441762104 bytes in use
8:M 18 Feb 2024 17:02:03.203 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:03.203 . <search> All threads are idle
8:M 18 Feb 2024 17:02:06.094 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:06.094 . 0 clients connected (0 replicas), 441762120 bytes in use
8:M 18 Feb 2024 17:02:07.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:07.716 . <search> All threads are idle
8:M 18 Feb 2024 17:02:08.718 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:08.719 . <search> All threads are idle
8:M 18 Feb 2024 17:02:09.718 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:09.718 . <search> All threads are idle
8:M 18 Feb 2024 17:02:10.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:10.720 . <search> All threads are idle
8:M 18 Feb 2024 17:02:11.203 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:11.203 . 0 clients connected (0 replicas), 441762208 bytes in use
8:M 18 Feb 2024 17:02:11.712 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:11.712 . <search> All threads are idle
8:M 18 Feb 2024 17:02:16.277 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:16.277 . 0 clients connected (0 replicas), 441762184 bytes in use
8:M 18 Feb 2024 17:02:21.369 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:21.369 . 0 clients connected (0 replicas), 441762184 bytes in use
8:M 18 Feb 2024 17:02:22.717 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:22.717 . <search> All threads are idle
8:M 18 Feb 2024 17:02:26.463 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:26.463 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:31.561 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:31.561 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:34.111 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:34.111 . <search> All threads are idle
8:M 18 Feb 2024 17:02:36.657 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:36.657 . 0 clients connected (0 replicas), 441762168 bytes in use
8:M 18 Feb 2024 17:02:40.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:40.715 . <search> All threads are idle
8:M 18 Feb 2024 17:02:41.739 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:41.739 . 0 clients connected (0 replicas), 441762152 bytes in use
8:M 18 Feb 2024 17:02:42.718 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:42.718 . <search> All threads are idle
8:M 18 Feb 2024 17:02:43.724 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:43.724 . <search> All threads are idle
8:M 18 Feb 2024 17:02:46.845 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:46.845 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:51.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:51.713 . <search> All threads are idle
8:M 18 Feb 2024 17:02:51.938 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:51.938 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:57.023 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:57.023 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:57.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:57.720 . <search> All threads are idle
8:M 18 Feb 2024 17:02:57.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:57.720 . <search> All threads are idle
8:M 18 Feb 2024 17:02:57.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:57.720 . <search> All threads are idle
8:M 18 Feb 2024 17:03:00.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:03:00.720 . <search> All threads are idle
8:M 18 Feb 2024 17:03:01.204 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:03:01.204 . <search> All threads are idle
8:M 18 Feb 2024 17:03:02.115 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:03:02.115 . 0 clients connected (0 replicas), 441762200 bytes in use```

Thank you!

@GuyAv46
Copy link
Collaborator

GuyAv46 commented Feb 18, 2024

Thank you for your cooperation!
I’ll dig deeper into it tomorrow. My suspect is that it is related to the AOF process that I’ll admit I don’t know much about yet.
What I was able to get this far:

  1. None of the indexes "declared" between Loading RDB produced by version 7.2.4 and Done loading RDB, keys loaded: 23753, keys expired: 0. gets their scan canceled.
  2. All the indexes that get their scan canceled get the cancelation immediately, as can be seen by the timestamp. The (scanned=27854) is a lie (a bug that is already fixed, the number is the number of keys in the database and not the number of scanned keys).
  3. org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d gets its GC started twice and its BG scan is canceled twice. There is an assertion if a GC is attempted to start twice, so the index was very likely dropped and recreated at least once.
  4. The number of indexes created after the Done loading RDB, keys loaded: mark matches the number of scans. This makes sense as when loading from RDB, there is no BG indexing at all, so only creations from the AOF section could cause a BG scan (the indexes that are created in the first section get loaded directly)

After I'll dig a bit deeper on the AOF section, I can confirm there is no real problem, and that the scans were canceled because the index was actually dropped in the AOF file.

Can you add the output of FT._LIST so we can see if any of the indexes that get their scan canceled still exist after the load is complete?

@Czechh
Copy link
Author

Czechh commented Feb 18, 2024

Thank you here's the ft._list

127.0.0.1:6379> ft._list
 1) org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca
 2) org-657cb19bb523e5ca31f9c1ce-index-65ce28fa108c43f5203907bd
 3) org-657cb19bb523e5ca31f9c1ce-index-65cd81ce3cddae2e6f227cad
 4) org-65830deff0f82d38de3397e0-session-65ce2067f52e4257f0c720e2
 5) org-657cb19bb523e5ca31f9c1ce-index-65ce2ba2108c43f5203907bf
 6) org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12
 7) org-657cb19bb523e5ca31f9c1ce-index-65ce2f3d108c43f5203907c1
 8) org-657cb19bb523e5ca31f9c1ce-index-65cd7d283cddae2e6f227cab
 9) org-65830deff0f82d38de3397e0-index-65ce1d43108c43f5203907b7
10) org-65830deff0f82d38de3397e0-session-65ce25e5f52e4257f0c7214f

Is there a way to reconstruct the who AOF file? given that's its partial? Got these files:

.
├── appendonlydir
│   ├── appendonly.aof.14.base.rdb
│   ├── appendonly.aof.14.incr.aof
│   └── appendonly.aof.manifest
└── dump.rdb

@GuyAv46
Copy link
Collaborator

GuyAv46 commented Feb 19, 2024

So basically the AOF mechanism includes a manifest file, a base RDB, and an incremental file/s. Depending on your setup, every once in a while a forked process "applies" the changes in the incr file into the base RDB.
The loading process of an AOF starts by reading the manifest to find the base RDB and the AOF file/s, then we first load the base RDB file and then apply the commands from the AOF file/s in order.

When loading an index from an RDB, there is no BG indexing and when the loading is done the index is ready. The AOF file contains more commands to apply, and it may create or delete indexes and thus may trigger a background scan. Since the entire loading event happens while holding the redis GIL, the BG index tasks cannot start until the entire loading process is done.

When it's done (at the Ready to accept connections log message), the BG index tasks can take the GIL and perform the indexing, but if the index was both created and dropped in the AOF file, the BG indexer recognizes the index is no longer exists, it cancels the tasks and returns.

The RDB file is binary, but the AOF incremental files are mostly text and you can verify that the indexes that got their BG scan canceled are both created and dropped in it.

TL;DR: Not a bug. expected and correct behavior.

You can read more about AOF and persistence here.
Let me know if there is anything else I can help with

@GuyAv46 GuyAv46 added question and removed bug labels Feb 19, 2024
@GuyAv46 GuyAv46 changed the title [BUG] Restarting redisearch sometimes doesn't reload all indexes from disk [Question] Restarting redisearch sometimes doesn't reload all indexes from disk Feb 19, 2024
@Czechh
Copy link
Author

Czechh commented Feb 19, 2024

Thanks for the explanation! That makes 100% sense.

What I'm trying to understand then is why these indexes try to get loaded and get cancelled, given that the AOF (latest segment) file doesn't have any FT.DROPINDEX command in them. I would've assumed that the RDB file is consolidated, meaning it wouldn't trigger an index creation process as a previous DROPINDEX command was incrementally added to that state file.

I just want to make 100% sure that command actually happen to ensure that my setup isn't somehow dropping data in some other way. Please let me know if my assumptions are incorrect, and again thanks for your help.

@GuyAv46
Copy link
Collaborator

GuyAv46 commented Feb 20, 2024

Yes, if an index was dropped and the change was applied to the RDB file, it won't be created when loaded. We can also see in the log what indexes were created from the RDB (before Done loading RDB, keys loaded: 23753, keys expired: 0.) and what from the AOF
It's strange that there is no DROP command in the AOF. Do you see the creation of the canceled indexes there? Maybe another command of the DROP family? (FT.DROP, FT._DROPIFX...)

Copy link

This issue is stale because it has been open for 60 days with no activity.

@github-actions github-actions bot added the stale label Apr 21, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants