RediSearch fails to acquire Global Lock.

[JohnSully]

This time it crashed when I call FT.EXPLAIN command of redisearch in v.0.9.6. But it didn't crash at startup like before.

=== KEYDB BUG REPORT START: Cut & paste starting from here ===
7:S 26 Jul 2019 08:57:21.318 # === ASSERTION FAILED ===
7:S 26 Jul 2019 08:57:21.318 # ==> multi.cpp:296 'GlobalLocksAcquired()' is not true
7:S 26 Jul 2019 08:57:21.318 # (forcing SIGSEGV to print the bug report.)
7:S 26 Jul 2019 08:57:21.318 # KeyDB 0.9.6 crashed by signal: 11
7:S 26 Jul 2019 08:57:21.318 # Crashed running the instruction at: 0x55aced61926e
7:S 26 Jul 2019 08:57:21.318 # Accessing address: 0xffffffffffffffff
7:S 26 Jul 2019 08:57:21.318 # Failed assertion: GlobalLocksAcquired() (multi.cpp:296)
 ------ STACK TRACE ------
EIP:
keydb-server *:6379(_serverAssert+0x7e) [0x55aced61926e]
 Backtrace:
keydb-server *:6379(logStackTrace(ucontext_t*)+0x6b) [0x55aced61c25b]
keydb-server *:6379(sigsegvHandler(int, siginfo_t*, void*)+0xbf) [0x55aced61c9ef]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890) [0x7fc625d61890]
keydb-server *:6379(_serverAssert+0x7e) [0x55aced61926e]
keydb-server *:6379(touchWatchedKey(redisDb*, redisObject*)+0x71) [0x55aced618cf1]
keydb-server *:6379(RM_CloseKey(RedisModuleKey*)+0x75) [0x55aced64b125]
keydb-server *:6379(+0xc7646) [0x55aced64c646]
keydb-server *:6379(moduleFreeContext(RedisModuleCtx*)+0x9b) [0x55aced64c76b]
keydb-server *:6379(RM_FreeThreadSafeContext(RedisModuleCtx*)+0x9) [0x55aced64c809]
/data/redisearch.so(+0x42140) [0x7fc622b05140]
/data/redisearch.so(+0xadabe) [0x7fc622b70abe]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7fc625d566db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fc625a7f88f]
 ------ INFO OUTPUT ------
7:S 26 Jul 2019 08:57:21.318 # === ASSERTION FAILED ===
7:S 26 Jul 2019 08:57:21.318 # ==> object.cpp:961 'GlobalLocksAcquired()' is not true
7:S 26 Jul 2019 08:57:21.318 # (forcing SIGSEGV to print the bug report.)
bash: line 1:     7 Segmentation fault      (core dumped) keydb-server /conf/redis.conf --loadmodule /data/redisearch.so TIMEOUT 0 ON_TIMEOUT fail 2> >(tee -a /data/redis.log >&2)

Originally posted by @oruchreis in #68 (comment)

[JohnSully]

Upon further investigation this may be a bug in RediSearch itself. The module is supposed to call RM_ThreadSafeContextLock to lock before attempting to call functions such as RM_FreeThreadSafeContext. In Redis this bug is silent because they do not have the extensive lock validation asserts that KeyDB has. KeyDB will crash instead of silently corrupting data as would happen in Redis under this scenario.

I will attempt to repro this locally and coordinate a fix with RediSearch.

[JohnSully]

@oruchreis I've communicated the issue with RediSearch and they opened issue #806 on their github.

In the meantime I've also implemented a workaround with change 6016dd0. I want to give it more bake time so I will not port this to v5.0.0 and instead include it in v5.0.1.

[MeirShpilraien]

@JohnSully Can you specify the redisearch version on which it happened?

[JohnSully]

Not sure, it was @oruchreis that experienced the bug. But I can verify the bug appears in the latest code available on your github. rmutilTimer_Loop must acquire the lock before calling RedisModule_FreeThreadSafeContext. I modified KeyDB to acquire this lock for you (inside FreeThreadSafeContext), but you will still experience corruption in Redis where there isn't a mitigation.

[MeirShpilraien]

When you say latest you mean master? And when you say the bug exists you mean you see it in the code or it actually happened to someone on current master?
Acquiring the lock after releasing is not a good solution, opened keys might have deleted during the time the lock was not taken and now we will try to access a freed memory. The right solution is to remove the auto-memory and make sure everything was free before releasing the lock. But when I checked it I saw that there is actually nothing left to free at the auto-memory free stage. So I do not understand how could it crash?
The only two ways it might happened is that there is an edge case in which we forgot to free something or its not on master. For the second case I would like to know on which version you saw the crash so I will be able to check this specific version.

