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

falkordb panic #649

Open
monkey92t opened this issue Apr 18, 2024 · 12 comments
Open

falkordb panic #649

monkey92t opened this issue Apr 18, 2024 · 12 comments
Assignees
Labels
bug Something isn't working good first issue Good for newcomers

Comments

@monkey92t
Copy link

1:M 18 Apr 2024 11:01:05.075 * RDB age 12210 seconds
1:M 18 Apr 2024 11:01:05.075 * RDB memory usage when created 0.89 Mb
1:M 18 Apr 2024 11:01:05.075 * RDB is base AOF
1:M 18 Apr 2024 11:01:05.075 * Done loading RDB, keys loaded: 0, keys expired: 0.
1:M 18 Apr 2024 11:01:05.075 * DB loaded from base file appendonly.aof.1.base.rdb: 0.000 seconds

=== REDIS BUG REPORT START: Cut & paste starting from here ===
1:M 18 Apr 2024 11:01:05.179 # Redis 7.2.4 crashed by signal: 11, si_code: 1
1:M 18 Apr 2024 11:01:05.179 # Accessing address: (nil)
1:M 18 Apr 2024 11:01:05.179 # Crashed running the instruction at: 0x7f647e0f6f7f

------ STACK TRACE ------
EIP:
/FalkorDB/bin/src/falkordb.so(AttributeSet_AddNoClone+0xf)[0x7f647e0f6f7f]

Backtrace:
/lib/x86_64-linux-gnu/libc.so.6(+0x3c050)[0x7f6481325050]
/FalkorDB/bin/src/falkordb.so(AttributeSet_AddNoClone+0xf)[0x7f647e0f6f7f]
/FalkorDB/bin/src/falkordb.so(UpdateNodeProperty+0x1ac)[0x7f647e0fb26c]
/FalkorDB/bin/src/falkordb.so(Effects_Apply+0x631)[0x7f647e0d7f81]
/FalkorDB/bin/src/falkordb.so(Graph_Effect+0x8d)[0x7f647e0ccbcd]
redis-server *:6379(RedisModuleCommandDispatcher+0x92)[0x5579576bdbf2]
redis-server *:6379(loadSingleAppendOnlyFile+0x48d)[0x55795766825d]
redis-server *:6379(loadAppendOnlyFiles+0x436)[0x557957668e86]
redis-server *:6379(loadDataFromDisk+0x1ec)[0x5579575f6aec]
redis-server *:6379(main+0x2d2)[0x5579575cf562]
/lib/x86_64-linux-gnu/libc.so.6(+0x2724a)[0x7f648131024a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85)[0x7f6481310305]
redis-server *:6379(_start+0x21)[0x5579575cfe41]

------ REGISTERS ------
1:M 18 Apr 2024 11:01:05.182 #
RAX:00007f6480995db0 RBX:00007ffd5cf55b70
RCX:0000000000000001 RDX:00007ffd5cf55aa0
RDI:0000000000000000 RSI:00007ffd5cf55abc
RBP:00007ffd5cf55b10 RSP:00007ffd5cf55a70
R8 :0000000000000001 R9 :00005579592c6730
R10:a42591afe3b3974c R11:00007f6466c37b90
R12:00007f6480e483c0 R13:0000000000000000
R14:00007ffd5cf55ac0 R15:00007f6480e483c0
RIP:00007f647e0f6f7f EFL:0000000000010246
CSGSFS:002b000000000033
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a7f) -> 00007ffd5cf55b70
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a7e) -> 00007f6480e483c0
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a7d) -> ebbad04084885900
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a7c) -> 00000800804c3070
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a7b) -> 00000000000000ce
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a7a) -> 0000000000000000
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a79) -> 0000000500000001
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a78) -> 00007f64804c3070
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a77) -> 0000000100000800
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a76) -> 00007f6466c37b90
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a75) -> 00007f647e0fb26c
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a74) -> 00007ffd5cf55ac0
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a73) -> 00007f64804c3070
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a72) -> 00007f6480e483c0
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a71) -> 00007ffd5cf55b10
1:M 18 Apr 2024 11:01:05.182 # (00007ffd5cf55a70) -> 00007ffd5cf55b70

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

