Incorrect FT.PROFILE command causes container to crash (on edge build)

[kenkyl]

Using the redislabs/redismod:edge image (pulled today)

A misspelled command caused the container to crash unexpectedly. I had 10 JSON docs as well as 1 index created.

FT.PROFIKE idx:movies "@title_stem:rise"

[kenkyl]

Crash report from logs:

=== REDIS BUG REPORT START: Cut & paste starting from here ===
1:M 29 Jun 2021 17:45:13.905 # Redis 6.2.4 crashed by signal: 11, si_code: 1
1:M 29 Jun 2021 17:45:13.905 # Accessing address: 0x3
1:M 29 Jun 2021 17:45:13.905 # Crashed running the instruction at: 0x7f18e4a7bbb1

------ STACK TRACE ------
EIP:
/lib/x86_64-linux-gnu/libc.so.6(+0x158bb1)[0x7f18e4a7bbb1]

Backtrace:
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7f18e4af8730]
/lib/x86_64-linux-gnu/libc.so.6(+0x158bb1)[0x7f18e4a7bbb1]
/usr/lib/redis/modules/redisearch.so(RSProfileCommand+0x38)[0x7f18e2fa6368]
redis-server *:6379(RedisModuleCommandDispatcher+0x54)[0x5626baa9a9d4]
redis-server *:6379(call+0x92)[0x5626baa13c72]
redis-server *:6379(processCommand+0x5b3)[0x5626baa157c3]
redis-server *:6379(processCommandAndResetClient+0x1c)[0x5626baa28f5c]
redis-server *:6379(processInputBuffer+0xea)[0x5626baa2b64a]
redis-server *:6379(+0xf3e88)[0x5626baabae88]
redis-server *:6379(aeProcessEvents+0x2a1)[0x5626baa0cce1]
redis-server *:6379(aeMain+0x1d)[0x5626baa0cf3d]
redis-server *:6379(main+0x314)[0x5626baa096f4]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb)[0x7f18e494709b]
redis-server *:6379(_start+0x2a)[0x5626baa09bda]

------ REGISTERS ------
1:M 29 Jun 2021 17:45:13.917 #
RAX:0000000000000003 RBX:00007f18e4409ef0
RCX:0000000000000004 RDX:00007f18e4adf560
RDI:0000000000000003 RSI:00007f18e3150844
RBP:0000000000000001 RSP:00007ffe66cac9c8
R8 :00007f18e4544ba0 R9 :0000000000000000
R10:82297eda49bd52be R11:0000000000000293
R12:00007ffe66caca20 R13:0000000000000003
R14:00007f18e31ff148 R15:00007f18e442a110
RIP:00007f18e4a7bbb1 EFL:0000000000010283
CSGSFS:002b000000000033
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d7) -> 0000000000000000
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d6) -> 0000000000000000
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d5) -> 00007f18d9379c40
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d4) -> 00007f18e440d760
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d3) -> 00005626baa93340
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d2) -> 00005626baa9a9d4
1:M 29 Jun 2021 17:45:13.917 # (00007ffe66cac9d1) -> 00007f18e442a110
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9d0) -> 0000000244d6a395
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9cf) -> 0000000000000000
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9ce) -> 00007f18d9379c40
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9cd) -> 00007f18d9379c40
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9cc) -> 00007ffe66caca20
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9cb) -> 00007ffe66cac9f7
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9ca) -> 00007ffe66caca5f
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9c9) -> 00005626bab558ee
1:M 29 Jun 2021 17:45:13.918 # (00007ffe66cac9c8) -> 00007f18e2fa6368

------ INFO OUTPUT ------

Server

redis_version:6.2.4
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:513e4a3e86ee6388
redis_mode:standalone
os:Linux 5.10.25-linuxkit x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:8.3.0
process_id:1
process_supervised:no
run_id:affe4559c28534588db7e4c82d9784da169f5f4b
tcp_port:6379
server_time_usec:1624988713905008
uptime_in_seconds:2650
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:14375977
executable:/data/redis-server
config_file:
io_threads_active:0

Clients

connected_clients:1
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:32
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0

Memory

