search

SIPp / sipp

The SIPp testing tool
https://sipp.readthedocs.io
Other
919 stars 380 forks source link

Segfault: 3pcc with optional first recv makes sendMode schizofrenic #493

Open sharkwsk opened 4 years ago

sharkwsk commented 4 years ago

I am trying to establish a basic call scenario

I am using 3pcc scenario for a "register and wait for INVITE" for B party However when the sendCmd is sends the trigger, the B party scenario crashes with "segmentation fault"

Have attached all the scenarios (A party, B party, 3PCC trigger to B party scenario) scenarios.zip

Version: SIPp v3.7-dev-9-ga284f3a-PCAP-RTPSTREAM-RTPCHECK

sharkwsk commented 4 years ago

Any feedback on this issue ?

wdoekes commented 4 years ago

It's good that you're asking attention for bugs.

But, the amount of time we can dedicate to this differs wildly. Any additional info you can get on your own, helps.

Add -g -O0 and try to get a backtrace from gdb:

$ cmake -DDEBUG=1 [optional other args..] .
$ make
$ gdb ./sipp
(gdb) run [arguments to sipp...]

When it crashes, you can do bt and bt full and info locals and all sorts of nice debug stuff.

sharkwsk commented 4 years ago

Thanks for your feedback, and apologies for my ignorance. I am pretty novice when it comes to debugging C/C++ applications :(

I managed to recompile with deubg option and run with gdb, here is the details. Note that I have masked the IPs for obvious reasons

Starting program: /home/sipp/sipp_full 10.10.10.1 -3pcc 192.168.1.1:9001 -i 10.10.10.1 -p 5060 -nd -t t1 -sf ./receive.xml -inf ./B_user.csv -trace_msg

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".

Program received signal SIGSEGV, Segmentation fault.
0x0000555555631bdd in process_message(SIPpSocket*, char*, long, sockaddr_storage*) ()
#0  0x0000555555631bdd in process_message(SIPpSocket*, char*, long, sockaddr_storage*) ()
#1  0x0000555555637222 in SIPpSocket::pollset_process(int) ()
#2  0x000055555564cacb in traffic_thread(int&, int&) ()
#3  0x0000555555651441 in main ()
#0  0x0000555555631bdd in process_message(SIPpSocket*, char*, long, sockaddr_storage*) ()
#1  0x0000555555637222 in SIPpSocket::pollset_process(int) ()
#2  0x000055555564cacb in traffic_thread(int&, int&) ()
#3  0x0000555555651441 in main ()
sharkwsk commented 3 years ago

I could not make much of the debug messages, Is it related to some socket connectivity issues ?

wdoekes commented 3 years ago

Me neither. It looks as if the -g didn't quite stick. We should at least see filenames and linenumbers in that backtrace.

sharkwsk commented 3 years ago

I did the following

  1. Re-build sipp after adding -DDEBUG=1 flag on top of the --full section in build.sh script

  2. Executed below for B party gdb ./sipp set logging on run 10.10.10.1 -3pcc 192.168.1.1:9001 -i 10.10.10.1 -p 5060 -nd -t t1 -sf ./receive.xml -inf ./B_user.csv -trace_msg bt bt full info locals

  3. Executed the Aparty using another script

Am I doing anything obviously wrong :(

wdoekes commented 3 years ago

Not something obvious, no.

$ make VERBOSE=1
...

Look for -g in the c++ commands.

Or do:

$ touch src/*.cpp; make VERBOSE=1 2>&1 | grep --color=yes -- -g

The binary should have lots of debug symbols (and therefore be big):

$ ls -lh sipp
-rwxrwxr-x 1 walter walter 6.4M okt 19 11:32 sipp

$ gdb ./sipp
...
(gdb) print process_message
$1 = {void (SIPpSocket *, char *, ssize_t, sockaddr_storage *)} 0xe517a <process_message(SIPpSocket*, char*, long, sockaddr_storage*)>
(gdb) quit
$ addr2line -Cfe ./sipp 0xe517a
process_message(SIPpSocket*, char*, long, sockaddr_storage*)
sipp/src/socket.cpp:1102
sharkwsk commented 3 years ago

Here is the revised gdb log

Starting program: /home/sipp/sipp_full 10.10.10.1 -3pcc 192.168.1.1:9001 -i 10.10.10.1 -p 5060 -nd -t t1 -sf ./receive.xml -inf ./B_user.csv -trace_msg [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".

Program received signal SIGSEGV, Segmentation fault. 0x0000555555631bdd in process_message (socket=0x555555b74be0, msg=0x7ffffffbdbe0 "Call-ID: 1-2457@127.0.0.1\r\nContact: sip:+33471000010@127.0.0.1:48568;transport=UDP\r\nUser-Agent: SIPp\r\n\r\n", msg_size=113, src=0x7ffffffbdb60) at /root/sipp/sipp/src/socket.cpp:1170 1170 /root/sipp/sipp/src/socket.cpp: No such file or directory. $1 = {void (SIPpSocket , char , ssize_t, sockaddr_storage )} 0x5555556317ce <process_message(SIPpSocket, char, long, sockaddr_storage)>

addr2line -Cfe ./sipp 0x5555556317ce

?? ??:0

sharkwsk commented 3 years ago

I was trying to check the socket.cpp file existing under src directory and it is. So I am not sure what is the actual fault of this error

src=0x7ffffffbdb60) at /root/sipp/sipp/src/socket.cpp:1170 1170 /root/sipp/sipp/src/socket.cpp: No such file or directory.

wdoekes commented 3 years ago

Well.. that line is probably correct, 1170 in socket.cpp.

But you're really only giving us minimal info.

info locals and bt and bt full would give a lot more.

With 1170, we know that:

                    case T_TLS:
                        new_ptr->associate_socket(tcp_multiplex);
                        tcp_multiplex->ss_count++;            /* 1170: it crashes here */
                        break;
                    }

And that's because tcp_multiplex is bad. But we don't know in what kind of bad state it is. It is probably NULL (0x0), but we cannot tell from just the words Segmentation fault.

Help us help yourself.

sharkwsk commented 3 years ago

Apologies again, I will try my best to get the necessary logs. I have re-run with above commands and logs again... If any further info needed, do let me know how I could extract them. I am more than happy to re-run the test

Program received signal SIGSEGV, Segmentation fault.
                                                    0x0000555555631bdd in process_message (socket=0x555555b74be0, msg=0x7ffffffbdbe0 "Call-ID: 1-15555@127.0.0.1\r\nContact: <sip:+33471000010@127.0.0.1:36526;transport=UDP>\r\nUser-Agent: SIPp\r\n\r\n", msg_size=114, 
    src=0x7ffffffbdb60) at /root/sipp/sipp/src/socket.cpp:1170
1170    /root/sipp/sipp/src/socket.cpp: No such file or directory.
(gdb) bt
#0  0x0000555555631bdd in process_message (socket=0x555555b74be0, msg=0x7ffffffbdbe0 "Call-ID: 1-15555@127.0.0.1\r\nContact: <sip:+33471000010@127.0.0.1:36526;transport=UDP>\r\nUser-Agent: SIPpTester\r\n\r\n", msg_size=114, 
    src=0x7ffffffbdb60) at /root/sipp/sipp/src/socket.cpp:1170
