search

paullouisageneau / violet

Lightweight STUN/TURN server
GNU General Public License v2.0
226 stars 22 forks source link

Segmentation fault during TURN allocate request #9

Closed peclatj closed 3 years ago

peclatj commented 3 years ago

Hello,

I wanted to report a segmentation fault during a TURN allocate request. The bugs happens 4 times in a row. (out of 4 try, so every time). It happens when the connection is closing or when I start a second one.

I'm creating the webrtc peer with libdatachannel and libjuice on one side:

IceServer turn("160.98.47.137", 8000, "user", "password", IceServer::RelayType::TurnUdp);
config.iceServers.emplace_back("stun:stun.1.google.com:19302");
config.iceServers.emplace_back(turn);

And on the web browser side:

if (document.getElementById('use-stun').checked) {
    config.iceServers = [
    {
        urls: ['stun:stun.l.google.com:19302']
    },
    {
        urls: ['turn:160.98.47.137:8000'],
        username: 'user',
        credential: 'password'
    }
    ];
}

let pc = new RTCPeerConnection(config);

Here is the log:

Starting program: /opt/violet --file=example.conf
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
2021-07-28 17:41:03 DEBUG   udp.c:139: UDP socket bound to any:8000
2021-07-28 17:41:03 INFO    server.c:235: Created server on port 8000
[New Thread 0x7ffff7d39700 (LWP 5675)]
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 160.98.47.35:60510
2021-07-28 17:41:11 DEBUG   server.c:607: Answering STUN unauthorized error response
2021-07-28 17:41:11 DEBUG   server.c:717: Answering STUN error response with code 401
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 160.98.47.35:60510
2021-07-28 17:41:11 DEBUG   server.c:752: Processing TURN Allocate request
2021-07-28 17:41:11 DEBUG   udp.c:157: UDP socket bound to any:65275
2021-07-28 17:41:11 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:65275 for client 160.98.47.35:60510
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 INFO    server.c:737: Got STUN binding from client 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:690: Answering STUN Binding request
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:607: Answering STUN unauthorized error response
2021-07-28 17:41:11 DEBUG   server.c:717: Answering STUN error response with code 401
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:752: Processing TURN Allocate request
2021-07-28 17:41:11 DEBUG   udp.c:157: UDP socket bound to any:65276
2021-07-28 17:41:11 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:65276 for client 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:899: Processing STUN CreatePermission request
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:899: Processing STUN CreatePermission request
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:899: Processing STUN CreatePermission request
2021-07-28 17:41:11 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:11 DEBUG   server.c:994: Processing STUN Send indication
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:12 DEBUG   server.c:994: Processing STUN Send indication
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:12 DEBUG   server.c:994: Processing STUN Send indication
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 160.98.47.35:60510
2021-07-28 17:41:12 DEBUG   server.c:899: Processing STUN CreatePermission request
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 160.98.47.35:60510
2021-07-28 17:41:12 DEBUG   server.c:994: Processing STUN Send indication
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:12 DEBUG   server.c:941: Processing STUN ChannelBind request
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:12 DEBUG   server.c:994: Processing STUN Send indication
2021-07-28 17:41:12 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:12 DEBUG   server.c:994: Processing STUN Send indication
2021-07-28 17:41:12 DEBUG   server.c:481: Received ChannelData datagram from 194.230.158.225:59603
2021-07-28 17:41:15 DEBUG   server.c:467: Received STUN datagram from 194.230.158.225:59603
2021-07-28 17:41:15 DEBUG   server.c:752: Processing TURN Allocate request