used_memory:8203184
used_memory_human:7.82M
used_memory_rss:28798976
used_memory_rss_human:27.46M
used_memory_peak:8222008
used_memory_peak_human:7.84M
used_memory_peak_perc:99.77%
used_memory_overhead:7975496
used_memory_startup:7954456
used_memory_dataset:227688
used_memory_dataset_perc:91.54%
allocator_allocated:8675104
allocator_active:9310208
allocator_resident:12038144
total_system_memory:4127531008
total_system_memory_human:3.84G
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.07
allocator_frag_bytes:635104
allocator_rss_ratio:1.29
allocator_rss_bytes:2727936
rss_overhead_ratio:2.39
rss_overhead_bytes:16760832
mem_fragmentation_ratio:3.53
mem_fragmentation_bytes:20638552
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:20512
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

Persistence

loading:0
current_cow_size:0
current_cow_size_age:0
current_fork_perc:0.00
current_save_keys_processed:0
current_save_keys_total:0
rdb_changes_since_last_save:36
rdb_bgsave_in_progress:0
rdb_last_save_time:1624986063
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
module_fork_in_progress:0
module_fork_last_cow_size:0

Stats

total_connections_received:3
total_commands_processed:76
instantaneous_ops_per_sec:0
total_net_input_bytes:5420
total_net_output_bytes:37794
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
expire_cycle_cpu_milliseconds:556
evicted_keys:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:0
total_forks: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
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:2
dump_payload_sanitizations:0
total_reads_processed:55
total_writes_processed:52
io_threaded_reads_processed:0
io_threaded_writes_processed:0

Replication

role:master
connected_slaves:0
master_failover_state:no-failover
master_replid:9305c13705e9392ca48f8f7bac5cdac404f2dbb8
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:193.284338
used_cpu_user:56.963320
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
used_cpu_sys_main_thread:11.343851
used_cpu_user_main_thread:4.464426

Modules

module:name=graph,ver=999999,api=1,filters=0,usedby=[],using=[],options=[]
module:name=rg,ver=999999,api=1,filters=1,usedby=[rgtimeseries],using=[rg],options=[]
module:name=search,ver=999999,api=1,filters=0,usedby=[],using=[ReJSON],options=[]
module:name=ReJSON,ver=999999,api=1,filters=0,usedby=[search],using=[],options=[]
module:name=ai,ver=999999,api=1,filters=0,usedby=[],using=[],options=[handle-io-errors]
module:name=bf,ver=999999,api=1,filters=0,usedby=[],using=[],options=[]
module:name=timeseries,ver=999999,api=1,filters=0,usedby=[],using=[rg],options=[]

Commandstats

cmdstat_flushdb:calls=1,usec=341,usec_per_call=341.00,rejected_calls=0,failed_calls=0
cmdstat_echo:calls=2,usec=19,usec_per_call=9.50,rejected_calls=0,failed_calls=0
cmdstat_FT.CREATE:calls=2,usec=1799,usec_per_call=899.50,rejected_calls=0,failed_calls=0
cmdstat_info:calls=5,usec=379,usec_per_call=75.80,rejected_calls=0,failed_calls=0
cmdstat_command:calls=1,usec=622,usec_per_call=622.00,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=1,usec=16,usec_per_call=16.00,rejected_calls=0,failed_calls=0
cmdstat_FT._LIST:calls=1,usec=28,usec_per_call=28.00,rejected_calls=0,failed_calls=0
cmdstat_keys:calls=5,usec=364,usec_per_call=72.80,rejected_calls=0,failed_calls=0
cmdstat_FT.SEARCH:calls=27,usec=4588,usec_per_call=169.93,rejected_calls=0,failed_calls=0
cmdstat_FT.PROFILE:calls=1,usec=42,usec_per_call=42.00,rejected_calls=0,failed_calls=1
cmdstat_json.get:calls=2,usec=173,usec_per_call=86.50,rejected_calls=0,failed_calls=0
cmdstat_FT.INFO:calls=2,usec=261,usec_per_call=130.50,rejected_calls=0,failed_calls=0
cmdstat_module:calls=1,usec=67,usec_per_call=67.00,rejected_calls=0,failed_calls=0
cmdstat_config:calls=1,usec=36,usec_per_call=36.00,rejected_calls=0,failed_calls=0
cmdstat_json.set:calls=24,usec=4491,usec_per_call=187.12,rejected_calls=0,failed_calls=0