[oruchreis]

I've tried 5.0.1 with redisearch 1.4.14, but no luck:

7:C 28 Aug 2019 10:58:17.735 # oO0OoO0OoO0Oo KeyDB is starting oO0OoO0OoO0Oo
7:C 28 Aug 2019 10:58:17.742 # KeyDB version=5.0.1, bits=64, commit=bf905a78, modified=0, pid=7, just started
7:C 28 Aug 2019 10:58:17.749 # Configuration loaded
7:M 28 Aug 2019 10:58:17.761 * Running mode=standalone, port=6379.
7:M 28 Aug 2019 10:58:17.776 # Server initialized
7:M 28 Aug 2019 10:58:17.812 * <ft> RediSearch version 1.4.14 (Git=v1.4.14)
7:M 28 Aug 2019 10:58:17.822 * <ft> concurrency: ON, gc: ON, prefix min length: 2, prefix max expansions: 1000, query timeout (ms): 0, timeout policy: fail, cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 3000000, search pool size: 20, index pool size: 8, 
7:M 28 Aug 2019 10:58:17.836 * <ft> Initialized thread pool!
7:M 28 Aug 2019 10:58:17.844 * Module 'ft' loaded from /data/redisearch.so
7:M 28 Aug 2019 10:58:17.857 * Loading RDB produced by version 5.0.1
7:M 28 Aug 2019 10:58:17.867 * RDB age 13 seconds
7:M 28 Aug 2019 10:58:17.879 * RDB memory usage when created 10.06 Mb
7:M 28 Aug 2019 10:58:17.887 * DB loaded from disk: 0.035 seconds
7:M 28 Aug 2019 10:58:17.912 * Ready to accept connections
7:M 28 Aug 2019 10:58:17.925   Thread 1 alive.
7:M 28 Aug 2019 10:58:17.930   Thread 0 alive.
7:M 28 Aug 2019 10:58:17.937   Thread 2 alive.
7:M 28 Aug 2019 10:58:17.948   Thread 3 alive.
7:M 28 Aug 2019 10:58:52.975 * Replica 10.116.0.18:6379 asks for synchronization
7:M 28 Aug 2019 10:58:53.007 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for 'e48103663f77084000fa142bb2bb99d799eff285', my replication IDs are '6f333d8ac5179329eb539448bdf7eeb7aa7931c8' and '0000000000000000000000000000000000000000')
7:M 28 Aug 2019 10:58:53.046 * Starting BGSAVE for SYNC with target: disk
7:M 28 Aug 2019 10:58:53.099 * Background saving started by pid 130
130:C 28 Aug 2019 10:58:53.419 * DB saved on disk
130:C 28 Aug 2019 10:58:53.434 * RDB: 0 MB of memory used by copy-on-write
7:M 28 Aug 2019 10:58:53.523 * Background saving terminated with success
7:M 28 Aug 2019 10:58:53.533 * Synchronization with replica 10.116.0.18:6379 succeeded
7:M 28 Aug 2019 10:59:18.947 * Replica 10.112.0.1:6379 asks for synchronization
7:M 28 Aug 2019 10:59:18.960 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for 'af07cfd2cd8039798f00b5618360faf8b3eb90f5', my replication IDs are 'a3518b718f2c38d66f06cd2b5216beaad0f6d0e4' and '0000000000000000000000000000000000000000')
7:M 28 Aug 2019 10:59:19.007 * Starting BGSAVE for SYNC with target: disk
7:M 28 Aug 2019 10:59:19.022 * Background saving started by pid 199
199:C 28 Aug 2019 10:59:19.505 * DB saved on disk
199:C 28 Aug 2019 10:59:19.525 * RDB: 0 MB of memory used by copy-on-write
7:M 28 Aug 2019 10:59:19.552 * Background saving terminated with success
7:M 28 Aug 2019 10:59:19.579 * Synchronization with replica 10.112.0.1:6379 succeeded


=== KEYDB BUG REPORT START: Cut & paste starting from here ===
7:M 28 Aug 2019 11:02:42.061 # === ASSERTION FAILED ===
7:M 28 Aug 2019 11:02:42.076 # ==> pubsub.cpp:250 'GlobalLocksAcquired()' is not true
7:M 28 Aug 2019 11:02:42.100 # (forcing SIGSEGV to print the bug report.)
7:M 28 Aug 2019 11:02:42.111 # KeyDB 5.0.1 crashed by signal: 11
7:M 28 Aug 2019 11:02:42.120 # Crashed running the instruction at: 0x559cf3124b4e
7:M 28 Aug 2019 11:02:42.132 # Accessing address: 0xffffffffffffffff
7:M 28 Aug 2019 11:02:42.141 # Failed assertion: GlobalLocksAcquired() (pubsub.cpp:250)