Thread 2 "violet" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff7d39700 (LWP 4822)]
0x000055555556537d in addr_get_len (sa=0x0) at /opt/violet_src/deps/libjuice/src/addr.c:26
26      switch (sa->sa_family) {
(gdb) list
21  
22  #include <stdio.h>
23  #include <string.h>
24  
25  socklen_t addr_get_len(const struct sockaddr *sa) {
26      switch (sa->sa_family) {
27      case AF_INET:
28          return sizeof(struct sockaddr_in);
29      case AF_INET6:
30          return sizeof(struct sockaddr_in6);
(gdb) bt
#0  0x000055555556537d in addr_get_len (sa=0x0) at /opt/violet_src/deps/libjuice/src/addr.c:26
#1  0x0000555555565b6a in addr_to_string (sa=0x0, buffer=0x7ffff7d36d00 " }\323\367\377\177", size=64) at /opt/violet_src/deps/libjuice/src/addr.c:203
#2  0x000055555556600e in addr_record_to_string (record=0x0, buffer=0x7ffff7d36d00 " }\323\367\377\177", size=64) at /opt/violet_src/deps/libjuice/src/addr.c:304
#3  0x000055555555d267 in server_process_turn_allocate (server=0x555555582500, msg=0x7ffff7d370f0, src=0x7ffff7d37d20, credentials=0x555555583570)
    at /opt/violet_src/deps/libjuice/src/server.c:868
#4  0x000055555555c5cc in server_dispatch_stun (server=0x555555582500, buf=0x7ffff7d37db0, size=124, msg=0x7ffff7d370f0, src=0x7ffff7d37d20)
    at /opt/violet_src/deps/libjuice/src/server.c:671
#5  0x000055555555b9d1 in server_input (server=0x555555582500, buf=0x7ffff7d37db0 "", len=124, src=0x7ffff7d37d20) at /opt/violet_src/deps/libjuice/src/server.c:474
#6  0x000055555555b44b in server_recv (server=0x555555582500) at /opt/violet_src/deps/libjuice/src/server.c:402
#7  0x000055555555b0ba in server_run (server=0x555555582500) at /opt/violet_src/deps/libjuice/src/server.c:348
#8  0x000055555555a2bb in server_thread_entry (arg=0x555555582500) at /opt/violet_src/deps/libjuice/src/server.c:111
#9  0x00007ffff7fa6609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff7ecd293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

And here is the configuration file that I used:

log-level=debug

# Port for STUN/TURN server
port=8000

# Port range for TURN relay
range=49152:65535

# TURN credentials with optional quota (default none)
credentials=user:password

Thank you for your work by the way.

paullouisageneau commented 3 years ago

Thank you for reporting! The error is caused by misplaced logging (level INFO) resulting in an attempt to log a NULL address on TURN Allocate with 0 lifetime (used to deallocate).

paullouisageneau commented 3 years ago

This is fixed in https://github.com/paullouisageneau/violet/commit/854579a560cd497d94fc73b0f778d5d3dea10ecd (v0.3.2)

peclatj commented 3 years ago

Hello again,

First of all thank you for being so quick to reply :D. I pulled the code to try again but unfortunately, this bug is still present with your fix.

Build log to show that I'm compiling with the fix

jonathan.peclat@smro2:/opt/violet_src$ rm -r build
jonathan.peclat@smro2:/opt/violet_src$ git reset --hard
HEAD is now at bcd4ede Bumped version to 0.3.2
jonathan.peclat@smro2:/opt/violet_src$ cmake -B build -DCMAKE_BUILD_TYPE=Debug
-- The C compiler identification is GNU 9.3.0
-- Check for working C compiler: /usr/bin/cc
-- Check for working C compiler: /usr/bin/cc -- works
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
-- Detecting C compile features
-- Detecting C compile features - done
-- Looking for pthread.h
-- Looking for pthread.h - found
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Failed
-- Check if compiler accepts -pthread
-- Check if compiler accepts -pthread - yes
-- Found Threads: TRUE
-- Performing Test COMPILER_HAS_HIDDEN_VISIBILITY
-- Performing Test COMPILER_HAS_HIDDEN_VISIBILITY - Success
-- Performing Test COMPILER_HAS_HIDDEN_INLINE_VISIBILITY
-- Performing Test COMPILER_HAS_HIDDEN_INLINE_VISIBILITY - Failed
-- Performing Test COMPILER_HAS_DEPRECATED_ATTR
-- Performing Test COMPILER_HAS_DEPRECATED_ATTR - Success
-- Configuring done
-- Generating done
-- Build files have been written to: /opt/violet_src/build
jonathan.peclat@smro2:/opt/violet_src$ cd build
jonathan.peclat@smro2:/opt/violet_src/build$ make
Scanning dependencies of target juice-static
[  4%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/addr.c.o
[  9%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/agent.c.o
[ 13%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/crc32.c.o
[ 18%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/const_time.c.o
[ 22%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/base64.c.o
[ 27%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/hash.c.o
[ 31%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/hmac.c.o
[ 36%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/ice.c.o
[ 40%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/juice.c.o
[ 45%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/log.c.o
[ 50%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/random.c.o
[ 54%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/server.c.o
[ 59%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/stun.c.o
[ 63%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/timestamp.c.o
[ 68%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/turn.c.o
[ 72%] Building C object deps/libjuice/CMakeFiles/juice-static.dir/src/udp.c.o
[ 77%] Linking C static library libjuice-static.a
[ 77%] Built target juice-static
Scanning dependencies of target violet
[ 81%] Building C object CMakeFiles/violet.dir/src/daemon.c.o
[ 86%] Building C object CMakeFiles/violet.dir/src/main.c.o
[ 90%] Building C object CMakeFiles/violet.dir/src/options.c.o
[ 95%] Building C object CMakeFiles/violet.dir/src/utils.c.o
[100%] Linking C executable violet
[100%] Built target violet
jonathan.peclat@smro2:/opt/violet_src/build$ cd ../..
jonathan.peclat@smro2:/opt$ ls
violet.conf  violet_src
jonathan.peclat@smro2:/opt$ cp violet_src/build/violet .

Running

jonathan.peclat@smro2:/opt/peclat_turn_server$ gdb violet
Reading symbols from violet...
(gdb) run --file=violet.conf
Starting program: /opt/peclat_turn_server/violet --file=violet.conf
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
2021-07-29 10:20:06 DEBUG   udp.c:139: UDP socket bound to any:8000
2021-07-29 10:20:06 INFO    server.c:235: Created server on port 8000
[New Thread 0x7ffff7d39700 (LWP 33039)]
2021-07-29 10:20:12 DEBUG   server.c:467: Received STUN datagram from 160.98.47.35:37147
2021-07-29 10:20:12 DEBUG   server.c:607: Answering STUN unauthorized error response
2021-07-29 10:20:12 DEBUG   server.c:717: Answering STUN error response with code 401
2021-07-29 10:20:13 DEBUG   server.c:467: Received STUN datagram from 160.98.47.35:37147
2021-07-29 10:20:13 DEBUG   server.c:752: Processing TURN Allocate request
2021-07-29 10:20:13 DEBUG   udp.c:157: UDP socket bound to any:52102
2021-07-29 10:20:13 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:52102 for client 160.98.47.35:37147
2021-07-29 10:20:13 DEBUG   server.c:467: Received STUN datagram from 160.98.166.71:56481
2021-07-29 10:20:13 INFO    server.c:737: Got STUN binding from client 160.98.166.71:56481
2021-07-29 10:20:13 DEBUG   server.c:690: Answering STUN Binding request
2021-07-29 10:20:13 DEBUG   server.c:467: Received STUN datagram from 160.98.166.71:56481
2021-07-29 10:20:13 DEBUG   server.c:607: Answering STUN unauthorized error response
2021-07-29 10:20:13 DEBUG   server.c:717: Answering STUN error response with code 401
2021-07-29 10:20:13 DEBUG   server.c:467: Received STUN datagram from 160.98.166.71:56481
2021-07-29 10:20:13 DEBUG   server.c:752: Processing TURN Allocate request
2021-07-29 10:20:13 DEBUG   udp.c:157: UDP socket bound to any:52103
2021-07-29 10:20:13 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:52103 for client 160.98.166.71:56481
2021-07-29 10:20:15 DEBUG   server.c:467: Received STUN datagram from 160.98.166.71:56481
2021-07-29 10:20:15 DEBUG   server.c:752: Processing TURN Allocate request

Thread 2 "violet" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff7d39700 (LWP 33039)]
0x000055555556537d in addr_get_len (sa=0x0) at /opt/violet_src/deps/libjuice/src/addr.c:26
26              switch (sa->sa_family) {
(gdb) bt
#0  0x000055555556537d in addr_get_len (sa=0x0) at /opt/violet_src/deps/libjuice/src/addr.c:26
#1  0x0000555555565b6a in addr_to_string (sa=0x0, buffer=0x7ffff7d36d00 " }\323\367\377\177", size=64)
    at /opt/violet_src/deps/libjuice/src/addr.c:203
#2  0x000055555556600e in addr_record_to_string (record=0x0, buffer=0x7ffff7d36d00 " }\323\367\377\177", size=64)
    at /opt/violet_src/deps/libjuice/src/addr.c:304
#3  0x000055555555d267 in server_process_turn_allocate (server=0x555555582500, msg=0x7ffff7d370f0,
    src=0x7ffff7d37d20, credentials=0x555555583570)
    at /opt/violet_src/deps/libjuice/src/server.c:868
#4  0x000055555555c5cc in server_dispatch_stun (server=0x555555582500, buf=0x7ffff7d37db0, size=128,
    msg=0x7ffff7d370f0, src=0x7ffff7d37d20) at /opt/violet_src/deps/libjuice/src/server.c:671
#5  0x000055555555b9d1 in server_input (server=0x555555582500, buf=0x7ffff7d37db0 "", len=128, src=0x7ffff7d37d20)
    at /opt/violet_src/deps/libjuice/src/server.c:474
#6  0x000055555555b44b in server_recv (server=0x555555582500)
    at /opt/violet_src/deps/libjuice/src/server.c:402
#7  0x000055555555b0ba in server_run (server=0x555555582500)
    at /opt/violet_src/deps/libjuice/src/server.c:348
#8  0x000055555555a2bb in server_thread_entry (arg=0x555555582500)
    at /opt/violet_src/deps/libjuice/src/server.c:111
#9  0x00007ffff7fa6609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff7ecd293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The seg fault also occurs in log-level=info

2021-07-29 10:30:43 INFO    server.c:235: Created server on port 8000
[New Thread 0x7ffff7d39700 (LWP 33331)]
2021-07-29 10:30:47 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:59809 for client 160.98.47.35:43332
2021-07-29 10:30:48 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:59809 for client 160.98.47.35:43332
2021-07-29 10:30:48 INFO    server.c:737: Got STUN binding from client 160.98.166.71:61724
2021-07-29 10:30:48 INFO    server.c:869: Allocated TURN relayed address 160.98.47.137:59810 for client 160.98.166.71:61724

Thread 2 "violet" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff7d39700 (LWP 33331)]
0x000055555556537d in addr_get_len (sa=0x0) at /opt/violet_src/deps/libjuice/src/addr.c:26
26              switch (sa->sa_family) {
(gdb) bt
#0  0x000055555556537d in addr_get_len (sa=0x0) at /opt/violet_src/deps/libjuice/src/addr.c:26
#1  0x0000555555565b6a in addr_to_string (sa=0x0, buffer=0x7ffff7d36d00 " }\323\367\377\177", size=64)
    at /opt/violet_src/deps/libjuice/src/addr.c:203
#2  0x000055555556600e in addr_record_to_string (record=0x0, buffer=0x7ffff7d36d00 " }\323\367\377\177", size=64)
    at /opt/violet_src/deps/libjuice/src/addr.c:304
#3  0x000055555555d267 in server_process_turn_allocate (server=0x555555582500, msg=0x7ffff7d370f0,
    src=0x7ffff7d37d20, credentials=0x555555583570)
    at /opt/violet_src/deps/libjuice/src/server.c:868
#4  0x000055555555c5cc in server_dispatch_stun (server=0x555555582500, buf=0x7ffff7d37db0, size=128,
    msg=0x7ffff7d370f0, src=0x7ffff7d37d20) at /opt/violet_src/deps/libjuice/src/server.c:671
#5  0x000055555555b9d1 in server_input (server=0x555555582500, buf=0x7ffff7d37db0 "", len=128, src=0x7ffff7d37d20)
    at /opt/violet_src/deps/libjuice/src/server.c:474
#6  0x000055555555b44b in server_recv (server=0x555555582500)
    at /opt/violet_src/deps/libjuice/src/server.c:402
#7  0x000055555555b0ba in server_run (server=0x555555582500)
    at /opt/violet_src/deps/libjuice/src/server.c:348
#8  0x000055555555a2bb in server_thread_entry (arg=0x555555582500)
    at /opt/violet_src/deps/libjuice/src/server.c:111
#9  0x00007ffff7fa6609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007ffff7ecd293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The config file:

# Violet - Example configuration file

# Log level
log-level=info
#log-level=debug

# Log file (default stdout)
#log=/var/log/violet.log

# Port for STUN/TURN server
port=8000

# Port range for TURN relay
range=49152:65535

# Local address to bind (default any)
#bind=0.0.0.0

# External address to advertise for TURN relay (default automatic)
#external=X.Y.Z.W

# TURN credentials with optional quota (default none)
credentials=user:password
#quota=50
#credentials=user2:pass2
#quota=60

# Global maximum number of allocations
#max=1024

Thank you for saying it's related to the logging, the program does not crash with the log-level=warning. For now I'll use this as a workaround. ^^'

If I can do more useful quick tests to find the issue, ask me please.

paullouisageneau commented 3 years ago

I forgot to say, you have to pull the change then update the libjuice submodule with git submodule update, as git won't do it automatically. Did you do the update?

peclatj commented 3 years ago

Ah, sorry you are right, I forgot to update the submodule, thank you again :D It works in log-level=debug.

Merci et bonne journée :)

paullouisageneau commented 3 years ago

Parfait, bonne journée :)