[asterisk-bugs] [JIRA] (ASTERISK-27371) Serious Network Trouble Errors with TCP Enabled

Wed Oct 25 11:59:21 CDT 2017

    [ https://issues.asterisk.org/jira/browse/ASTERISK-27371?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=239642#comment-239642 ] 

Richard Mudgett edited comment on ASTERISK-27371 at 10/25/17 11:59 AM:
-----------------------------------------------------------------------

So I let that run, and about an hour later, we got FRACKs and a crash, which are related to astobj2.c (like in our other thread here ASTERISK-27321), but not identical. We let debug run again a few hours later, replicating the FRACK and crash, but took a few more hours than the first crash.

Here's a link to the entire log (was far too big to upload): https://cloud.verticalcomputers.com/index.php/s/igDEHxLFcWnw6KV 

Here's a snip of it:

<--- Transmitting (NAT) to 47.145.213.138:5176 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.1.2:5176;branch=z9hG4bK-ff7f9fcb;received=47.145.213.138;rport=5176
From: <sip:303 at dubois.ringvertical.com>;tag=SP25fb38ba7f9fae97a
To: <sip:303 at dubois.ringvertical.com>;tag=as5424874d
Call-ID: 65c67b3c at 192.168.1.2
CSeq: 213162 REGISTER
Server: FPBX-13.0.192.19(13.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 60
Contact: <sip:303 at 47.145.213.138:5176;transport=tcp>;expires=60
Date: Wed, 25 Oct 2017 01:09:07 GMT
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog '65c67b3c at 192.168.1.2' in 32000 ms (Method: REGISTER)
Really destroying SIP dialog '231a334b31c9638b7979bfd5696944da at 23.187.0.112:57875' Method: OPTIONS

<--- SIP read from TCP:47.145.213.138:5176 --->
SIP/2.0 200 OK
Call-ID: 3f9a3b9065ea248c1f99eb074fb462f1 at 23.187.0.112:57875
CSeq: 102 OPTIONS
Content-Length: 0
From: "Unknown" <sip:Unknown at 23.187.0.112:57875>;tag=as4b7c1172
To: <sip:303 at 47.145.213.138:5176;transport=tcp>
Via: SIP/2.0/TCP 23.187.0.112:57875;branch=z9hG4bK67cde5df;received=0.62.224.144;rport=1

<------------->
--- (7 headers 0 lines) ---
[2017-10-24 18:09:07] NOTICE[3003]: chan_sip.c:30191 sip_poke_peer: Still have a QUALIFY dialog active, deleting
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
#0: [0x60614a] /usr/sbin/asterisk(__ast_assert_failed+0x88) [0x60614a]
#1: [0x45da45] /usr/sbin/asterisk() [0x45da45]
#2: [0x45dae3] /usr/sbin/asterisk() [0x45dae3]
#3: [0x45f0ef] /usr/sbin/asterisk(__ao2_unlink+0x20) [0x45f0ef]
#4: [0x7fbd88cb6c1e] /usr/lib64/asterisk/modules/chan_sip.so(+0x17c1e) [0x7fbd88cb6c1e]
#5: [0x7fbd88d3a0c6] /usr/lib64/asterisk/modules/chan_sip.so(+0x9b0c6) [0x7fbd88d3a0c6]
#6: [0x7fbd88cf486c] /usr/lib64/asterisk/modules/chan_sip.so(+0x5586c) [0x7fbd88cf486c]
#7: [0x5c23de] /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x5c23de]
#8: [0x7fbd88d38405] /usr/lib64/asterisk/modules/chan_sip.so(+0x99405) [0x7fbd88d38405]
#9: [0x602d4c] /usr/sbin/asterisk() [0x602d4c]
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
#0: [0x60614a] /usr/sbin/asterisk(__ast_assert_failed+0x88) [0x60614a]
#1: [0x45da45] /usr/sbin/asterisk() [0x45da45]
#2: [0x45dae3] /usr/sbin/asterisk() [0x45dae3]
#3: [0x45f0ef] /usr/sbin/asterisk(__ao2_unlink+0x20) [0x45f0ef]
#4: [0x7fbd88cb6c3c] /usr/lib64/asterisk/modules/chan_sip.so(+0x17c3c) [0x7fbd88cb6c3c]
#5: [0x7fbd88d3a0c6] /usr/lib64/asterisk/modules/chan_sip.so(+0x9b0c6) [0x7fbd88d3a0c6]
#6: [0x7fbd88cf486c] /usr/lib64/asterisk/modules/chan_sip.so(+0x5586c) [0x7fbd88cf486c]
#7: [0x5c23de] /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x5c23de]
#8: [0x7fbd88d38405] /usr/lib64/asterisk/modules/chan_sip.so(+0x99405) [0x7fbd88d38405]
#9: [0x602d4c] /usr/sbin/asterisk() [0x602d4c]
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
#0: [0x60614a] /usr/sbin/asterisk(__ast_assert_failed+0x88) [0x60614a]
#1: [0x45da45] /usr/sbin/asterisk() [0x45da45]
#2: [0x45dae3] /usr/sbin/asterisk() [0x45dae3]
#3: [0x45f0ef] /usr/sbin/asterisk(__ao2_unlink+0x20) [0x45f0ef]
#4: [0x7fbd88cb6c5a] /usr/lib64/asterisk/modules/chan_sip.so(+0x17c5a) [0x7fbd88cb6c5a]
#5: [0x7fbd88d3a0c6] /usr/lib64/asterisk/modules/chan_sip.so(+0x9b0c6) [0x7fbd88d3a0c6]
#6: [0x7fbd88cf486c] /usr/lib64/asterisk/modules/chan_sip.so(+0x5586c) [0x7fbd88cf486c]
#7: [0x5c23de] /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x5c23de]
#8: [0x7fbd88d38405] /usr/lib64/asterisk/modules/chan_sip.so(+0x99405) [0x7fbd88d38405]
#9: [0x602d4c] /usr/sbin/asterisk() [0x602d4c]
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
v12*CLI>
Disconnected from Asterisk server
Asterisk cleanly ending (0).
Executing last minute cleanups

was (Author: stevensedory):
So I let that run, and about an hour later, we got FRACKs and a crash, which are related to astobj2.c (like in our other thread here https://issues.asterisk.org/jira/browse/ASTERISK-27321), but not identical. We let debug run again a few hours later, replicating the FRACK and crash, but took a few more hours than the first crash.

Here's a link to the entire log (was far too big to upload): https://cloud.verticalcomputers.com/index.php/s/igDEHxLFcWnw6KV 

Here's a snip of it:

<--- Transmitting (NAT) to 47.145.213.138:5176 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.1.2:5176;branch=z9hG4bK-ff7f9fcb;received=47.145.213.138;rport=5176
From: <sip:303 at dubois.ringvertical.com>;tag=SP25fb38ba7f9fae97a
To: <sip:303 at dubois.ringvertical.com>;tag=as5424874d
Call-ID: 65c67b3c at 192.168.1.2
CSeq: 213162 REGISTER
Server: FPBX-13.0.192.19(13.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 60
Contact: <sip:303 at 47.145.213.138:5176;transport=tcp>;expires=60
Date: Wed, 25 Oct 2017 01:09:07 GMT
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog '65c67b3c at 192.168.1.2' in 32000 ms (Method: REGISTER)
Really destroying SIP dialog '231a334b31c9638b7979bfd5696944da at 23.187.0.112:57875' Method: OPTIONS

<--- SIP read from TCP:47.145.213.138:5176 --->
SIP/2.0 200 OK
Call-ID: 3f9a3b9065ea248c1f99eb074fb462f1 at 23.187.0.112:57875
CSeq: 102 OPTIONS
Content-Length: 0
From: "Unknown" <sip:Unknown at 23.187.0.112:57875>;tag=as4b7c1172
To: <sip:303 at 47.145.213.138:5176;transport=tcp>
Via: SIP/2.0/TCP 23.187.0.112:57875;branch=z9hG4bK67cde5df;received=0.62.224.144;rport=1

<------------->
--- (7 headers 0 lines) ---
[2017-10-24 18:09:07] NOTICE[3003]: chan_sip.c:30191 sip_poke_peer: Still have a QUALIFY dialog active, deleting
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
#0: [0x60614a] /usr/sbin/asterisk(__ast_assert_failed+0x88) [0x60614a]
#1: [0x45da45] /usr/sbin/asterisk() [0x45da45]
#2: [0x45dae3] /usr/sbin/asterisk() [0x45dae3]
#3: [0x45f0ef] /usr/sbin/asterisk(__ao2_unlink+0x20) [0x45f0ef]
#4: [0x7fbd88cb6c1e] /usr/lib64/asterisk/modules/chan_sip.so(+0x17c1e) [0x7fbd88cb6c1e]
#5: [0x7fbd88d3a0c6] /usr/lib64/asterisk/modules/chan_sip.so(+0x9b0c6) [0x7fbd88d3a0c6]
#6: [0x7fbd88cf486c] /usr/lib64/asterisk/modules/chan_sip.so(+0x5586c) [0x7fbd88cf486c]
#7: [0x5c23de] /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x5c23de]
#8: [0x7fbd88d38405] /usr/lib64/asterisk/modules/chan_sip.so(+0x99405) [0x7fbd88d38405]
#9: [0x602d4c] /usr/sbin/asterisk() [0x602d4c]
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
#0: [0x60614a] /usr/sbin/asterisk(__ast_assert_failed+0x88) [0x60614a]
#1: [0x45da45] /usr/sbin/asterisk() [0x45da45]
#2: [0x45dae3] /usr/sbin/asterisk() [0x45dae3]
#3: [0x45f0ef] /usr/sbin/asterisk(__ao2_unlink+0x20) [0x45f0ef]
#4: [0x7fbd88cb6c3c] /usr/lib64/asterisk/modules/chan_sip.so(+0x17c3c) [0x7fbd88cb6c3c]
#5: [0x7fbd88d3a0c6] /usr/lib64/asterisk/modules/chan_sip.so(+0x9b0c6) [0x7fbd88d3a0c6]
#6: [0x7fbd88cf486c] /usr/lib64/asterisk/modules/chan_sip.so(+0x5586c) [0x7fbd88cf486c]
#7: [0x5c23de] /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x5c23de]
#8: [0x7fbd88d38405] /usr/lib64/asterisk/modules/chan_sip.so(+0x99405) [0x7fbd88d38405]
#9: [0x602d4c] /usr/sbin/asterisk() [0x602d4c]
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
#0: [0x60614a] /usr/sbin/asterisk(__ast_assert_failed+0x88) [0x60614a]
#1: [0x45da45] /usr/sbin/asterisk() [0x45da45]
#2: [0x45dae3] /usr/sbin/asterisk() [0x45dae3]
#3: [0x45f0ef] /usr/sbin/asterisk(__ao2_unlink+0x20) [0x45f0ef]
#4: [0x7fbd88cb6c5a] /usr/lib64/asterisk/modules/chan_sip.so(+0x17c5a) [0x7fbd88cb6c5a]
#5: [0x7fbd88d3a0c6] /usr/lib64/asterisk/modules/chan_sip.so(+0x9b0c6) [0x7fbd88d3a0c6]
#6: [0x7fbd88cf486c] /usr/lib64/asterisk/modules/chan_sip.so(+0x5586c) [0x7fbd88cf486c]
#7: [0x5c23de] /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x5c23de]
#8: [0x7fbd88d38405] /usr/lib64/asterisk/modules/chan_sip.so(+0x99405) [0x7fbd88d38405]
#9: [0x602d4c] /usr/sbin/asterisk() [0x602d4c]
[2017-10-24 18:09:07] ERROR[3003]: astobj2.c:121 INTERNAL_OBJ: FRACK!, Failed assertion user_data is NULL (0)
Got 15 backtrace records
v12*CLI>
Disconnected from Asterisk server
Asterisk cleanly ending (0).
Executing last minute cleanups

> Serious Network Trouble Errors with TCP Enabled
> -----------------------------------------------
>
>                 Key: ASTERISK-27371
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-27371
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/chan_sip/General
>    Affects Versions: 13.17.2
>         Environment: FreePBX 13.0.192.19 and Asterisk 13.17.2, proxmox 4.4 on Dell R720, local RAID volume. Using TCP and obscure port for SIP. UDP 5060 still open/enabled, but firewalled to only allow Anveo Direct servers.
>            Reporter: Steven Sedory
>            Assignee: Unassigned
>
> Per the environment explained above we are setup. The TCP port we use for our endpoints is 57875. The only other SIP traffic is UDP 5060 to Anveo Direct servers. UDP 10,000-20,000 is allowed from any for RTP. We also set qualify to 25 seconds to help keep NAT holes open. 
> That said, we get lots of errors like below (X.X.X.X has replaced IP's):
> {noformat}
> [2017-10-23 08:13:05] WARNING[10930] chan_sip.c: sip_xmit of 0x7f6058024ba0 (len 670) to X.X.X.X:50664 returned -2: Interrupted system call
> [2017-10-23 08:13:05] ERROR[10930] chan_sip.c: Serious Network Trouble; __sip_xmit returns error for pkt data
> [2017-10-23 05:01:57] WARNING[21567] chan_sip.c: sip_xmit of 0x7f60b0005150 (len 714) to X.X.X.X:50567 returned -2: No such file or directory
> [2017-10-23 05:01:57] ERROR[21567] chan_sip.c: Serious Network Trouble; __sip_xmit returns error for pkt data
> [2017-10-23 08:12:37] WARNING[10930] chan_sip.c: sip_xmit of 0x7f6058023360 (len 670) to X.X.X.X:50664 returned -2: Broken pipe
> [2017-10-23 08:12:37] ERROR[10930] chan_sip.c: Serious Network Trouble; __sip_xmit returns error for pkt data
> {noformat}
> Now, if I have the endpoints switch to UDP 5060, the errors go away. That said, shouldn't we be able to use TCP and almost any port and work just fine?
> We use an obscure port so we can open an obscure port to any, allowing endpoints to be registered from essentially any internet connection with much less security risk. And we use TCP, as it seems to eliminate most NAT traversal issues.

--
This message was sent by Atlassian JIRA
(v6.2#6252)