------ STACK TRACE ------
EIP:
keydb-server *:6379(_serverAssert+0x7e) [0x559cf3124b4e]

Backtrace:
keydb-server *:6379(logStackTrace(ucontext_t*)+0x6b) [0x559cf3127b3b]
keydb-server *:6379(sigsegvHandler(int, siginfo_t*, void*)+0xc6) [0x559cf31282d6]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890) [0x7ffbfc94c890]
keydb-server *:6379(_serverAssert+0x7e) [0x559cf3124b4e]
keydb-server *:6379(pubsubUnsubscribeAllChannels(client*, int)+0xa2) [0x559cf31232b2]
keydb-server *:6379(freeClient(client*)+0x1c6) [0x559cf30e6df6]
keydb-server *:6379(RM_FreeThreadSafeContext(RedisModuleCtx*)+0x9) [0x559cf3158239]
/data/redisearch.so(+0xb350a) [0x7ffbf997350a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7ffbfc9416db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7ffbfc66a88f]

------ INFO OUTPUT ------
# Server
redis_version:5.0.1
redis_git_sha1:bf905a78
redis_git_dirty:0
redis_build_id:804a3e6fd29ae74a
redis_mode:standalone
os:Linux 5.0.0-25-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.4.0
process_id:7
run_id:7f30638473243e58a5969bc15198e04fdb29e5b5
tcp_port:6379
uptime_in_seconds:265
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:6709074
executable:/data/keydb-server
config_file:/conf/redis.conf

# Clients
connected_clients:21
client_recent_max_input_buffer:2
client_recent_max_output_buffer:0
blocked_clients:0
thread_0_clients:5
thread_1_clients:6
thread_2_clients:8
thread_3_clients:4

# Memory
used_memory:10775744
used_memory_human:10.28M
used_memory_rss:13783040
used_memory_rss_human:13.14M
used_memory_peak:11187240
used_memory_peak_human:10.67M
used_memory_peak_perc:96.32%
used_memory_overhead:10589658
used_memory_startup:9051256
used_memory_dataset:186086
used_memory_dataset_perc:10.79%
allocator_allocated:12566448
allocator_active:13975552
allocator_resident:17170432
total_system_memory:7257391104
total_system_memory_human:6.76G
used_memory_lua:37888
used_memory_lua_human:37.00K
used_memory_scripts:0
used_memory_scripts_human:0B
number_of_cached_scripts:0
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.11
allocator_frag_bytes:1409104
allocator_rss_ratio:1.23
allocator_rss_bytes:3194880
rss_overhead_ratio:0.80
rss_overhead_bytes:-3387392
mem_fragmentation_ratio:1.28
mem_fragmentation_bytes:3008320
mem_not_counted_for_evict:0
mem_replication_backlog:1048576
mem_clients_slaves:34020
mem_clients_normal:455526
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

# Persistence
loading:0
rdb_changes_since_last_save:19
rdb_bgsave_in_progress:0
rdb_last_save_time:1566989959
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:1032192
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_last_write_status:ok
aof_last_cow_size:0

# Stats
total_connections_received:161
total_commands_processed:2100
instantaneous_ops_per_sec:29
total_net_input_bytes:97543
total_net_output_bytes:615396
instantaneous_input_kbps:2.34
instantaneous_output_kbps:7.13
rejected_connections:0
sync_full:2
sync_partial_ok:0
sync_partial_err:2
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
evicted_keys:0
keyspace_hits:0
keyspace_misses:1
pubsub_channels:9
pubsub_patterns:0
latest_fork_usec:1512
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0

# Replication
role:master
connected_slaves:2
slave0:ip=10.116.0.18,port=6379,state=online,offset=47827,lag=1
slave1:ip=10.112.0.1,port=6379,state=online,offset=48685,lag=1
master_replid:a3518b718f2c38d66f06cd2b5216beaad0f6d0e4
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:50942
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:1
repl_backlog_histlen:50942

# CPU
used_cpu_sys:1.266314
used_cpu_user:1.617837
used_cpu_sys_children:0.005535
used_cpu_user_children:0.003870
server_threads:4
long_lock_waits:76