Server

redis_version:7.2.4
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:30468499a8bc54fe
redis_mode:standalone
os:Linux 4.12.14-122.201-default x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:12.2.0
process_id:1
process_supervised:no
run_id:df0f6c1b518f60aadc177d252b11526c6977d91d
tcp_port:6379
server_time_usec:1713438065075453
uptime_in_seconds:0
uptime_in_days:0

@monkey92t
Copy link
Author

my os:

10-238-50-108:/opt # uname -a
Linux 10-238-50-108 4.12.14-122.201-default #1 SMP Tue Mar 12 13:01:34 UTC 2024 (b92bd5a) x86_64 x86_64 x86_64 GNU/Linux
10-238-50-108:/opt # cat /etc/os-release 
NAME="SLES"
VERSION="12-SP5"
VERSION_ID="12.5"
PRETTY_NAME="SUSE Linux Enterprise Server 12 SP5"
ID="sles"
ANSI_COLOR="0;32"
CPE_NAME="cpe:/o:suse:sles:12:sp5"

@gkorland gkorland added the good first issue Good for newcomers label Apr 18, 2024
@monkey92t
Copy link
Author

I'm using the falkordb/falkordb:edge image, and I can 100% reproduce this issue on SUSE system, without any luck involved. However, it doesn't occur on Ubuntu and works fine there. I'm not familiar with C/C++ languages, so it's difficult for me to troubleshoot the root cause.

😊Thank you very much FalkorDB. It's great and provides efficient graph database queries.I have submitted a PR to add support for FalkorDB in the go-redis client(redis/go-redis#2969). Assuming everything goes smoothly, go-redis will release a version supporting FalkorDB in a very short time. Apart from that, looking forward to RESP3!

@gkorland gkorland added the bug Something isn't working label Apr 21, 2024
@gkorland
Copy link
Contributor

@monkey92t for sharing the issue, any chance you can share the rdb/aof you're using to get the crash?

@monkey92t
Copy link
Author

sure~,

rdb-aof file:
test-rdb-aof.tar.gz

When I copied the RDB-AOF data to an Ubuntu system, FalkorDB failed to start with the same error message as the current issue. I suspect that a certain piece of data triggered this bug because my test environments are not exactly the same. When I performed the same operation on another cluster (a slightly different one), it did not trigger this bug. I am not sure where the problem lies, whether it's the data format or character set.

I checked the redis.conf configuration file, but there was nothing unusual. I use the same configuration file for other redis-server instances (non-FalkorDB), and they have not had any issues. I can provide the redis.conf file if you need it, but I feel it may not be of much use.

@swilly22
Copy link
Contributor

Hi @monkey92t, thank you for sharing this information.
I'm running on Apple M3 Pro and was able to load the data using the dump.rdb file.
during the upcoming week we'll test this RDB file on additional systems.

@AviAvni can you please give this a try ?

@monkey92t
Copy link
Author

I tried replacing another device (ubuntu x86) for testing and recompiled the FalkorDB module, but it still doesn't work.