Errorstats

errorstat_Bad:count=1
errorstat_ERR:count=1

Cluster

cluster_enabled:0

Keyspace

db0:keys=10,expires=0,avg_ttl=0

------ CLIENT LIST OUTPUT ------
id=15 addr=172.17.0.1:57026 laddr=172.17.0.2:6379 fd=16 name= age=1207 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=21 qbuf-free=40933 argv-mem=10 obl=0 oll=0 omem=0 tot-mem=61458 events=r cmd=FT.PROFILE user=default redir=-1

------ CURRENT CLIENT INFO ------
id=15 addr=172.17.0.1:57026 laddr=172.17.0.2:6379 fd=16 name= age=1207 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=21 qbuf-free=40933 argv-mem=10 obl=0 oll=0 omem=0 tot-mem=61458 events=r cmd=FT.PROFILE user=default redir=-1
argv[0]: 'Ft.PROFILE'

------ MODULES INFO OUTPUT ------

graph_executing commands

ai_git

ai_git_sha:1c5298f7185caf4178f750f7c09b26b3e01f0dcd

ai_load_time_configs

ai_threads_per_queue:1
ai_inter_op_parallelism:0
ai_intra_op_parallelism:0

ai_memory_usage

ai_onnxruntime_memory:0
ai_onnxruntime_memory_access_num:0

ai_cpu

ai_self_used_cpu_sys:193.284338
ai_self_used_cpu_user:56.968597
ai_children_used_cpu_sys:0.000000
ai_children_used_cpu_user:0.000000
ai_main_thread_used_cpu_sys:11.284338
ai_main_thread_used_cpu_user:4.968597
ai_queue_CPU_bthread_n1_used_cpu_total:234.034621