# Commandstats
cmdstat_FT.INFO:calls=1,usec=27,usec_per_call=27.00
cmdstat_cluster:calls=14,usec=15,usec_per_call=1.07
cmdstat_select:calls=14,usec=14,usec_per_call=1.00
cmdstat_client:calls=53,usec=226,usec_per_call=4.26
cmdstat_FT.ALTER:calls=12,usec=220,usec_per_call=18.33
cmdstat_echo:calls=28,usec=34,usec_per_call=1.21
cmdstat_info:calls=148,usec=19527,usec_per_call=131.94
cmdstat_unsubscribe:calls=7,usec=55,usec_per_call=7.86
cmdstat_ping:calls=918,usec=1406,usec_per_call=1.53
cmdstat_FT.CREATE:calls=1,usec=1366,usec_per_call=1366.00
cmdstat_replconf:calls=434,usec=1007,usec_per_call=2.32
cmdstat_hset:calls=4,usec=25,usec_per_call=6.25
cmdstat_hmset:calls=1,usec=22,usec_per_call=22.00
cmdstat_psync:calls=2,usec=245205,usec_per_call=122602.50
cmdstat_set:calls=1,usec=6,usec_per_call=6.00
cmdstat_publish:calls=379,usec=8964,usec_per_call=23.65
cmdstat_subscribe:calls=40,usec=192,usec_per_call=4.80
cmdstat_pubsub:calls=1,usec=16,usec_per_call=16.00
cmdstat_config:calls=42,usec=943,usec_per_call=22.45

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=4,expires=1,avg_ttl=599847

------ CLIENT LIST OUTPUT ------
id=488 addr=10.10.1.2:28221 fd=98 name=oruchreis age=15 idle=15 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping
id=100 addr=10.116.0.17:60802 fd=110 name=sentinel-5b4696d3-pubsub age=205 idle=1 flags=P db=0 sub=1 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=45 addr=10.116.0.18:32814 fd=111 name= age=230 idle=1 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=replconf
id=97 addr=10.112.0.0:50164 fd=108 name=sentinel-1232d13a-cmd age=205 idle=1 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=publish
id=98 addr=10.112.0.0:50166 fd=107 name=sentinel-1232d13a-pubsub age=205 idle=1 flags=P db=0 sub=1 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=104 addr=10.112.0.1:45540 fd=113 name= age=204 idle=1 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=replconf
id=72 addr=10.114.0.16:58656 fd=112 name=redis-commander age=216 idle=1 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=info
id=95 addr=10.114.0.17:47196 fd=105 name=sentinel-ddcb09b6-pubsub age=205 idle=1 flags=P db=0 sub=1 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=96 addr=10.114.0.17:47194 fd=106 name=sentinel-ddcb09b6-cmd age=205 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=ping
id=99 addr=10.116.0.17:60800 fd=109 name=sentinel-5b4696d3-cmd age=205 idle=1 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping
id=481 addr=10.10.1.2:28203 fd=91 name=oruchreis age=15 idle=15 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping
id=482 addr=10.10.1.2:28204 fd=92 name=oruchreis age=15 idle=15 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=483 addr=10.10.1.2:28209 fd=93 name=oruchreis age=15 idle=15 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=489 addr=10.10.1.2:28231 fd=99 name=oruchreis age=15 idle=1 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=490 addr=10.10.1.2:28227 fd=100 name=oruchreis age=15 idle=15 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping
id=491 addr=10.10.1.2:28228 fd=101 name=oruchreis age=15 idle=1 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=hset
id=492 addr=10.10.1.2:28230 fd=102 name=oruchreis age=15 idle=15 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=493 addr=10.10.1.2:28232 fd=103 name=oruchreis age=15 idle=15 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=494 addr=10.10.1.2:28229 fd=104 name=oruchreis age=15 idle=15 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=info
id=484 addr=10.10.1.2:28207 fd=94 name=oruchreis age=15 idle=15 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=info
id=485 addr=10.10.1.2:28216 fd=95 name=oruchreis age=15 idle=15 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe
id=486 addr=10.10.1.2:28215 fd=96 name=oruchreis age=15 idle=15 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=info
id=487 addr=10.10.1.2:28222 fd=97 name=oruchreis age=15 idle=15 flags=P db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=subscribe