[ 98%] Building C object CMakeFiles/falkordb.dir/src/util/thpool/pools.c.o
[ 99%] Building C object CMakeFiles/falkordb.dir/src/util/thpool/thpool.c.o
[ 99%] Building C object CMakeFiles/falkordb.dir/src/util/uuid.c.o
[ 99%] Building C object CMakeFiles/falkordb.dir/src/value.c.o
[100%] Linking CXX shared library falkordb.so
Extacting debug symbols from /opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so ...
[100%] Built target falkordb
root@shtest:/opt/graph/FalkorDB# 
root@shtest:/opt/graph/FalkorDB# 
root@shtest:/opt/graph/FalkorDB# cd ..
root@shtest:/opt/graph# ll
total 51088
drwxr-xr-x  5 root root     4096 Apr 25 01:28 ./
drwxr-xr-x  8 root root     4096 Apr 25 01:05 ../
drwxr-xr-x  3 root root     4096 Apr 25 01:13 data/
drwxr-xr-x 12 root root     4096 Apr 25 01:38 FalkorDB/
-rwxr-xr-x  1 root root 48631256 Apr 25 01:12 falkordb.so*
-rw-r--r--  1 root root        8 Apr 25 01:13 redis_6379.pid
drwxrwxr-x  8 root root     4096 Apr 25 01:12 redis-7.2.1/
-rw-r--r--  1 root root  3383319 Sep  7  2023 redis-7.2.1.tar.gz
-rw-r--r--  1 root root   266885 Apr 22 10:57 test-rdb-aof.tar.gz
root@shtest:/opt/graph# cd redis-7.2.1/
root@shtest:/opt/graph/redis-7.2.1# vi redis.conf 
root@shtest:/opt/graph/redis-7.2.1# ./src/redis-server ./redis.conf 
3229186:C 25 Apr 2024 02:13:15.669 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
3229186:C 25 Apr 2024 02:13:15.669 * Redis version=7.2.1, bits=64, commit=00000000, modified=0, pid=3229186, just started
3229186:C 25 Apr 2024 02:13:15.669 * Configuration loaded
3229186:M 25 Apr 2024 02:13:15.670 * Increased maximum number of open files to 10032 (it was originally set to 1024).
3229186:M 25 Apr 2024 02:13:15.670 * monotonic clock: POSIX clock_gettime
                _._                                                  
           _.-``__ ''-._                                             
      _.-``    `.  `_.  ''-._           Redis 7.2.1 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._                                  
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 26379
 |    `-._   `._    /     _.-'    |     PID: 3229186
  `-._    `-._  `-./  _.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |           https://redis.io       
  `-._    `-._`-.__.-'_.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |                                  
  `-._    `-._`-.__.-'_.-'    _.-'                                   
      `-._    `-.__.-'    _.-'                                       
          `-._        _.-'                                           
              `-.__.-'                                               

3229186:M 25 Apr 2024 02:13:15.677 * <graph> Enabled role change notification
3229186:M 25 Apr 2024 02:13:15.677 * <graph> Starting up FalkorDB version 99.99.99.
3229186:M 25 Apr 2024 02:13:15.679 * <graph> Thread pool created, using 8 threads.
3229186:M 25 Apr 2024 02:13:15.679 * <graph> Maximum number of OpenMP threads set to 8
3229186:M 25 Apr 2024 02:13:15.679 * <graph> Query backlog size: 1000
3229186:M 25 Apr 2024 02:13:15.679 * Module 'graph' loaded from /opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so
3229186:M 25 Apr 2024 02:13:15.679 * Server initialized
3229186:M 25 Apr 2024 02:13:15.704 * Reading RDB base file on AOF loading...
3229186:M 25 Apr 2024 02:13:15.704 * Loading RDB produced by version 7.2.4
3229186:M 25 Apr 2024 02:13:15.704 * RDB age 541407 seconds
3229186:M 25 Apr 2024 02:13:15.704 * RDB memory usage when created 0.89 Mb
3229186:M 25 Apr 2024 02:13:15.704 * RDB is base AOF
3229186:M 25 Apr 2024 02:13:15.704 * Done loading RDB, keys loaded: 0, keys expired: 0.
3229186:M 25 Apr 2024 02:13:15.704 * DB loaded from base file appendonly.aof.1.base.rdb: 0.004 seconds


=== REDIS BUG REPORT START: Cut & paste starting from here ===
3229186:M 25 Apr 2024 02:13:15.784 # Redis 7.2.1 crashed by signal: 11, si_code: 1
3229186:M 25 Apr 2024 02:13:15.784 # Accessing address: (nil)
3229186:M 25 Apr 2024 02:13:15.784 # Crashed running the instruction at: 0x7f653ec29885

------ STACK TRACE ------
EIP:
/opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so(AttributeSet_AddNoClone+0x15)[0x7f653ec29885]

Backtrace:
/lib/x86_64-linux-gnu/libpthread.so.0(+0x14420)[0x7f6541a41420]
/opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so(AttributeSet_AddNoClone+0x15)[0x7f653ec29885]
/opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so(UpdateNodeProperty+0x1ac)[0x7f653ec2db4c]
/opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so(Effects_Apply+0x641)[0x7f653ec0cc51]
/opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so(Graph_Effect+0x8d)[0x7f653ec018fd]
./src/redis-server *:26379(RedisModuleCommandDispatcher+0x52)[0x556f616c0992]
./src/redis-server *:26379(loadSingleAppendOnlyFile+0x342)[0x556f61719432]
./src/redis-server *:26379(loadAppendOnlyFiles+0x45f)[0x556f6171a11f]
./src/redis-server *:26379(loadDataFromDisk+0x14c)[0x556f6179083c]
./src/redis-server *:26379(main+0x2c2)[0x556f61655cd2]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f654185f083]
./src/redis-server *:26379(_start+0x2e)[0x556f6165657e]

------ REGISTERS ------
3229186:M 25 Apr 2024 02:13:15.786 # 
RAX:00007f6540cabdb0 RBX:00007ffea1df7cb0
RCX:0000000000000001 RDX:00007ffea1df7be0
RDI:0000000000000000 RSI:00007ffea1df7bfc
RBP:00007ffea1df7c50 RSP:00007ffea1df7ba0
R8 :0000000000000001 R9 :0000000000000027
R10:00000000045313c8 R11:00007f654183a680
R12:00007f6541448480 R13:0000000000000000
R14:00007ffea1df7c00 R15:00007f6541448480
RIP:00007f653ec29885 EFL:0000000000010206
CSGSFS:002b000000000033
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7baf) -> ab7e062347dd2700
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7bae) -> 000008004183a680
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7bad) -> 00000000000000bc
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7bac) -> 0000000000000000
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7bab) -> 0000000500000001
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7baa) -> 00007f65407e7108
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba9) -> 0000000100000800
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba8) -> 00007f652e643370
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba7) -> 00007f653ec2db4c
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba6) -> 00007f6541448480
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba5) -> 00007ffea1df7c00
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba4) -> 00007f65407e7108
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba3) -> 00007f6541448480
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba2) -> 00007ffea1df7c50
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba1) -> 00007ffea1df7cb0
3229186:M 25 Apr 2024 02:13:15.786 # (00007ffea1df7ba0) -> 0000000000000041

------ INFO OUTPUT ------
# Server
redis_version:7.2.1
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:84faa584749f4a39
redis_mode:standalone
os:Linux 5.4.0-169-generic x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:9.4.0
process_id:3229186
process_supervised:no
run_id:974bf409c8f6fc169f11b6d5f4f66ca522838fa7
tcp_port:26379
server_time_usec:1713982395721009
uptime_in_seconds:0
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:2706363
executable:/opt/graph/redis-7.2.1/./src/redis-server
config_file:/opt/graph/redis-7.2.1/./redis.conf
io_threads_active:0
listener0:name=tcp,bind=*,bind=-::*,port=26379

# Clients
connected_clients:0
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
total_blocking_keys:0
total_blocking_keys_on_nokey:0

# Memory
used_memory:10341904
used_memory_human:9.86M
used_memory_rss:15413248
used_memory_rss_human:14.70M
used_memory_peak:10341904
used_memory_peak_human:9.86M
used_memory_peak_perc:1084.08%
used_memory_overhead:936248
used_memory_startup:935992
used_memory_dataset:9405656

@monkey92t
Copy link
Author

My OS:

root@shtest:/opt/graph/redis-7.2.1# cat /etc/os-release 
NAME="Ubuntu"
VERSION="20.04.3 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 20.04.3 LTS"
VERSION_ID="20.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal
root@shtest:/opt/graph/redis-7.2.1# uname -r
5.4.0-169-generic
root@shtest:/opt/graph/redis-7.2.1# 

@monkey92t
Copy link
Author

monkey92t commented Apr 24, 2024

If I disable AOF (appendonly no) and only enable RDB, it works fine.

root@shtest:/opt/graph/redis-7.2.1# ./src/redis-server ./redis.conf 
3266598:C 25 Apr 2024 02:27:27.386 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
3266598:C 25 Apr 2024 02:27:27.386 * Redis version=7.2.1, bits=64, commit=00000000, modified=0, pid=3266598, just started
3266598:C 25 Apr 2024 02:27:27.386 * Configuration loaded
3266598:M 25 Apr 2024 02:27:27.387 * Increased maximum number of open files to 10032 (it was originally set to 1024).
3266598:M 25 Apr 2024 02:27:27.387 * monotonic clock: POSIX clock_gettime
                _._                                                  
           _.-``__ ''-._                                             
      _.-``    `.  `_.  ''-._           Redis 7.2.1 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._                                  
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 26379
 |    `-._   `._    /     _.-'    |     PID: 3266598
  `-._    `-._  `-./  _.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |           https://redis.io       
  `-._    `-._`-.__.-'_.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |                                  
  `-._    `-._`-.__.-'_.-'    _.-'                                   
      `-._    `-.__.-'    _.-'                                       
          `-._        _.-'                                           
              `-.__.-'                                               