#1  0x0000555555637222 in SIPpSocket::pollset_process (wait=1) at /root/sipp/sipp/src/socket.cpp:2995
#2  0x000055555564cacb in traffic_thread (rtp_errors=@0x7fffffffdd98: 0, echo_errors=@0x7fffffffdd9c: 0) at /root/sipp/sipp/src/sipp.cpp:601
#3  0x0000555555651441 in main (argc=16, argv=0x7fffffffe268) at /root/sipp/sipp/src/sipp.cpp:2161
(gdb) bt full
#0  0x0000555555631bdd in process_message (socket=0x555555b74be0, msg=0x7ffffffbdbe0 "Call-ID: 1-15555@127.0.0.1\r\nContact: <sip:+33471000010@127.0.0.1:36526;transport=UDP>\r\nUser-Agent: SIPpTester\r\n\r\n", msg_size=114, 
    src=0x7ffffffbdb60) at /root/sipp/sipp/src/socket.cpp:1170
        new_ptr = 0x555555b75d10
        call_id = 0x5555558f0660 <get_call_id(char const*)::call_id> "1-15555@127.0.0.1"
        listener_ptr = 0x0
        currentTime = {tv_sec = 1603358235, tv_usec = 457858}
#1  0x0000555555637222 in SIPpSocket::pollset_process (wait=1) at /root/sipp/sipp/src/socket.cpp:2995
        msg = <error reading variable msg (value requires 262144 bytes, which is more than max-value-size)>
        src = {ss_family = 0, __ss_padding = '\000' <repeats 117 times>, __ss_align = 0}
        len = 114
        sock = 0x555555b74be0
        ret = 114
        old_pollnfds = 4
        poll_idx = 3
        events = 1
        event_idx = 0
        rs = 1
        __PRETTY_FUNCTION__ = "static void SIPpSocket::pollset_process(int)"