------ REGISTERS ------
7:M 28 Aug 2019 11:02:42.256 # 
RAX:0000000000000000 RBX:00000000000000fa
RCX:0000000000000001 RDX:00007ffbd80008d0
RDI:0000000000000000 RSI:00007ffbd80009d8
RBP:0000559cf32180af RSP:00007ffbea7fd530
R8 :00007ffbea7ff700 R9 :00007ffbea7ff700
R10:00000000ffffffd6 R11:0000000000000206
R12:0000559cf320a2da R13:0000000000000000
R14:00007ffbea7fd5e0 R15:00007ffbea7fd5d0
RIP:0000559cf3124b4e EFL:0000000000010206
CSGSFS:002b000000000033
7:M 28 Aug 2019 11:02:42.263 # (00007ffbea7fd53f) -> 00007ffbe4001690
7:M 28 Aug 2019 11:02:42.273 # (00007ffbea7fd53e) -> 00007ffbe9a00000
7:M 28 Aug 2019 11:02:42.281 # (00007ffbea7fd53d) -> 0a3c832db6d8a500
7:M 28 Aug 2019 11:02:42.290 # (00007ffbea7fd53c) -> 00007ffbe9a00000
7:M 28 Aug 2019 11:02:42.305 # (00007ffbea7fd53b) -> 00007ffbe4001601
7:M 28 Aug 2019 11:02:42.315 # (00007ffbea7fd53a) -> 00007ffbe9a0bb9c
7:M 28 Aug 2019 11:02:42.327 # (00007ffbea7fd539) -> 0000559cf30e6df6
7:M 28 Aug 2019 11:02:42.348 # (00007ffbea7fd538) -> 00007ffbe9a00000
7:M 28 Aug 2019 11:02:42.361 # (00007ffbea7fd537) -> 00007ffbe40016b8
7:M 28 Aug 2019 11:02:42.381 # (00007ffbea7fd536) -> 00007ffbe9a0bb9c
7:M 28 Aug 2019 11:02:42.415 # (00007ffbea7fd535) -> 00007ffbe9a07940
7:M 28 Aug 2019 11:02:42.443 # (00007ffbea7fd534) -> 00007ffbe9a0bb9c
7:M 28 Aug 2019 11:02:42.466 # (00007ffbea7fd533) -> 0000559cf31232b2
7:M 28 Aug 2019 11:02:42.528 # (00007ffbea7fd532) -> 00007ffbe9a07940
7:M 28 Aug 2019 11:02:42.581 # (00007ffbea7fd531) -> 00007ffbe9a0bb9c
7:M 28 Aug 2019 11:02:42.607 # (00007ffbea7fd530) -> 00007ffbe9a07940

------ FAST MEMORY TEST ------
7:M 28 Aug 2019 11:02:42.667 # Bio thread for job type #0 terminated
7:M 28 Aug 2019 11:02:42.695 # Bio thread for job type #1 terminated
7:M 28 Aug 2019 11:02:42.736 # Bio thread for job type #2 terminated
*** Preparing to test memory region 559cf346a000 (2256896 bytes)
*** Preparing to test memory region 559cf3bef000 (270336 bytes)
*** Preparing to test memory region 7ffbd4000000 (135168 bytes)
*** Preparing to test memory region 7ffbd8000000 (135168 bytes)
*** Preparing to test memory region 7ffbdc000000 (135168 bytes)
*** Preparing to test memory region 7ffbe0000000 (135168 bytes)
*** Preparing to test memory region 7ffbe4000000 (135168 bytes)
*** Preparing to test memory region 7ffbe9a00000 (4194304 bytes)
*** Preparing to test memory region 7ffbea000000 (8388608 bytes)
*** Preparing to test memory region 7ffbea800000 (16777216 bytes)
*** Preparing to test memory region 7ffbeb8a5000 (8388608 bytes)
*** Preparing to test memory region 7ffbec0a6000 (8388608 bytes)
*** Preparing to test memory region 7ffbec8a7000 (8388608 bytes)
*** Preparing to test memory region 7ffbed0a8000 (8388608 bytes)
*** Preparing to test memory region 7ffbed8a9000 (8388608 bytes)
*** Preparing to test memory region 7ffbee0aa000 (8388608 bytes)
*** Preparing to test memory region 7ffbee8ab000 (8388608 bytes)
*** Preparing to test memory region 7ffbef0ac000 (8388608 bytes)
*** Preparing to test memory region 7ffbef8ad000 (8388608 bytes)
*** Preparing to test memory region 7ffbf00ae000 (8388608 bytes)
*** Preparing to test memory region 7ffbf08af000 (8388608 bytes)
*** Preparing to test memory region 7ffbf10b0000 (8388608 bytes)
*** Preparing to test memory region 7ffbf18b1000 (8388608 bytes)
*** Preparing to test memory region 7ffbf20b2000 (8388608 bytes)
*** Preparing to test memory region 7ffbf28b3000 (8388608 bytes)
*** Preparing to test memory region 7ffbf30b4000 (8388608 bytes)
*** Preparing to test memory region 7ffbf38b5000 (8388608 bytes)
*** Preparing to test memory region 7ffbf40b6000 (8388608 bytes)
*** Preparing to test memory region 7ffbf48b7000 (8388608 bytes)
*** Preparing to test memory region 7ffbf50b8000 (8388608 bytes)
*** Preparing to test memory region 7ffbf58b9000 (8388608 bytes)
*** Preparing to test memory region 7ffbf60ba000 (8388608 bytes)
*** Preparing to test memory region 7ffbf68bb000 (8388608 bytes)
*** Preparing to test memory region 7ffbf70bc000 (8388608 bytes)
*** Preparing to test memory region 7ffbf78bd000 (8388608 bytes)
*** Preparing to test memory region 7ffbf80be000 (8388608 bytes)
*** Preparing to test memory region 7ffbf88bf000 (8388608 bytes)
*** Preparing to test memory region 7ffbf90c0000 (8388608 bytes)
*** Preparing to test memory region 7ffbf9af9000 (16384 bytes)
*** Preparing to test memory region 7ffbf9afe000 (8388608 bytes)
*** Preparing to test memory region 7ffbfa2ff000 (8388608 bytes)
*** Preparing to test memory region 7ffbfab00000 (8388608 bytes)
*** Preparing to test memory region 7ffbfb300000 (17825792 bytes)
*** Preparing to test memory region 7ffbfc936000 (16384 bytes)
*** Preparing to test memory region 7ffbfcb55000 (16384 bytes)
*** Preparing to test memory region 7ffbfd494000 (16384 bytes)
*** Preparing to test memory region 7ffbfdcc3000 (49152 bytes)
*** Preparing to test memory region 7ffbfdcd4000 (4096 bytes)