3266598:M 25 Apr 2024 02:27:27.392 * <graph> Enabled role change notification
3266598:M 25 Apr 2024 02:27:27.392 * <graph> Starting up FalkorDB version 99.99.99.
3266598:M 25 Apr 2024 02:27:27.393 * <graph> Thread pool created, using 8 threads.
3266598:M 25 Apr 2024 02:27:27.393 * <graph> Maximum number of OpenMP threads set to 8
3266598:M 25 Apr 2024 02:27:27.393 * <graph> Query backlog size: 1000
3266598:M 25 Apr 2024 02:27:27.393 * Module 'graph' loaded from /opt/graph/FalkorDB/bin/linux-x64-release/src/falkordb.so
3266598:M 25 Apr 2024 02:27:27.393 * Server initialized
3266598:M 25 Apr 2024 02:27:27.393 * Loading RDB produced by version 7.2.1
3266598:M 25 Apr 2024 02:27:27.393 * RDB age 84 seconds
3266598:M 25 Apr 2024 02:27:27.393 * RDB memory usage when created 10.43 Mb
3266598:M 25 Apr 2024 02:27:27.409 * <module> Deleted 0 virtual keys for graph mycluster:graph
3266598:M 25 Apr 2024 02:27:27.409 * Done loading RDB, keys loaded: 2, keys expired: 0.
3266598:M 25 Apr 2024 02:27:27.409 * DB loaded from disk: 0.016 seconds
3266598:M 25 Apr 2024 02:27:27.409 * Ready to accept connections tcp

@monkey92t
Copy link
Author

any news?

@AviAvni
Copy link
Contributor

AviAvni commented May 7, 2024

I was able to reproduce this crash on my M3 mac
the crash occure when loading the AOF after the rdb loaded

@AviAvni
Copy link
Contributor

AviAvni commented May 7, 2024

it look like something is corrupted in the aof can you try run the BGREWRITEAOF command get the new aof and try to load it?

@monkey92t
Copy link
Author

I discovered this issue during an unexpected power outage. The issue can also be reproduced using kill -9, but it's not 100% reproducible. It's more likely to occur when inserting data into the graph store at a high frequency. I'm not sure when BGREWRITEAOF should be executed. In most cases, Redis fails to start after recovery, so I haven't had the opportunity to execute it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working good first issue Good for newcomers
Projects
None yet
Development

No branches or pull requests

4 participants