#2  0x000055555564cacb in traffic_thread (rtp_errors=@0x7fffffffdd98: 0, echo_errors=@0x7fffffffdd9c: 0) at /root/sipp/sipp/src/sipp.cpp:601
        running_tasks = 0x555555a71200 <running_tasks[abi:cxx11]>
        loops = 1000
        last = 0x0
        iter = 0x1
        L_file_name = "receivereg_15547_screen.log\000\000\000\000\000\000\022\247U\020\000\000\000\a\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\200\000\256UUU\000\000 \001\000\000\000\000\000\000\220\377\377\377\377\377\377\377\004\000\000\000\000\000\000\000\020\000\000\000\064", '\000' <repeats 27 times>, "|\000\000\000w\000\000\000n\000\000\000[", '\000' <repeats 19 times>, "\370\000\000\000\000\000\000\000\220\377\377\377\377\377\377\377\v\000\000\000\000\000\000\000`\342\377\377\377\177", '\000' <repeats 18 times>...
        __PRETTY_FUNCTION__ = <optimised out>
#3  0x0000555555651441 in main (argc=16, argv=0x7fffffffe268) at /root/sipp/sipp/src/sipp.cpp:2161
        argi = 16
        pthread2_id = 0
        pthread3_id = 0
        generic_count = 0
        slave_masterSet = false
        rtp_errors = 0
        echo_errors = 0
        __PRETTY_FUNCTION__ = "int main(int, char**)"
(gdb) info locals
argi = 16
pthread2_id = 0
pthread3_id = 0
generic_count = 0
slave_masterSet = false
rtp_errors = 0
echo_errors = 0
__PRETTY_FUNCTION__ = "int main(int, char**)"
(gdb) 
argi = 16
pthread2_id = 0
pthread3_id = 0
generic_count = 0
slave_masterSet = false
rtp_errors = 0
echo_errors = 0
__PRETTY_FUNCTION__ = "int main(int, char**)"
(gdb) print process_message
$1 = {void (SIPpSocket *, char *, ssize_t, sockaddr_storage *)} 0x5555556317ce <process_message(SIPpSocket*, char*, long, sockaddr_storage*)>
(gdb) quit
A debugging session is active.

        Inferior 1 [process 15547] will be killed.

Quit anyway? (y or n) y
# addr2line -Cfe ./sipp 0x5555556317ce
??
??:0
sharkwsk commented 3 years ago

Any findings based on the above logs. I could read below messages related to size, is there any maximum limit my message is exceeding and causing the crash ?

