[CRASH] Using TCP traffic

[adigeo]

OpenSIPS version you are running

version: opensips 3.1.1 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, Q_MALLOC, F_MALLOC, HP_MALLOC, DBG_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 7ce3a4688
main.c compiled on  with gcc 8

Crash Core Dump
agp@live01:~$ sudo gdb /usr/sbin/opensips /cores/core.8812.opensips.1617699922
GNU gdb (Debian 8.2.1-2+b3) 8.2.1

Reading symbols from /usr/sbin/opensips...Reading symbols from /usr/lib/debug/.build-id/82/e390634b674192db657b546b1bf9603d7f7f74.debug...done.
done.
[New LWP 8812]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/opensips -w /run/opensips -P opensips.pid -a F_MALLOC_DBG -m 2048'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00007fefe06ba535 in __GI_abort () at abort.c:79
#2 0x000055b4f9fc2c9e in build_res_buf_from_sip_res (msg=msg@entry=0x55b4faaa3850, returned_len=returned_len@entry=0x7ffe921e8f04,
sock=, flags=flags@entry=0) at msg_translator.c:2419
#3 0x00007fef5f5e0a2d in relay_reply (t=0x7fef6244ff38, p_msg=, branch=0, msg_status=200, cancel_bitmap=0x7ffe921e8ff4)
at t_reply.c:1282
#4 0x00007fef5f5e2fad in reply_received (p_msg=0x55b4faaa3850) at t_reply.c:1647
#5 0x000055b4f9ff4438 in forward_reply (msg=msg@entry=0x55b4faaa3850) at forward.c:499
#6 0x000055b4f9fdd027 in receive_msg (
buf=0x55b4fab0db70 "SIP/2.0 200 Answering\r\nRecord-Route: sip:81.23.228.180;transport=tcp;lr;ftag=qpgpaa4f;did=58.e1a04a36\r\nVia: SIP/2.0/TCP 81.23.228.180:5060;branch=z9hG4bK9b09.9fe768.0;i=0228483\r\nVia: SIP/2.0/TCP 194"..., len=, len@entry=1541,
rcv_info=rcv_info@entry=0x7ffe921e9260, existing_context=existing_context@entry=0x0, msg_flags=msg_flags@entry=0) at receive.c:266
#7 0x000055b4fa141785 in tcp_handle_req (_max_msg_chunks=, con=0x7fef61e200f8, req=0x55b4fab0db70)
at net/proto_tcp/tcp_common.h:411
#8 tcp_read_req (con=, bytes_read=0x7ffe921e9320) at net/proto_tcp/proto_tcp.c:1197
#9 0x000055b4fa12185a in handle_io (fm=, idx=idx@entry=25, event_type=event_type@entry=1) at net/net_tcp_proc.c:312
#10 0x000055b4fa123b91 in io_wait_loop_epoll (h=, t=, repeat=) at net/../io_wait_loop.h:305
#11 tcp_worker_proc_loop () at net/net_tcp_proc.c:422
#12 0x000055b4fa133eab in tcp_start_processes (chd_rank=chd_rank@entry=0x55b4fa3135a8 <chd_rank>, startup_done=startup_done@entry=0x7fef61b686c8)
at net/net_tcp.c:2088
#13 0x000055b4f9fb2813 in main_loop () at main.c:810
#14 main (argc=, argv=) at main.c:1491

Describe the traffic that generated the bug

To Reproduce

Relevant System Logs

OS/environment information