[JohnSully]

This fix did not make it into 5.0.1 because it was overlooked. 5.0.1 was an emergency release for the PUB/SUB crashes.

My original plan was to have this go out in the next merge of unstable into RELEASE_5 however I don’t see why this fix shouldn’t go in early as well.

I will update this when I’ve backported the fix.

[JohnSully]

@oruchreis This has now been backported to v5.0.1 and the git label+docker have been updated. Sorry I forgot it.

[miroslavp]

I still have this error with KeyDB 5.3.0 and latest Redisearch module

89:M 14 Feb 2020 21:41:57.245 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
89:M 14 Feb 2020 21:41:57.245 # Server initialized
89:M 14 Feb 2020 21:41:57.245 # WARNING overcommit_memory is set to 0! Background save 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.
89:M 14 Feb 2020 21:41:57.245 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with KeyDB. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. KeyDB must be restarted after THP is disabled.
89:M 14 Feb 2020 21:41:57.247 * <ft> RediSearch version 99.99.99 (Git=v1.6.6-25-g2dd3223e)
89:M 14 Feb 2020 21:41:57.247 * <ft> Low level api version 1 initialized successfully
89:M 14 Feb 2020 21:41:57.247 * <ft> concurrency: ON, 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, search pool size: 20, index pool size: 8,
89:M 14 Feb 2020 21:41:57.248 * <ft> Initialized thread pool!
89:M 14 Feb 2020 21:41:57.248 * Module 'ft' loaded from /home/miroslav/RediSearch/build/redisearch.so
89:M 14 Feb 2020 21:41:57.248 * Loading RDB produced by version 5.3.0
89:M 14 Feb 2020 21:41:57.248 * RDB age 10 seconds
89:M 14 Feb 2020 21:41:57.248 * RDB memory usage when created 8.88 Mb
89:M 14 Feb 2020 21:41:57.249 * DB loaded from disk: 0.000 seconds
89:M 14 Feb 2020 21:41:57.249 * Ready to accept connections
89:M 14 Feb 2020 21:41:57.249   Thread 0 alive.

=== KEYDB BUG REPORT START: Cut & paste starting from here ===
129:C 14 Feb 2020 21:42:07.251 # === ASSERTION FAILED ===
129:C 14 Feb 2020 21:42:07.251 # ==> multi.cpp:296 'GlobalLocksAcquired()' is not true
129:C 14 Feb 2020 21:42:07.251 # (forcing SIGSEGV to print the bug report.)
129:C 14 Feb 2020 21:42:07.251 # KeyDB 5.3.0 crashed by signal: 11
129:C 14 Feb 2020 21:42:07.251 # Crashed running the instruction at: 0x55634039011e
129:C 14 Feb 2020 21:42:07.251 # Accessing address: 0xffffffffffffffff
129:C 14 Feb 2020 21:42:07.251 # Failed assertion: GlobalLocksAcquired() (multi.cpp:296)

------ STACK TRACE ------
EIP:
/usr/bin/keydb-server 127.0.0.1:6379(_serverAssert+0x7e) [0x55634039011e]