error reading variable msg (value requires 262144 bytes, which is more than max-value-size

sharkwsk commented 3 years ago

@wdoekes - Any hints on what I could check and try. Unfortunately I am not that familiar with SIPp code to try things out...

Thanks

wdoekes commented 3 years ago

So, I tried to spend a little time on this now.

But I found:

.. faith .. humanity ..

I hate to sound disappointed, but again: if you want our help, you need to make it possible for us to help you.

Please: (a) add all files we need to reproduce this (b) describe all steps we need to reproduce this (c) ensure we can reproduce this on localhost, without conjuring up 10.x and 192.x networks

sharkwsk commented 3 years ago

Happy to share the actual files and commands one-to-one via an email if possible....

wdoekes commented 3 years ago

So, you're saying it's hard to reproduce with generic (non-private) details?

sharkwsk commented 3 years ago

No, it can be reproduced all the time. Issue is the IPs and specific system specific details, I am unable to share over public forum unless I mask it

sharkwsk commented 3 years ago

Here is the revised logs with scenario & input files (again screened for actual IPs) test2.zip

wdoekes commented 3 years ago

Minimal test case recv.xml:

<?xml version="1.0" encoding="ISO-8859-1"?>
<scenario>
<recv request="INFO" optional="true"/>
<recvCmd/>
<send>
<![CDATA[
  SIP/2.0 501 Problem
  From: <sip:[service]@127.0.0.1>;tag=[call_number]
  To: <sip:[service]@127.0.0.1>
  Call-ID: [call_id]
  CSeq: [cseq] INFO 
  Content-Length: 0
]]>
</send>
</scenario>

send.xml:

<?xml version="1.0" encoding="ISO-8859-1"?>
<scenario>
<send>
<![CDATA[
  INFO sip:whatever SIP/2.0
  From: <sip:[service]@127.0.0.1>;tag=[call_number]
  To: <sip:[service]@127.0.0.1>
  Call-ID: [call_id]
  CSeq: [cseq] INFO 
  Content-Length: 0
]]>
</send>
<sendCmd>
<![CDATA[
  Call-ID: [call_id]
]]>
</sendCmd>
</scenario>

Exec:

./sipp -m 1 -sf recv.xml -3pcc 127.0.0.1:9001 -t t1
./sipp -m 1 -sf send.xml -3pcc 127.0.0.1:9001 -t t1 google.com:80

GDB:

(gdb) bt
#0  0x000055555563959d in process_message (socket=0x55555599b8c0, msg=0x7ffffffed650 "call-id: 1-153060@127.0.0.1\r\ninternal-cmd: abort_call\r\n\r\n", msg_size=58, src=0x7ffffffed5d0)
    at /home/walter/src/sipp/src/socket.cpp:1170
#1  0x000055555563ed13 in SIPpSocket::pollset_process (wait=1) at /home/walter/src/sipp/src/socket.cpp:2995
#2  0x00005555556561ca in traffic_thread (rtp_errors=@0x7fffffffd7f8: 0, echo_errors=@0x7fffffffd7fc: 0) at /home/walter/src/sipp/src/sipp.cpp:601
#3  0x000055555565abdb in main (argc=9, argv=0x7fffffffdcd8) at /home/walter/src/sipp/src/sipp.cpp:2161
(gdb) list
1165                            break;
1166                        case T_TCP:
1167                        case T_SCTP:
1168                        case T_TLS:
1169                            new_ptr->associate_socket(tcp_multiplex);
1170                            tcp_multiplex->ss_count++;
1171                            break;
1172                        }
1173                    }
1174                }
(gdb) print tcp_multiplex
$1 = (SIPpSocket *) 0x0

Looks like tcp_multiplex hasn't been initialized. I assume the problem goes away if you use -t tn instead of -t t1 (or use udp mode).

Bug appears to be in:

wdoekes commented 3 years ago

Ok, for -t tn you're in trouble elsehwere:

(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007ffff73c4859 in __GI_abort () at abort.c:79
#2  0x00007ffff73c4729 in __assert_fail_base (fmt=0x7ffff755a588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55555567a219 "false", 
    file=0x55555567a1f0 "/home/walter/src/sipp/include/socket.hpp", line=48, function=<optimized out>) at assert.c:92
#3  0x00007ffff73d5f36 in __GI___assert_fail (assertion=0x55555567a219 "false", file=0x55555567a1f0 "/home/walter/src/sipp/include/socket.hpp", line=48, 
    function=0x55555567a1b8 "socklen_t socklen_from_addr(const sockaddr_storage*)") at assert.c:101
