Redisgraph: Startup Crash After `<graph> Done decoding graph [graph name]`

Created on 13 Oct 2020 · 3Comments · Source: RedisGraph/RedisGraph

Running container tagged latest from ~Oct 8, 2020

127.0.0.1:6379> MODULE LIST
1) 1) "name"
   2) "graph"
   3) "ver"
   4) (integer) 20206

The graph in question may have been unused (this happened in a development env). Stack Trace:

1:C 09 Oct 2020 21:59:41.966 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1:C 09 Oct 2020 21:59:41.966 # Redis version=6.0.5, bits=64, commit=00000000, modified=0, pid=1, just started
1:C 09 Oct 2020 21:59:41.966 # Configuration loaded
1:M 09 Oct 2020 21:59:41.968 * Running mode=standalone, port=6379.
1:M 09 Oct 2020 21:59:41.968 # Server initialized
1:M 09 Oct 2020 21:59:41.973 * <graph> Graph deletion will be done asynchronously.
1:M 09 Oct 2020 21:59:41.976 * <graph> Thread pool created, using 4 threads.
1:M 09 Oct 2020 21:59:41.977 * <graph> Maximum number of OpenMP threads set to 4
1:M 09 Oct 2020 21:59:41.977 * Module 'graph' loaded from /usr/lib/redis/modules/redisgraph.so
1:M 09 Oct 2020 21:59:41.977 * Loading RDB produced by version 6.0.5
1:M 09 Oct 2020 21:59:41.977 * RDB age 1491 seconds
1:M 09 Oct 2020 21:59:41.977 * RDB memory usage when created 993.01 Mb
1:M 09 Oct 2020 22:00:44.521 * <graph> Done decoding graph graph:access_log


=== REDIS BUG REPORT START: Cut & paste starting from here ===
1:M 09 Oct 2020 22:01:27.481 # Redis 6.0.5 crashed by signal: 11
1:M 09 Oct 2020 22:01:27.481 # Crashed running the instruction at: 0x7f22c1a5ea00
1:M 09 Oct 2020 22:01:27.481 # Accessing address: 0x30
1:M 09 Oct 2020 22:01:27.481 # Failed assertion: <no assertion failed> (<no file>:0)

------ STACK TRACE ------
EIP:
/lib/x86_64-linux-gnu/libpthread.so.0(pthread_rwlock_rdlock+0x0)[0x7f22c1a5ea00]

Backtrace:
redis-server *:6379(logStackTrace+0x32)[0x562be2d01e02]
redis-server *:6379(sigsegvHandler+0x9e)[0x562be2d024de]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7f22c1a64730]
/lib/x86_64-linux-gnu/libpthread.so.0(pthread_rwlock_rdlock+0x0)[0x7f22c1a5ea00]
/usr/lib/redis/modules/redisgraph.so(GraphContext_FindOrAddAttribute+0x1a)[0x7f22c090a89a]
/usr/lib/redis/modules/redisgraph.so(Index_AddField+0x29)[0x7f22c0915c09]
/usr/lib/redis/modules/redisgraph.so(Schema_AddIndex+0x66)[0x7f22c0921626]
/usr/lib/redis/modules/redisgraph.so(+0x1e5af1)[0x7f22c0913af1]
/usr/lib/redis/modules/redisgraph.so(RdbLoadGraphSchema_v7+0xf0)[0x7f22c0913c10]
/usr/lib/redis/modules/redisgraph.so(RdbLoadGraph_v7+0x1bb)[0x7f22c09137fb]
/usr/lib/redis/modules/redisgraph.so(+0x1e327d)[0x7f22c091127d]
redis-server *:6379(+0x6ae1f)[0x562be2ce2e1f]
redis-server *:6379(rdbLoadRio+0x230)[0x562be2ce4b50]
redis-server *:6379(rdbLoad+0x51)[0x562be2ce5591]
redis-server *:6379(loadDataFromDisk+0x7f)[0x562be2cc2b1f]
redis-server *:6379(main+0x438)[0x562be2cb4738]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb)[0x7f22c18b309b]
redis-server *:6379(_start+0x2a)[0x562be2cb4a5a]

------ INFO OUTPUT ------
# Server
redis_version:6.0.5
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:a552bef8bac6cf1c
redis_mode:standalone
os:Linux 5.4.0-1025-aws x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:8.3.0
process_id:1
run_id:3f8b4e698017ffcb4bcf29c2cf8d16ebe3c044ff
tcp_port:6379
uptime_in_seconds:106
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:8445261
executable:/data/redis-server
config_file:

# Clients
connected_clients:1
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0

# Memory
used_memory:1482008128
used_memory_human:1.38G
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:1482008128
used_memory_peak_human:1.38G
used_memory_peak_perc:100.03%
used_memory_overhead:842552
used_memory_startup:840168
used_memory_dataset:1481165576
used_memory_dataset_perc:100.00%
allocator_allocated:0
allocator_active:0
allocator_resident:0
total_system_memory:16789581824
total_system_memory_human:15.64G
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:-nan
allocator_frag_bytes:0
allocator_rss_ratio:-nan
allocator_rss_bytes:0
rss_overhead_ratio:-nan
rss_overhead_bytes:0
mem_fragmentation_ratio:-nan
mem_fragmentation_bytes:0
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:1
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1602280781
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
loading_start_time:1602280781
loading_total_bytes:245498504
loading_loaded_bytes:245366783
loading_loaded_perc:99.95
loading_eta_seconds:0