Backtrace:
/usr/bin/keydb-server 127.0.0.1:6379(logStackTrace(ucontext_t*)+0x6b) [0x5563403918ab]
/usr/bin/keydb-server 127.0.0.1:6379(sigsegvHandler(int, siginfo_t*, void*)+0xc9) [0x556340392049]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890) [0x7f2031adb890]
/usr/bin/keydb-server 127.0.0.1:6379(_serverAssert+0x7e) [0x55634039011e]
/usr/bin/keydb-server 127.0.0.1:6379(touchWatchedKey(redisDb*, redisObject*)+0x7b) [0x55634038fadb]
/usr/bin/keydb-server 127.0.0.1:6379(signalModifiedKey(redisDb*, redisObject*)+0x9) [0x556340355ce9]
/usr/bin/keydb-server 127.0.0.1:6379(RM_CloseKey(RedisModuleKey*)+0x75) [0x5563403c2725]
/home/miroslav/RediSearch/build/redisearch.so(+0x724e8) [0x7f202e63f4e8]
/home/miroslav/RediSearch/build/redisearch.so(+0x73a91) [0x7f202e640a91]
/home/miroslav/RediSearch/build/redisearch.so(+0x75a03) [0x7f202e642a03]
/home/miroslav/RediSearch/build/redisearch.so(+0x7c0aa) [0x7f202e6490aa]
/home/miroslav/RediSearch/build/redisearch.so(+0x15d8f4) [0x7f202e72a8f4]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f2031ad06db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f20317f988f]

------ INFO OUTPUT ------
# Server
redis_version:5.3.0
redis_git_sha1:c575e7df
redis_git_dirty:0
redis_build_id:14a12d377a20980b
redis_mode:standalone
os:Linux 4.19.84-microsoft-standard x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.4.0
process_id:129
run_id:0a953cf24dc303828687ba8a27dd5ccc4cf2f831
tcp_port:6379
uptime_in_seconds:10
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:4651023
executable:/usr/bin/keydb-server
config_file:/etc/KeyDB/6379.conf

# Clients
connected_clients:0
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
current_client_thread:0
thread_0_clients:0

# Memory
used_memory:9255904
used_memory_human:8.83M
used_memory_rss:24883200
used_memory_rss_human:23.73M
used_memory_peak:9255904
used_memory_peak_human:8.83M
used_memory_peak_perc:100.32%
used_memory_overhead:9067704
used_memory_startup:9064944
used_memory_dataset:188200
used_memory_dataset_perc:98.55%
allocator_allocated:9512320
allocator_active:10027008
allocator_resident:14499840
total_system_memory:26869592064
total_system_memory_human:25.02G
used_memory_lua:37888
used_memory_lua_human:37.00K
used_memory_scripts:0
used_memory_scripts_human:0B
number_of_cached_scripts:0
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.05
allocator_frag_bytes:514688
allocator_rss_ratio:1.45
allocator_rss_bytes:4472832
rss_overhead_ratio:1.72
rss_overhead_bytes:10383360
mem_fragmentation_ratio:2.70
mem_fragmentation_bytes:15657208
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

# Persistence
loading:0
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1581709317
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:0
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_last_write_status:ok
aof_last_cow_size:0

# Stats
total_connections_received:0
total_commands_processed:0
instantaneous_ops_per_sec:0
total_net_input_bytes:0
total_net_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
evicted_keys:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0

# Replication
role:master
connected_slaves:0
master_replid:ffb3b7d3df0959f63870300d8652533721d27462
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:0.002471
used_cpu_user:0.000000
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:1
long_lock_waits:0

# Commandstats

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=12,expires=0,avg_ttl=0

------ CLIENT LIST OUTPUT ------

------ REGISTERS ------
129:C 14 Feb 2020 21:42:07.252 #
RAX:0000000000000000 RBX:0000000000000128
RCX:0000000000000b40 RDX:0000000000000000
RDI:00007f2031ac4760 RSI:00007f2031ac58c0
RBP:000055634048a435 RSP:00007f201e5aa3d0
R8 :00007f2031ac58c0 R9 :00007f201e5ac700
R10:6e697270206f7420 R11:0000000000000000
R12:000055634047aa82 R13:0000000000000000
R14:00007f2031235140 R15:00007ffc3d916570
RIP:000055634039011e EFL:0000000000010206
CSGSFS:002b000000000033
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3df) -> 00007f202e63f4e8
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3de) -> 0000000000000000
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3dd) -> 00005563403c2725
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3dc) -> 00007f201c417080
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3db) -> 0000556340355ce9
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3da) -> 00007f201e5aa4c0
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d9) -> 00007f201c418050
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d8) -> 0000000000000000
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d7) -> ea4797539a2a1000
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d6) -> 0000000000000001
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d5) -> 00007f201e5aa480
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d4) -> 0000000000000000
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d3) -> 000055634038fadb
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d2) -> 00007f201e5aa700
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d1) -> 00007f201c418050
129:C 14 Feb 2020 21:42:07.252 # (00007f201e5aa3d0) -> 00007f2030519000