------ FAST MEMORY TEST ------
1:M 29 Jun 2021 17:45:13.924 # Bio thread for job type #0 terminated
1:M 29 Jun 2021 17:45:13.925 # Bio thread for job type #1 terminated
1:M 29 Jun 2021 17:45:13.926 # Bio thread for job type #2 terminated
*** Preparing to test memory region 5626babc9000 (2277376 bytes)
*** Preparing to test memory region 5626bbad9000 (454656 bytes)
*** Preparing to test memory region 7f18cf800000 (8388608 bytes)
*** Preparing to test memory region 7f18d0000000 (135168 bytes)
*** Preparing to test memory region 7f18d4000000 (4194304 bytes)
*** Preparing to test memory region 7f18d4600000 (8388608 bytes)
*** Preparing to test memory region 7f18d4e00000 (4194304 bytes)
*** Preparing to test memory region 7f18d53fb000 (8388608 bytes)
*** Preparing to test memory region 7f18d5bfc000 (8388608 bytes)
*** Preparing to test memory region 7f18d63fd000 (8388608 bytes)
*** Preparing to test memory region 7f18d6bfe000 (8388608 bytes)
*** Preparing to test memory region 7f18d73ff000 (8388608 bytes)
*** Preparing to test memory region 7f18d7c00000 (8388608 bytes)
*** Preparing to test memory region 7f18d8400000 (4194304 bytes)
*** Preparing to test memory region 7f18d887b000 (8388608 bytes)
*** Preparing to test memory region 7f18d9299000 (9437184 bytes)
*** Preparing to test memory region 7f18d9b9a000 (8388608 bytes)
*** Preparing to test memory region 7f18da6f7000 (139264 bytes)
*** Preparing to test memory region 7f18da71a000 (8388608 bytes)
*** Preparing to test memory region 7f18daf1b000 (8388608 bytes)
*** Preparing to test memory region 7f18db71c000 (8388608 bytes)
*** Preparing to test memory region 7f18dbf1d000 (8388608 bytes)
*** Preparing to test memory region 7f18dc71e000 (8388608 bytes)
*** Preparing to test memory region 7f18dd028000 (4096 bytes)
*** Preparing to test memory region 7f18dd12a000 (8388608 bytes)
*** Preparing to test memory region 7f18dd92b000 (8388608 bytes)
*** Preparing to test memory region 7f18de12c000 (8388608 bytes)
*** Preparing to test memory region 7f18de92d000 (8388608 bytes)
*** Preparing to test memory region 7f18df12e000 (8388608 bytes)
*** Preparing to test memory region 7f18df92f000 (8388608 bytes)
*** Preparing to test memory region 7f18e0130000 (8388608 bytes)
*** Preparing to test memory region 7f18e0931000 (8388608 bytes)
*** Preparing to test memory region 7f18e253f000 (12288 bytes)
*** Preparing to test memory region 7f18e2543000 (8388608 bytes)
*** Preparing to test memory region 7f18e2d43000 (2097152 bytes)
*** Preparing to test memory region 7f18e31fd000 (12288 bytes)
*** Preparing to test memory region 7f18e3200000 (2097152 bytes)
*** Preparing to test memory region 7f18e343c000 (4096 bytes)
*** Preparing to test memory region 7f18e35bd000 (16384 bytes)
*** Preparing to test memory region 7f18e35c2000 (8388608 bytes)
*** Preparing to test memory region 7f18e3fff000 (4096 bytes)
*** Preparing to test memory region 7f18e4000000 (8388608 bytes)
*** Preparing to test memory region 7f18e486d000 (4096 bytes)
*** Preparing to test memory region 7f18e48ed000 (4096 bytes)
*** Preparing to test memory region 7f18e491f000 (16384 bytes)
*** Preparing to test memory region 7f18e4ae0000 (24576 bytes)
*** Preparing to test memory region 7f18e4b03000 (16384 bytes)
*** Preparing to test memory region 7f18e4dec000 (16384 bytes)
*** Preparing to test memory region 7f18e5014000 (8192 bytes)
*** Preparing to test memory region 7f18e5042000 (4096 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.E.E.1:C 29 Jun 2021 17:49:14.710 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

[kenkyl]

Recreate scenario (NOTE: currently unable to recreate):

1. docker run -p 6379:6379 redislabs/redismod:edge
2. redis-cli
3. FT.CREATE idx:movies ON JSON PREFIX 1 movie: SCHEMA $.title AS title_stem TEXT SORTABLE $.title AS title_no_stem TEXT NOSTEM SORTABLE $.published_at AS published_at NUMERIC SORTABLE $.genre AS genre TAG SEPARATOR ";" SORTABLE
4. cat json_movies.txt | redis-cli --pipe
5. FT.PROFIKE idx:movies "@title_stem:rise"

Docs:

JSON.SET movie:1 . '{"title":"Thrashin","genre":"Action;Drama","published_at":1612778006}'
JSON.SET movie:2 . '{"title":"Five Children and It","genre":"Adventure;Children;Fantasy","published_at":1617697195}'
JSON.SET movie:3 . '{"title":"Letters from Iwo Jima","genre":"Drama;War","published_at":1599831943}'
JSON.SET movie:4 . '{"title":"Small Time Crooks","genre":"Comedy;Crime","published_at":1598314286}'
JSON.SET movie:5 . '{"title":"Seven Year Itch, The","genre":"Comedy","published_at":1616922478}'
JSON.SET movie:6 . '{"title":"Purple Rain","genre":"Drama;Musical","published_at":1596291812}'
JSON.SET movie:7 . '{"title":"Aftermath: Population Zero","genre":"Documentary;Sci-Fi","published_at":1614772953}'
JSON.SET movie:8 . '{"title":"Napoleon Dynamite","genre":"Comedy","published_at":1616686567}'
JSON.SET movie:9 . '{"title":"And Life Goes On (a.k.a. Life and Nothing More) (Zendegi va digar hich)","genre":"Drama","published_at":1596317637}'
JSON.SET movie:10 . '{"title":"House of the Rising Sun","genre":"Action;Crime;Drama;Thriller","published_at":1613547265}'

[gkorland]

127.0.0.1:6379> FT.CREATE idx:movies ON JSON PREFIX 1 movie: SCHEMA $.title AS title_stem TEXT SORTABLE $.title AS title_no_stem TEXT NOSTEM SORTABLE $.published_at AS published_at NUMERIC SORTABLE $.genre AS genre TAG SEPARATOR ";" SORTABLE
OK
127.0.0.1:6379> Ft.PROFILE idx:movies
(error) Bad command type
127.0.0.1:6379> Ft.PROFILE idx:movies
Error: Connection reset by peer
(0.59s)