#4  0x000055555563f024 in socklen_from_addr (ss=0x55555599f7a0) at /home/walter/src/sipp/include/socket.hpp:48
#5  0x000055555563a7c8 in SIPpSocket::connect (this=0x55555599f770, dest=0x555555883020 <remote_sockaddr>) at /home/walter/src/sipp/src/socket.cpp:1559
#6  0x00005555555d2cc5 in call::connect_socket_if_needed (this=0x55555599b9c0) at /home/walter/src/sipp/src/call.cpp:1387
#7  0x00005555555d387f in call::send_scene (this=0x55555599b9c0, index=2, send_status=0x7fffffffd5b8, len=0x7fffffffd5b4) at /home/walter/src/sipp/src/call.cpp:1634
#8  0x00005555555d4b98 in call::executeMessage (this=0x55555599b9c0, curmsg=0x5555558a2150) at /home/walter/src/sipp/src/call.cpp:1950
#9  0x00005555555d5cd1 in call::run (this=0x55555599b9c0) at /home/walter/src/sipp/src/call.cpp:2221
#10 0x000055555565611c in traffic_thread (rtp_errors=@0x7fffffffd7d8: 0, echo_errors=@0x7fffffffd7dc: 0) at /home/walter/src/sipp/src/sipp.cpp:591
#11 0x000055555565abdb in main (argc=11, argv=0x7fffffffdcb8) at /home/walter/src/sipp/src/sipp.cpp:2161
(gdb) up 4
#4  0x000055555563f024 in socklen_from_addr (ss=0x55555599f7a0) at /home/walter/src/sipp/include/socket.hpp:48
48          assert(false);
(gdb) list
43      if (ss->ss_family == AF_INET) {
44          return sizeof(struct sockaddr_in);
45      } else if (ss->ss_family == AF_INET6) {
46          return sizeof(struct sockaddr_in6);
47      } else {
48          assert(false);
49          return 0;
50      }
51  }
52  
(gdb) print ss
$1 = (const sockaddr_storage *) 0x55555599f7a0
(gdb) print ss->ss_family
$2 = 0
(gdb) print *ss
$3 = {ss_family = 0, __ss_padding = '\000' <repeats 117 times>, __ss_align = 0}
wdoekes commented 3 years ago

I can't tell what scenario you're trying to achieve. But for now, that combination of optional-recv and recvCmd will not work.

The receivereg.xml scenario you have should either be a client-scenario (start with a send) or a server-scenario (start with a recv). If you have both, like you do know, things will go wrong -- as you have noticed.

sharkwsk commented 3 years ago

Ok, I modified the receivereg.xml to start like this. Same crash occurs

<scenario name="UAS receiver">

  <!-- Receive the invite message -->
  <!-- ================================================================== -->

<recvCmd next="sendregister">
</recvCmd>

<recv request="INVITE" next="registrationsuccessful">
    <action>
      <!-- Analyse the message -->
      <!-- =================== -->
        <ereg regexp=".*" search_in="hdr" header="Via:" check_it="true" assign_to="2" occurrence="1"/>
        <ereg regexp=".*" search_in="hdr" header="Record-Route:" check_it="true" assign_to="4" occurrence="1"/>
    </action>
</recv>

<label id="sendregister"/>
..
..

What I would like to achieve is fairly simple use case

Initially, I was referring to below post and preparing for the scenario described there - 3PCC scenario with trigger messages to have some level of synchronization between A & B parties https://sourceforge.net/p/sipp/mailman/message/34707334/

wdoekes commented 3 years ago

Ok, I modified the receivereg.xml to start like this. Same crash occurs

Ok. You have managed to create another way to make the sendMode ambiguous. You didn't fix the underlying problem that SIPp starts in UAS mode and then you ask it to play UAC.

The sendMode is determined by the first <recv>/<send> that's encountered in the scenario: <recv> for UAS in your case. But you have found the <recvCmd/> loophole to make it skip that statement, and start with a <send> instead of a <recv>: while SIPp does not know where to send anything at that point, the <send>-code assumes it's already connected. The result is the segfaults you see.

If you intend on skipping the <recv>: remove that statement, and observe how SIPp will complain that you didn't specify any target to send to.

Missing remote host parameter. This scenario requires it
sharkwsk commented 3 years ago

Ok. I guess I am too obsessed to simulate the scenario that is described in that forum :) I will have to abandon that and see alternative ways to achieve my use case.

I know its not related to this issue, Is there any possibility to achieve below mentioned use case..

wdoekes commented 3 years ago

I know its not related to this issue, Is there any possibility to achieve below mentioned use case..

This is not the right place for those questions.

sharkwsk commented 3 years ago

Is there any forum for SIPp apart from SourceForge ? You may close this ticket