------ FAST MEMORY TEST ------
*** Preparing to test memory region 5563406df000 (2260992 bytes)
*** Preparing to test memory region 5563409db000 (266240 bytes)
*** Preparing to test memory region 7f201c400000 (8388608 bytes)
*** Preparing to test memory region 7f201cdab000 (8388608 bytes)
*** Preparing to test memory region 7f201d5ac000 (8388608 bytes)
*** Preparing to test memory region 7f201ddad000 (8388608 bytes)
*** Preparing to test memory region 7f201e5ae000 (8388608 bytes)
*** Preparing to test memory region 7f201edaf000 (8388608 bytes)
*** Preparing to test memory region 7f201f5b0000 (8388608 bytes)
*** Preparing to test memory region 7f201fdb1000 (8388608 bytes)
*** Preparing to test memory region 7f20205b2000 (8388608 bytes)
*** Preparing to test memory region 7f2020db3000 (8388608 bytes)
*** Preparing to test memory region 7f20215b4000 (8388608 bytes)
*** Preparing to test memory region 7f2021db5000 (8388608 bytes)
*** Preparing to test memory region 7f20225b6000 (8388608 bytes)
*** Preparing to test memory region 7f2022db7000 (8388608 bytes)
*** Preparing to test memory region 7f20235b8000 (8388608 bytes)
*** Preparing to test memory region 7f2023db9000 (8388608 bytes)
*** Preparing to test memory region 7f20245ba000 (8388608 bytes)
*** Preparing to test memory region 7f2024dbb000 (8388608 bytes)
*** Preparing to test memory region 7f20255bc000 (8388608 bytes)
*** Preparing to test memory region 7f2025dbd000 (8388608 bytes)
*** Preparing to test memory region 7f20265be000 (8388608 bytes)
*** Preparing to test memory region 7f2026dbf000 (8388608 bytes)
*** Preparing to test memory region 7f20275c0000 (8388608 bytes)
*** Preparing to test memory region 7f2027dc1000 (8388608 bytes)
*** Preparing to test memory region 7f20285c2000 (8388608 bytes)
*** Preparing to test memory region 7f2028dc3000 (8388608 bytes)
*** Preparing to test memory region 7f20295c4000 (8388608 bytes)
*** Preparing to test memory region 7f2029dc5000 (8388608 bytes)
*** Preparing to test memory region 7f202a5c6000 (8388608 bytes)
*** Preparing to test memory region 7f202adc7000 (8388608 bytes)
*** Preparing to test memory region 7f202b5c8000 (8388608 bytes)
*** Preparing to test memory region 7f202bdc9000 (8388608 bytes)
*** Preparing to test memory region 7f202c5ca000 (8388608 bytes)
*** Preparing to test memory region 7f202cdcb000 (8388608 bytes)
*** Preparing to test memory region 7f202d5cc000 (8388608 bytes)
*** Preparing to test memory region 7f202ddcd000 (8388608 bytes)
*** Preparing to test memory region 7f202eb86000 (16384 bytes)
*** Preparing to test memory region 7f202eb8b000 (8388608 bytes)
*** Preparing to test memory region 7f202f38c000 (8388608 bytes)
*** Preparing to test memory region 7f202fb8d000 (8388608 bytes)
*** Preparing to test memory region 7f203038d000 (9437184 bytes)
*** Preparing to test memory region 7f2030e00000 (8388608 bytes)
*** Preparing to test memory region 7f2031ac5000 (16384 bytes)
*** Preparing to test memory region 7f2031ce4000 (16384 bytes)
*** Preparing to test memory region 7f2032623000 (16384 bytes)
*** Preparing to test memory region 7f2032e4e000 (49152 bytes)
*** Preparing to test memory region 7f2032e63000 (4096 bytes)
.O.O.O.O.O.

[miroslavp]

The stack trace is a bit different, but the error states the same. Should I post this as a separate issue?
When I run the module with NOGC parameter, it goes away

[MeirShpilraien]

@JohnSully on 1.6 we do not even use the auto memory so it looks like something else. Also rethinking about it, it does not make sense to hold the GIL to release a ThreadSafeCtx cause you need this ctx after in order to release the GIL. This whole auto memory is fragile and this is why we decided not to use it on 1.6.