• Operating System: `Debian Buster
• OpenSIPS installation:
• other relevant information:

Additional context

[adigeo]

Another one:

agp@live01:~$ sudo gdb /usr/sbin/opensips /cores/core.8789.opensips.1617699937
Reading symbols from /usr/sbin/opensips...Reading symbols from /usr/lib/debug/.build-id/82/e390634b674192db657b546b1bf9603d7f7f74.debug...done.
done.
[New LWP 8789]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/opensips -w /run/opensips -P opensips.pid -a F_MALLOC_DBG -m 2048'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x000055b4fa139710 in tcp_conn_clean (c=0x7fef61fcf9a8) at net/proto_tcp/proto_tcp.c:318
318 net/proto_tcp/proto_tcp.c: No such file or directory.
(gdb) bt
#0 0x000055b4fa139710 in tcp_conn_clean (c=0x7fef61fcf9a8) at net/proto_tcp/proto_tcp.c:318
#1 0x000055b4fa129008 in _tcpconn_rm (c=0x7fef61fcf9a8) at net/net_tcp.c:741
#2 0x000055b4fa132714 in __tcpconn_lifetime (force=1) at net/net_tcp.c:1620
#3 tcp_destroy () at net/net_tcp.c:1823
#4 0x000055b4fa048e3e in cleanup (show_status=show_status@entry=1) at main.c:368
#5 0x000055b4fa049667 in shutdown_opensips (status=status@entry=134) at main.c:530
#6 0x000055b4fa049d63 in handle_sigs () at main.c:613
#7 0x000055b4f9fb2c0c in main_loop () at main.c:870
#8 main (argc=, argv=) at main.c:1491
(gdb)

[adigeo]

agp@live01:~$ sudo gdb /usr/sbin/opensips /cores/core.8498.opensips.1617698993
GNU gdb (Debian 8.2.1-2+b3) 8.2.1

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/opensips...Reading symbols from /usr/lib/debug/.build-id/82/e390634b674192db657b546b1bf9603d7f7f74.debug...done.
done.
[New LWP 8498]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/opensips -w /run/opensips -P opensips.pid -a F_MALLOC_DBG -m 2048'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00007fc13ab92535 in __GI_abort () at abort.c:79
#2 0x0000565377ab8c9e in build_res_buf_from_sip_res (msg=msg@entry=0x5653791556d0, returned_len=returned_len@entry=0x7fff3e0c3524,
sock=, flags=flags@entry=0) at msg_translator.c:2419
#3 0x00007fc0b9ab8a2d in relay_reply (t=0x7fc0bc8a73b8, p_msg=, branch=0, msg_status=200, cancel_bitmap=0x7fff3e0c3614)
at t_reply.c:1282
#4 0x00007fc0b9abafad in reply_received (p_msg=0x5653791556d0) at t_reply.c:1647
#5 0x0000565377aea438 in forward_reply (msg=msg@entry=0x5653791556d0) at forward.c:499
#6 0x0000565377ad3027 in receive_msg (
buf=0x565377e2faa0 <tcp_current_req> "SIP/2.0 200 Answering\r\nRecord-Route: sip:81.23.228.180;transport=tcp;lr;ftag=242lqdqf;did=4a.d2b18521\r\nRecord-Route: sip:195.98.238.24;transport=tcp;lr=on\r\nVia: SIP/2.0/TCP 81.23.228.180:5060;bran"..., len=, len@entry=1750,
rcv_info=rcv_info@entry=0x7fff3e0c3880, existing_context=existing_context@entry=0x0, msg_flags=msg_flags@entry=0) at receive.c:266
#7 0x0000565377c37785 in tcp_handle_req (_max_msg_chunks=, con=0x7fc0bc445d20, req=0x565377e2faa0 <tcp_current_req>)
at net/proto_tcp/tcp_common.h:411
#8 tcp_read_req (con=, bytes_read=0x7fff3e0c3940) at net/proto_tcp/proto_tcp.c:1197
#9 0x0000565377c1785a in handle_io (fm=, idx=idx@entry=17, event_type=event_type@entry=1) at net/net_tcp_proc.c:312
#10 0x0000565377c19b91 in io_wait_loop_epoll (h=, t=, repeat=) at net/../io_wait_loop.h:305
#11 tcp_worker_proc_loop () at net/net_tcp_proc.c:422
#12 0x0000565377c29eab in tcp_start_processes (chd_rank=chd_rank@entry=0x565377e095a8 <chd_rank>, startup_done=startup_done@entry=0x7fc0bc01f9e0)
at net/net_tcp.c:2088
#13 0x0000565377aa8813 in main_loop () at main.c:810
#14 main (argc=, argv=) at main.c:1491

[bogdan-iancu]

@adigeo , you should have in the logs something like "len mismatch : calculated XX, written YY", right at the crash time - do you see it?
Also, do you still have the corefiles for investigation? The abort is triggered by some issue when applying the changes over that sip 200 reply, so we may iterate on the lump list. BTW, what kind of changes do you do over that 200 reply in script?

[adigeo]

Yes. I do have the core files.

"len mismatch : calculate" does not appear in the journal.

The logs before the crash for core.8498.opensips.1617698993:

agp@live01:~$ ls -lh /cores/core.8498.opensips.1617698993
-rw------- 1 opensips opensips 2.1G Apr  6 10:50 /cores/core.8498.opensips.1617698993

Apr 06 10:50:09 live01 /usr/sbin/opensips[8500]: [CONFIG] Asking NoAuth@sipfone.net for credentials (8-2_Eac5eV3Q-C-jm5eGug..)
Apr 06 10:50:09 live01 /usr/sbin/opensips[8487]: ERROR:core:parse_first_line: bad request first line
Apr 06 10:50:09 live01 /usr/sbin/opensips[8487]: ERROR:core:parse_first_line: at line 0 char 20:
Apr 06 10:50:09 live01 /usr/sbin/opensips[8487]: [64B blob data]
Apr 06 10:50:09 live01 /usr/sbin/opensips[8487]: ERROR:core:parse_msg: message=<>
Apr 06 10:50:09 live01 /usr/sbin/opensips[8487]: ERROR:core:receive_msg: Unable to parse msg received from [27.95.14.76:12441]
Apr 06 10:50:09 live01 systemd[1]: check_mk@38306-81.23.228.180:6556-85.17.186.22:48250.service: Succeeded.
Apr 06 10:50:10 live01 snmpd[6385]: Cannot statfs /sys/kernel/debug/tracing: Permission denied
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: [CONFIG] INVITE CALL from sip:NoAuth@andymacprod.com to sip:851011442032876136@andymacprod.com via local user tls:195.154.1
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: ERROR:tls_mgm:get_cert: failed to get certificate from SSL structure
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: [CONFIG] INVITE sip:851011442032876136@andymacprod.com audio CALL from sip:NoAuth@andymacprod.com to sip:851011442032876136
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: [CONFIG] Asking NoAuth@andymacprod.com for credentials (21gdgSRtxJciPyptmnj6Ng..)
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: [CONFIG] INVITE CALL from sip:NoAuth@andymacprod.com to sip:851011442032876136@andymacprod.com via local user tls:195.154.1
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: ERROR:tls_mgm:get_cert: failed to get certificate from SSL structure
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: [CONFIG] INVITE sip:851011442032876136@andymacprod.com audio CALL from sip:NoAuth@andymacprod.com to sip:851011442032876136
Apr 06 10:50:10 live01 /usr/sbin/opensips[8497]: [CONFIG] Asking NoAuth@andymacprod.com for credentials (21gdgSRtxJciPyptmnj6Ng..)
Apr 06 10:50:11 live01 /usr/sbin/opensips[8478]: CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1062): Duplicate entry '3034389912770936501' for key 'PR
Apr 06 10:50:11 live01 /usr/sbin/opensips[8478]: ERROR:usrloc:db_insert_ucontact: inserting contact in db failed
Apr 06 10:50:11 live01 /usr/sbin/opensips[8478]: ERROR:usrloc:wb_timer: inserting contact into database failed
Apr 06 10:50:11 live01 /usr/sbin/opensips[8478]: CRITICAL:core:sig_usr: segfault in attendant (starter) process!
Apr 06 10:50:15 live01 collectd[112]: statvfs(/sys/kernel/debug/tracing) failed: Permission denied
Apr 06 10:50:25 live01 collectd[112]: statvfs(/sys/kernel/debug/tracing) failed: Permission denied
Apr 06 10:50:32 live01 sshd[8772]: Invalid user franbella from 154.8.232.15 port 33144
Apr 06 10:50:32 live01 sshd[8772]: pam_unix(sshd:auth): check pass; user unknown
Apr 06 10:50:32 live01 sshd[8772]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=154.8.232.15
Apr 06 10:50:33 live01 systemd[1]: opensips.service: Main process exited, code=dumped, status=11/SEGV
Apr 06 10:50:33 live01 systemd[1]: opensips.service: Failed with result 'core-dump'.

I have to check about the script logic and get back with this info.

[adigeo]

Found the logs:

Apr 06 10:45:27 live01 /usr/sbin/opensips[10762]: CRITICAL:core:build_res_buf_from_sip_res:
>>> len mismatch : calculated 1644, written 1622

                                              It seems you have hit a programming bug.
                                              Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues

[adigeo]

I found the script actions for on reply route:

onreply_route[INVITE_REPLY] {
        if ($hdr(Contact) and $hdr(Record-Route)) {
            $var(rr_host) = $(hdr(Record-Route){s.select,0,,}{nameaddr.uri}{uri.host});
            if (is_myself($var(rr_host)) and client_nat_test(1)) {
                fix_contact();
            }
        }
}

the packet after which it stopped:

  msg: SIP/2.0 200 Answering
Record-Route: 
Record-Route: 
Via: SIP/2.0/TCP 81.23.228.180:5060;branch=z9hG4bK994a.ecd97124.0;i=5f581064
Via: SIP/2.0/TCP 195.98.238.24;branch=z9hG4bK994a.42ca70d2.0;i=30572
Via: SIP/2.0/TCP 194.57.1.132:5080;branch=z9hG4bKfhbcffblhhgl2adq4bbcq50j5;rport=5080
Call-ID: 55bajdqffjgldqcbh22jpcalce2j45jp@194.57.1.132
From: "RENATER-PARIS-703";tag=bfcbh5fq;epid=55555555
To: ;tag=ef17e2ca002be8cf
CSeq: 2 INVITE
Server: baresip v1.0.0 (x86_64/linux)
Contact: <sip:dmo-0x5581a400a340@192.168.1.99:40426;transport=tcp>
Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,REFER
Content-Type: application/sdp
Content-Length: 798

v=0
o=- 1486526008 1569335721 IN IP4 192.168.1.99
s=-
c=IN IP4 192.168.1.99
t=0 0
a=tool:baresip 1.0.0
m=audio 7544 RTP/AVP 9 0 8 97
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 telephone-event/8000
a=fmtp:97 0-15
a=sendrecv
a=label:1
a=ssrc:191614282 cname:sip:dmo@sip2sip.info
a=minptime:20
a=ptime:20
m=video 3206 RTP/AVP 107 34 105
a=rtpmap:107 H264/90000
a=fmtp:107 packetization-mode=0;profile-level-id=42e01f
a=rtpmap:34 H263/90000
a=fmtp:34 CIF=1;CIF4=1
a=rtpmap:105 H264/90000
a=fmtp:105 packetization-mode=1;profile-level-id=42e01f
a=sendrecv
a=label:2
a=ssrc:1510685591 cname:sip:dmo@sip2sip.info
a=framerate:30.00
a=rtcp-fb:* nack pli
a=content:main
m=application 0 TCP/BFCP 0
m=application 0 RTP/AVP 0
m=video 0 RTP/AVP 0

     method: INVITE
     status: 200
 from_proto: tcp
    from_ip: 77.133.223.243
  from_port: 40426
   to_proto: tcp
      to_ip: 81.23.228.180
    to_port: 5060
    fromtag: bfcbh5fq
  direction: in

The Contact look a bit strange....

[bogdan-iancu]

any chances to get access to a machine were I can explore the core file ?

[adigeo]

Yes, please send your ssh public key to support@ag-projects.com

[adigeo]

We installed the key, details sent by email

[adigeo]

By changing F_MALLOC_DBG to Q_MALLOC_DBG the crashes still happen but much less often.

Last one:

Core was generated by `/usr/sbin/opensips -w /run/opensips -P opensips.pid -a Q_MALLOC_DBG -m 2048'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00005619fbe7e710 in tcp_conn_clean (c=0x7f94b99b6ea0) at net/proto_tcp/proto_tcp.c:318
318	net/proto_tcp/proto_tcp.c: No such file or directory.
(gdb) bt
#0  0x00005619fbe7e710 in tcp_conn_clean (c=0x7f94b99b6ea0) at net/proto_tcp/proto_tcp.c:318
#1  0x00005619fbe6e008 in _tcpconn_rm (c=c@entry=0x7f94b99b6ea0) at net/net_tcp.c:741
#2  0x00005619fbe74142 in handle_new_connect (si=<optimized out>) at net/net_tcp.c:1098
#3  handle_io (fm=<optimized out>, idx=idx@entry=0, event_type=event_type@entry=1) at net/net_tcp.c:1530
#4  0x00005619fbe7641b in io_wait_loop_epoll (h=<optimized out>, t=<optimized out>, repeat=<optimized out>) at net/../io_wait_loop.h:305
#5  tcp_main_server () at net/net_tcp.c:1707
#6  0x00005619fbe793f9 in tcp_start_listener () at net/net_tcp.c:2126
#7  0x00005619fbcf7a4c in main_loop () at main.c:822
#8  main (argc=<optimized out>, argv=<optimized out>) at main.c:1491

[stale]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[github-actions]

Marking as closed due to lack of progress for more than 30 days. If this issue is still relevant, please re-open it with additional details.