[asterisk-bugs] [JIRA] (ASTERISK-28430) res_rtp_asterisk.c: FRACK!, Failed assertion errno != EBADF
under (JIRA)
noreply at issues.asterisk.org
Mon May 27 04:43:47 CDT 2019
[ https://issues.asterisk.org/jira/browse/ASTERISK-28430?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
under updated ASTERISK-28430:
-----------------------------
Description:
Asterisk hangs up a call in the middle.
The following message is inside log:
[2019-05-27 11:12:04] ERROR[100170] asterisk-stable-16.2.1/main/tcptls.c: Unable to connect SIP socket to 192.168.0.5:5060: Host is down
[2019-05-27 11:12:04] ERROR[100170] asterisk-stable-16.2.1/channels/chan_sip.c: unable to start TCPTLS client
[2019-05-27 11:12:04] ERROR[102203][C-00000001] asterisk-stable-16.2.1/res/res_rtp_asterisk.c: FRACK!, Failed assertion errno != EBADF (0)
[2019-05-27 11:12:04] ERROR[102203][C-00000001] : Got 25 backtrace records
# 0: 0x735c7a <__ast_assert_failed+0x8a> at /usr/local/sbin/asterisk
# 1: 0x833b20ef9 <__internal_res_rtp_asterisk_self+0x5fe9> at /usr/local/lib/asterisk/res_rtp_asterisk.so
# 2: 0x68f53a <ast_rtp_instance_read+0x5a> at /usr/local/sbin/asterisk
# 3: 0x83253d025 <__internal_chan_sip_self+0xa15c5> at /usr/local/lib/asterisk/chan_sip.so
# 4: 0x832486333 <_init+0xa6a3> at /usr/local/lib/asterisk/chan_sip.so
# 5: 0x5157e1 <__ast_read+0xac1> at /usr/local/sbin/asterisk
# 6: 0x51766b <ast_read_stream+0x1b> at /usr/local/sbin/asterisk
# 7: 0x4aa26a <bridge_handle_trip+0x13a> at /usr/local/sbin/asterisk
# 8: 0x4a8872 <bridge_channel_wait+0x342> at /usr/local/sbin/asterisk
# 9: 0x4a7ec0 <bridge_channel_internal_join+0x630> at /usr/local/sbin/asterisk
#10: 0x4b3e9a <ast_bridge_join+0x3ca> at /usr/local/sbin/asterisk
#11: 0x5af39f <ast_bridge_call_with_flags+0x18f> at /usr/local/sbin/asterisk
#12: 0x5af8c7 <ast_bridge_call+0x27> at /usr/local/sb[2019-05-27 11:12:04] WARNING[102203][C-00000001] asterisk/asterisk-stable-16.2.1/res/res_rtp_asterisk.c: RTP Read error: Bad file descriptor. Hanging up.
I found out that the issue is connected to tcptls.c code.
Asterisk is configured to register at TCP peer.
However the TCP peer is offline.
And there is a bug in Asterisk TCP connection error handling code.
Asterisk closes the socket FD twice!
If this socket FD has been reused by some other Asterisk process, it's closed, just like it happens in above trace, when the socket is reused for RTP.
So, the issue flow is as follows:
1. Thread 1: starts TCP registration process to peer A, creating socket FD 60.
2. Thread 1: there is a TCP connection issue, so Asterisk closes the socket FD 60 : ast_tcptls_client_start() -> close(FD 60).
3. Thread 2: a new SIP call, peer B -> peer C.
The operating system sees that socket FD 60 is currently free, so it re-uses it for RTP socket.
4. Thread 1: ast_tcptls_client_start() -> ao2_ref(tcptls_session, -1) -> session_instance_destructor() -> ast_iostream_close() -> close(FD 60).
So FD 60 is closed again, but FD 60 is now used for RTP of a totally different call!
5. Thread 2: attempts to read from closed RTP socket which leads to assert with errno EBADF.
was:
Asterisk hangs up a call in the middle.
The following message is inside log:
[2019-05-27 11:12:04] ERROR[100170] asterisk-stable-16.2.1/main/tcptls.c: Unable to connect SIP socket to 192.168.0.5:5060: Host is down
[2019-05-27 11:12:04] ERROR[100170] asterisk-stable-16.2.1/channels/chan_sip.c: unable to start TCPTLS client
[2019-05-27 11:12:04] ERROR[102203][C-00000001] asterisk-stable-16.2.1/res/res_rtp_asterisk.c: FRACK!, Failed assertion errno != EBADF (0)
[2019-05-27 11:12:04] ERROR[102203][C-00000001] : Got 25 backtrace records
# 0: 0x735c7a <__ast_assert_failed+0x8a> at /usr/local/sbin/asterisk
# 1: 0x833b20ef9 <__internal_res_rtp_asterisk_self+0x5fe9> at /usr/local/lib/asterisk/res_rtp_asterisk.so
# 2: 0x68f53a <ast_rtp_instance_read+0x5a> at /usr/local/sbin/asterisk
# 3: 0x83253d025 <__internal_chan_sip_self+0xa15c5> at /usr/local/lib/asterisk/chan_sip.so
# 4: 0x832486333 <_init+0xa6a3> at /usr/local/lib/asterisk/chan_sip.so
# 5: 0x5157e1 <__ast_read+0xac1> at /usr/local/sbin/asterisk
# 6: 0x51766b <ast_read_stream+0x1b> at /usr/local/sbin/asterisk
# 7: 0x4aa26a <bridge_handle_trip+0x13a> at /usr/local/sbin/asterisk
# 8: 0x4a8872 <bridge_channel_wait+0x342> at /usr/local/sbin/asterisk
# 9: 0x4a7ec0 <bridge_channel_internal_join+0x630> at /usr/local/sbin/asterisk
#10: 0x4b3e9a <ast_bridge_join+0x3ca> at /usr/local/sbin/asterisk
#11: 0x5af39f <ast_bridge_call_with_flags+0x18f> at /usr/local/sbin/asterisk
#12: 0x5af8c7 <ast_bridge_call+0x27> at /usr/local/sb[2019-05-27 11:12:04] WARNING[102203][C-00000001] asterisk/asterisk-stable-16.2.1/res/res_rtp_asterisk.c: RTP Read error: Bad file descriptor. Hanging up.
I found out that the issue is connected to tcptls.c code.
Asterisk is configured to register at TCP peer.
However the TCP peer is offline.
And there is a bug in Asterisk TCP connection error handling code.
Asterisk closes the socket FD twice!
If this socket FD has been reused by some other Asterisk process, it's closed, just like it happens in above trace, when the socket is reused for RTP.
So, the issue flow is as follows:
1. Thread 1: starts TCP registration process to peer A, creating socket FD 60.
2. Thread 1: there is a TCP connection issue, so Asterisk closes the socket FD 60 : ast_tcptls_client_start() -> close(FD 60).
3. Thread 2: a new SIP call, peer B -> peer C.
The operating system sees that socket FD 60 is currently free, so it re-uses it for RTP socket.
4. Thread 1: ast_tcptls_client_start() -> ao2_ref(tcptls_session, -1) -> session_instance_destructor() -> ast_iostream_close() -> close(FD 60).
So FD 60 is closed again, but FD 60 is now used for RTP of a totally different call!
> res_rtp_asterisk.c: FRACK!, Failed assertion errno != EBADF
> -----------------------------------------------------------
>
> Key: ASTERISK-28430
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-28430
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Core/General
> Affects Versions: 16.2.1
> Environment: FreeBSD-11.2
> Reporter: under
>
> Asterisk hangs up a call in the middle.
> The following message is inside log:
> [2019-05-27 11:12:04] ERROR[100170] asterisk-stable-16.2.1/main/tcptls.c: Unable to connect SIP socket to 192.168.0.5:5060: Host is down
> [2019-05-27 11:12:04] ERROR[100170] asterisk-stable-16.2.1/channels/chan_sip.c: unable to start TCPTLS client
> [2019-05-27 11:12:04] ERROR[102203][C-00000001] asterisk-stable-16.2.1/res/res_rtp_asterisk.c: FRACK!, Failed assertion errno != EBADF (0)
> [2019-05-27 11:12:04] ERROR[102203][C-00000001] : Got 25 backtrace records
> # 0: 0x735c7a <__ast_assert_failed+0x8a> at /usr/local/sbin/asterisk
> # 1: 0x833b20ef9 <__internal_res_rtp_asterisk_self+0x5fe9> at /usr/local/lib/asterisk/res_rtp_asterisk.so
> # 2: 0x68f53a <ast_rtp_instance_read+0x5a> at /usr/local/sbin/asterisk
> # 3: 0x83253d025 <__internal_chan_sip_self+0xa15c5> at /usr/local/lib/asterisk/chan_sip.so
> # 4: 0x832486333 <_init+0xa6a3> at /usr/local/lib/asterisk/chan_sip.so
> # 5: 0x5157e1 <__ast_read+0xac1> at /usr/local/sbin/asterisk
> # 6: 0x51766b <ast_read_stream+0x1b> at /usr/local/sbin/asterisk
> # 7: 0x4aa26a <bridge_handle_trip+0x13a> at /usr/local/sbin/asterisk
> # 8: 0x4a8872 <bridge_channel_wait+0x342> at /usr/local/sbin/asterisk
> # 9: 0x4a7ec0 <bridge_channel_internal_join+0x630> at /usr/local/sbin/asterisk
> #10: 0x4b3e9a <ast_bridge_join+0x3ca> at /usr/local/sbin/asterisk
> #11: 0x5af39f <ast_bridge_call_with_flags+0x18f> at /usr/local/sbin/asterisk
> #12: 0x5af8c7 <ast_bridge_call+0x27> at /usr/local/sb[2019-05-27 11:12:04] WARNING[102203][C-00000001] asterisk/asterisk-stable-16.2.1/res/res_rtp_asterisk.c: RTP Read error: Bad file descriptor. Hanging up.
> I found out that the issue is connected to tcptls.c code.
> Asterisk is configured to register at TCP peer.
> However the TCP peer is offline.
> And there is a bug in Asterisk TCP connection error handling code.
> Asterisk closes the socket FD twice!
> If this socket FD has been reused by some other Asterisk process, it's closed, just like it happens in above trace, when the socket is reused for RTP.
> So, the issue flow is as follows:
> 1. Thread 1: starts TCP registration process to peer A, creating socket FD 60.
> 2. Thread 1: there is a TCP connection issue, so Asterisk closes the socket FD 60 : ast_tcptls_client_start() -> close(FD 60).
> 3. Thread 2: a new SIP call, peer B -> peer C.
> The operating system sees that socket FD 60 is currently free, so it re-uses it for RTP socket.
> 4. Thread 1: ast_tcptls_client_start() -> ao2_ref(tcptls_session, -1) -> session_instance_destructor() -> ast_iostream_close() -> close(FD 60).
> So FD 60 is closed again, but FD 60 is now used for RTP of a totally different call!
> 5. Thread 2: attempts to read from closed RTP socket which leads to assert with errno EBADF.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list