# Stats
total_connections_received:9
total_commands_processed:0
instantaneous_ops_per_sec:0
total_net_input_bytes:189
total_net_output_bytes:441
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: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
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0

# Replication
role:master
connected_slaves:0
master_replid:ac1a91b3cbd43e9c873c4f577c0f3c01e1e7230c
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:25.699910
used_cpu_user:80.315073
used_cpu_sys_children:0.000835
used_cpu_user_children:0.002242

# Modules
module:name=graph,ver=20206,api=1,filters=0,usedby=[],using=[],options=[]

# Commandstats

# Cluster
cluster_enabled:0

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

------ CLIENT LIST OUTPUT ------
id=14 addr=172.18.0.5:33160 fd=9 name= age=0 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=keys user=default

------ REGISTERS ------
1:M 09 Oct 2020 22:01:27.483 #
RAX:0000000000000000 RBX:00007f22c15e14c0
RCX:00007f22c0000000 RDX:0000000000000001
RDI:0000000000000018 RSI:00007f22c15e14c0
RBP:00007f22c15e14c0 RSP:00007fffc718a8c8
R8 :00007f22c188b730 R9 :0000000000000000
R10:00007f22c1600ac8 R11:00007f22c188b838
R12:0000000000000018 R13:0000000000000000
R14:0000000000000001 R15:0000000000000001
RIP:00007f22c1a5ea00 EFL:0000000000010206
CSGSFS:002b000000000033
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d7) -> 00007f22c15e02e0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d6) -> 00007f22c0ffe9a0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d5) -> 00007fffc718aae0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d4) -> 00007f22c0921626
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d3) -> 00007f22c15e02e0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d2) -> 00007fffc718a978
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d1) -> 00007f22c15e14c0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8d0) -> 00007f22a3df2bf0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8cf) -> 00007fffc718aae0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8ce) -> 00007f22c0915c09
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8cd) -> 0000000000000001
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8cc) -> 00007f22c15e02e0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8cb) -> 00007f22c15e14c0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8ca) -> 00007f22c15e14c0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8c9) -> 00007f22a3df2bf0
1:M 09 Oct 2020 22:01:27.483 # (00007fffc718a8c8) -> 00007f22c090a89a

------ MODULES INFO OUTPUT ------
# graph_executing commands

------ FAST MEMORY TEST ------
1:M 09 Oct 2020 22:01:27.485 # Bio thread for job type #0 terminated
1:M 09 Oct 2020 22:01:27.485 # Bio thread for job type #1 terminated
1:M 09 Oct 2020 22:01:27.485 # Bio thread for job type #2 terminated
*** Preparing to test memory region 562be2e4d000 (2277376 bytes)
*** Preparing to test memory region 562be4f37000 (270336 bytes)
*** Preparing to test memory region 7f225257d000 (1614807040 bytes)
*** Preparing to test memory region 7f22b297e000 (8388608 bytes)
*** Preparing to test memory region 7f22b317f000 (8388608 bytes)
*** Preparing to test memory region 7f22b3980000 (8388608 bytes)
*** Preparing to test memory region 7f22b4180000 (120061952 bytes)
*** Preparing to test memory region 7f22bb4a4000 (2621440 bytes)
*** Preparing to test memory region 7f22bb725000 (8388608 bytes)
*** Preparing to test memory region 7f22bbf26000 (8388608 bytes)
*** Preparing to test memory region 7f22bc727000 (8388608 bytes)
*** Preparing to test memory region 7f22bcf28000 (8388608 bytes)
*** Preparing to test memory region 7f22bd729000 (8388608 bytes)
*** Preparing to test memory region 7f22bdf2a000 (8388608 bytes)
*** Preparing to test memory region 7f22be72b000 (8388608 bytes)
*** Preparing to test memory region 7f22bef2c000 (8388608 bytes)
*** Preparing to test memory region 7f22bf72d000 (8388608 bytes)
*** Preparing to test memory region 7f22bff2e000 (8388608 bytes)
*** Preparing to test memory region 7f22c0ffc000 (16384 bytes)
*** Preparing to test memory region 7f22c1000000 (8388608 bytes)
*** Preparing to test memory region 7f22c188b000 (16384 bytes)
*** Preparing to test memory region 7f22c1a4c000 (24576 bytes)
*** Preparing to test memory region 7f22c1a6f000 (16384 bytes)
*** Preparing to test memory region 7f22c1d58000 (16384 bytes)
*** Preparing to test memory region 7f22c1f80000 (8192 bytes)
*** Preparing to test memory region 7f22c1fad000 (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
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.

------ DUMPING CODE AROUND EIP ------
Symbol: pthread_rwlock_rdlock (base: 0x7f22c1a5ea00)
Module: /lib/x86_64-linux-gnu/libpthread.so.0 (base 0x7f22c1a52000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x7f22c1a5ea00 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
1:M 09 Oct 2020 22:01:33.553 # dump of function (hexdump of 128 bytes):
8b5718648b0425d002000039c20f844d010000415741564155415455534889fb4883ec08837f30027436b808000000f00fc10383c00885c00f8828010000a8010f85b200000031c04883c4085b5d415c415d415e415fc3660f1f8400000000008b1741bcffffffffbdca00000089d083e00383f80275b389d0c1e80374ac89d1

=== REDIS BUG REPORT END. Make sure to include from START to END. ===

       Please report the crash by opening an issue on github:

           http://github.com/antirez/redis/issues

  Suspect RAM error? Use redis-server --test-memory to verify it.

bug

Source